niks3-go-unit-tests
checks.aarch64-darwin.go-unit-tests
· build #461
· raw
1tribuchet: building on mac022Running client tests...3=== RUN TestDoServerRequestAttachesToken4=== PAUSE TestDoServerRequestAttachesToken5=== RUN TestUploadBuildLog_FileBodyReplayedOnRetry6=== PAUSE TestUploadBuildLog_FileBodyReplayedOnRetry7=== RUN TestRegisterUploadedObjectReusesConnections8=== PAUSE TestRegisterUploadedObjectReusesConnections9=== RUN TestRunGarbageCollection_FinishedOnAnotherReplica10=== PAUSE TestRunGarbageCollection_FinishedOnAnotherReplica11=== RUN TestRunGarbageCollection_NotFoundAfterLocalRun12=== PAUSE TestRunGarbageCollection_NotFoundAfterLocalRun13=== RUN TestCaseHackSuffix14=== PAUSE TestCaseHackSuffix15=== RUN TestFilterOversizedClosures16=== PAUSE TestFilterOversizedClosures17=== RUN TestUploadMultipart_PartsInParallel18=== PAUSE TestUploadMultipart_PartsInParallel19=== RUN TestUploadMultipart_ReturnsAfterDroppedBody20=== PAUSE TestUploadMultipart_ReturnsAfterDroppedBody21=== RUN TestPartSizeForNAR22=== PAUSE TestPartSizeForNAR23=== RUN TestUploadMultipart_SupersededByPeer24=== PAUSE TestUploadMultipart_SupersededByPeer25=== RUN TestDumpPathCaseHackMatchesNix26--- PASS: TestDumpPathCaseHackMatchesNix (0.22s)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 TestDoWithRetry_BodyReplayedViaGetBody117=== CONT TestRunGarbageCollection_NotFoundAfterLocalRun118=== CONT TestSupersededNARStillUploadsListing119=== RUN TestSupersededNARStillUploadsListing/small_NAR120=== CONT TestResolveStorePath121=== CONT TestRegisterUploadedObject_BoundedAgainstSilentServer122=== CONT TestRateLimiterFeedback_400DoesNotCountAsSuccess123=== CONT TestRateLimiterFeedback124=== RUN TestRateLimiterFeedback/429_enables_limiter125=== PAUSE TestRateLimiterFeedback/429_enables_limiter126=== RUN TestRateLimiterFeedback/503_enables_limiter127=== PAUSE TestRateLimiterFeedback/503_enables_limiter128=== RUN TestRateLimiterFeedback/200_does_not_enable_limiter129=== PAUSE TestRateLimiterFeedback/200_does_not_enable_limiter130=== RUN TestRateLimiterFeedback/400_does_not_enable_limiter131=== PAUSE TestRateLimiterFeedback/400_does_not_enable_limiter132=== CONT TestScriptTokenBadJSON133=== CONT TestPathInfoCACompatibility134=== RUN TestPathInfoCACompatibility/null_ca_field135=== PAUSE TestPathInfoCACompatibility/null_ca_field136=== CONT TestParsePathInfoJSONMultiplePaths137=== CONT TestParsePathInfoJSON138=== CONT TestPathInfoHashCompatibility139=== CONT TestGetStorePathHash140=== CONT TestConvertHashToNix32141=== CONT TestEncodeNixBase32WithRealHash142--- PASS: TestEncodeNixBase32WithRealHash (0.00s)143=== CONT TestEncodeNixBase32144=== CONT TestDumpPathSingleFile145=== CONT TestDumpPathMatchesNix146=== CONT TestFilterOversizedClosures147=== CONT TestSetClientTLS148=== CONT TestScriptTokenEmptyCommand1492026/11/06 06:52:04 WARN Rate limiter enabled after throttle name=server-test rate=5150=== CONT TestScriptTokenScriptFails1512026/11/06 06:52:04 WARN Rate limiter enabled after throttle name=server-test rate=51522026/11/06 06:52:04 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:52018153=== CONT TestUploadMultipart_PartsInParallel1542026/11/06 06:52:04 INFO Garbage collection started155=== CONT TestDumpPathWriterError1562026/11/06 06:52:04 WARN Rate limiter backed off name=server-test rate=5157=== PAUSE TestSupersededNARStillUploadsListing/small_NAR1582026/11/06 06:52:04 WARN Request returned retryable status, retrying attempt=2 backoff=0s status=503 url=http://127.0.0.1:52018159=== CONT TestScriptTokenEmptyToken160=== RUN TestEncodeNixBase32/test_string_hash161=== RUN TestPathInfoCACompatibility/old_string_format_-_text162=== RUN TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths163=== RUN TestParsePathInfoJSON/Nix_format164=== RUN TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)165=== RUN TestGetStorePathHash/valid_store_path166=== RUN TestConvertHashToNix32/SRI_format_to_Nix32167=== RUN TestFilterOversizedClosures/no_limit_keeps_everything168--- PASS: TestScriptTokenEmptyCommand (0.00s)169=== CONT TestScriptTokenCachesUntilRefresh170=== RUN TestSupersededNARStillUploadsListing/dump_cut_short171=== PAUSE TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths172=== PAUSE TestEncodeNixBase32/test_string_hash173=== PAUSE TestPathInfoCACompatibility/old_string_format_-_text174=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)175=== PAUSE TestParsePathInfoJSON/Nix_format176=== CONT TestScriptTokenNoExpiryRerunsEveryCall177=== PAUSE TestGetStorePathHash/valid_store_path178=== PAUSE TestConvertHashToNix32/SRI_format_to_Nix32179=== CONT TestFileTokenEmpty180=== CONT TestFileTokenMissing181=== RUN TestSetClientTLS/rejects_connection_without_client_cert182=== RUN TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths183=== PAUSE TestFilterOversizedClosures/no_limit_keeps_everything184--- PASS: TestDoWithRetry_BodyReplayedViaGetBody (0.02s)185=== RUN TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped186=== RUN TestPathInfoHashCompatibility/old_string_format_with_colon187--- PASS: TestRunGarbageCollection_NotFoundAfterLocalRun (0.02s)188--- PASS: TestDoServerRequestAttachesToken (0.02s)189--- PASS: TestResolveStorePath (0.02s)190=== CONT TestFileTokenReadsAndCaches191=== RUN TestConvertHashToNix32/already_Nix32_format192--- PASS: TestScriptTokenScriptFails (0.02s)193=== CONT TestStaticToken194--- PASS: TestFileTokenReadsAndCaches (0.00s)195--- PASS: TestStaticToken (0.00s)196=== CONT TestSetClientTLSDoesNotMutateDefaultTransport197=== CONT TestSetClientTLSErrors198=== PAUSE TestSupersededNARStillUploadsListing/dump_cut_short199=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_colon200=== PAUSE TestConvertHashToNix32/already_Nix32_format201=== PAUSE TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped202=== PAUSE TestSetClientTLS/rejects_connection_without_client_cert203=== PAUSE TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths204=== CONT TestCaseHackSuffix205=== RUN TestEncodeNixBase32/empty_input206=== PAUSE TestEncodeNixBase32/empty_input207=== RUN TestPathInfoCACompatibility/old_string_format_-_fixed_recursive208=== PAUSE TestPathInfoCACompatibility/old_string_format_-_fixed_recursive209=== RUN TestPathInfoCACompatibility/new_structured_format_-_text210=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_text211=== RUN TestPathInfoCACompatibility/new_structured_format_-_nar_method212=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_nar_method213=== CONT TestClientSignaturesByStorePath214=== CONT TestStreamPushReportsSignatures215=== RUN TestParsePathInfoJSON/Lix_format216=== PAUSE TestParsePathInfoJSON/Lix_format217=== RUN TestParsePathInfoJSON/empty_input218=== PAUSE TestParsePathInfoJSON/empty_input219=== RUN TestParsePathInfoJSON/whitespace_only220=== PAUSE TestParsePathInfoJSON/whitespace_only221=== RUN TestParsePathInfoJSON/invalid_JSON222=== PAUSE TestParsePathInfoJSON/invalid_JSON223=== CONT TestStreamPushReportsSkippedPaths224=== CONT TestStreamPushGivesUpOnDeadServer225=== RUN TestSetClientTLSErrors/missing_cert_file226=== PAUSE TestSetClientTLSErrors/missing_cert_file227=== RUN TestGetStorePathHash/basename_without_hyphen_should_error228=== RUN TestSupersededNARStillUploadsListing/listing_upload_fails229=== RUN TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI230=== RUN TestConvertHashToNix32/invalid_format231=== RUN TestFilterOversizedClosures/all_closures_skipped232=== RUN TestSetClientTLS/succeeds_with_client_cert_and_CA233--- PASS: TestScriptTokenBadJSON (0.04s)234=== CONT TestStreamPushIsolatesFailures235=== CONT TestStreamPushStopsWhenCanceled2362026/11/06 06:52:04 ERROR Upload failed error="connection refused" count=202372026/11/06 06:52:04 ERROR Server seems unavailable, giving up on batch untried=17238=== CONT TestShellSplitErrors239=== CONT TestStreamPushBatchesUnderLoad240=== RUN TestStreamPushBatchesUnderLoad/oneAtATime=false241=== PAUSE TestStreamPushBatchesUnderLoad/oneAtATime=false242=== RUN TestStreamPushBatchesUnderLoad/oneAtATime=true243=== PAUSE TestStreamPushBatchesUnderLoad/oneAtATime=true244=== CONT TestDoWithRetry_FinalResponseBodyReadable245=== PAUSE TestSupersededNARStillUploadsListing/listing_upload_fails246=== PAUSE TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI247=== RUN TestPathInfoHashCompatibility/new_structured_format_with_sha512248=== PAUSE TestPathInfoHashCompatibility/new_structured_format_with_sha512249=== PAUSE TestConvertHashToNix32/invalid_format250=== PAUSE TestFilterOversizedClosures/all_closures_skipped251=== PAUSE TestSetClientTLS/succeeds_with_client_cert_and_CA252=== RUN TestSetClientTLS/preserves_debug_logging_transport2532026/11/06 06:52:04 ERROR Upload failed error=boom count=1254=== PAUSE TestSetClientTLS/preserves_debug_logging_transport255=== CONT TestUploadMultipart_ReturnsAfterDroppedBody2562026/11/06 06:52:04 ERROR Upload failed error="bad path" count=3257=== CONT TestRegisterUploadedObjectReusesConnections258=== CONT TestUploadBuildLog_FileBodyReplayedOnRetry259=== CONT TestPartSizeForNAR260=== RUN TestPartSizeForNAR/zero_stays_at_minimum261=== PAUSE TestPartSizeForNAR/zero_stays_at_minimum262=== RUN TestPartSizeForNAR/small_stays_at_minimum263=== PAUSE TestPartSizeForNAR/small_stays_at_minimum264=== RUN TestPartSizeForNAR/80_GiB_fits_at_minimum265=== PAUSE TestPartSizeForNAR/80_GiB_fits_at_minimum266=== RUN TestPartSizeForNAR/115_GiB_needs_larger_parts267=== PAUSE TestPartSizeForNAR/115_GiB_needs_larger_parts268=== RUN TestPartSizeForNAR/1_TiB269=== PAUSE TestPartSizeForNAR/1_TiB270=== RUN TestPartSizeForNAR/5_TiB_S3_max_object271=== PAUSE TestPartSizeForNAR/5_TiB_S3_max_object272=== RUN TestPartSizeForNAR/capped_at_5_GiB273=== PAUSE TestPartSizeForNAR/capped_at_5_GiB274=== RUN TestSetClientTLSErrors/missing_key_file275=== PAUSE TestSetClientTLSErrors/missing_key_file276=== RUN TestSetClientTLSErrors/missing_ca_file277=== PAUSE TestSetClientTLSErrors/missing_ca_file278=== RUN TestSetClientTLSErrors/invalid_ca_file279=== PAUSE TestSetClientTLSErrors/invalid_ca_file280=== CONT TestRetryTimeoutOutlastsMaxRetries281=== CONT TestRunGarbageCollection_FinishedOnAnotherReplica282=== CONT TestRateLimiterFeedback/429_enables_limiter283=== PAUSE TestGetStorePathHash/basename_without_hyphen_should_error284=== RUN TestGetStorePathHash/hash_with_invalid_characters_should_error285=== PAUSE TestGetStorePathHash/hash_with_invalid_characters_should_error286=== RUN TestGetStorePathHash/hash_with_wrong_length_should_error287=== PAUSE TestGetStorePathHash/hash_with_wrong_length_should_error288=== CONT TestRateLimiterFeedback/200_does_not_enable_limiter289=== CONT TestRateLimiterFeedback/503_enables_limiter290--- PASS: TestFileTokenEmpty (0.01s)291--- PASS: TestClientSignaturesByStorePath (0.00s)292--- PASS: TestStreamPushReportsSkippedPaths (0.00s)293--- PASS: TestStreamPushStopsWhenCanceled (0.00s)294--- PASS: TestShellSplitErrors (0.00s)295--- PASS: TestStreamPushGivesUpOnDeadServer (0.00s)296--- PASS: TestStreamPushReportsSignatures (0.00s)297--- PASS: TestStreamPushIsolatesFailures (0.00s)298=== CONT TestUploadMultipart_SupersededByPeer299=== CONT TestStreamPushReportsEveryPath300=== CONT TestShellSplit301=== CONT TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths302=== CONT TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths303=== CONT TestEncodeNixBase32/test_string_hash304=== CONT TestPathInfoCACompatibility/null_ca_field305=== CONT TestEncodeNixBase32/empty_input306=== CONT TestParsePathInfoJSON/Nix_format307=== CONT TestPathInfoCACompatibility/new_structured_format_-_nar_method308=== CONT TestPathInfoCACompatibility/new_structured_format_-_text309=== CONT TestPathInfoCACompatibility/old_string_format_-_fixed_recursive310=== CONT TestPathInfoCACompatibility/old_string_format_-_text311=== CONT TestParsePathInfoJSON/invalid_JSON312=== CONT TestParsePathInfoJSON/whitespace_only313=== CONT TestParsePathInfoJSON/empty_input314=== CONT TestParsePathInfoJSON/Lix_format315=== CONT TestStreamPushBatchesUnderLoad/oneAtATime=false316=== CONT TestStreamPushRequestLine317--- PASS: TestSetClientTLSDoesNotMutateDefaultTransport (0.01s)318--- PASS: TestFileTokenMissing (0.01s)319--- PASS: TestShellSplit (0.00s)320=== RUN TestUploadMultipart_SupersededByPeer/exists321=== PAUSE TestUploadMultipart_SupersededByPeer/exists322=== CONT TestRateLimiterFeedback/400_does_not_enable_limiter3232026/11/06 06:52:04 ERROR Upload failed error=boom count=13242026/11/06 06:52:04 WARN Rate limiter enabled after throttle name=s3-test rate=53252026/11/06 06:52:04 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:520793262026/11/06 06:52:04 WARN Rate limiter enabled after throttle name=server-test rate=53272026/11/06 06:52:04 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:520593282026/11/06 06:52:04 WARN Rate limiter enabled after throttle name=server-test rate=53292026/11/06 06:52:04 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=429 url=http://127.0.0.1:520503302026/11/06 06:52:04 WARN Rate limiter enabled after throttle name=server-test rate=53312026/11/06 06:52:04 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:520323322026/11/06 06:52:04 WARN Request returned retryable status, retrying attempt=1 backoff=1ms status=502 url=http://127.0.0.1:520423332026/11/06 06:52:04 INFO Garbage collection started3342026/11/06 06:52:04 WARN Rate limiter backed off name=server-test rate=53352026/11/06 06:52:04 WARN Rate limiter backed off name=server-test rate=5336=== CONT TestSupersededNARStillUploadsListing/small_NAR337=== RUN TestUploadMultipart_SupersededByPeer/missing338=== PAUSE TestUploadMultipart_SupersededByPeer/missing339=== CONT TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)340=== CONT TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI341=== CONT TestPathInfoHashCompatibility/old_string_format_with_colon342=== CONT TestConvertHashToNix32/invalid_format343=== CONT TestConvertHashToNix32/already_Nix32_format344=== CONT TestPartSizeForNAR/zero_stays_at_minimum345=== CONT TestFilterOversizedClosures/all_closures_skipped3462026/11/06 06:52:04 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=50347=== CONT TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped3482026/11/06 06:52:04 WARN Rate limiter backed off name=server-test rate=53492026/11/06 06:52:04 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=20003502026/11/06 06:52:04 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=03512026/11/06 06:52:04 WARN Request returned retryable status, retrying attempt=2 backoff=1ms status=502 url=http://127.0.0.1:52042352=== CONT TestPathInfoHashCompatibility/new_structured_format_with_sha512353=== CONT TestSetClientTLSErrors/missing_cert_file354=== CONT TestPartSizeForNAR/5_TiB_S3_max_object355=== CONT TestPartSizeForNAR/1_TiB356=== CONT TestPartSizeForNAR/115_GiB_needs_larger_parts357=== CONT TestPartSizeForNAR/80_GiB_fits_at_minimum358=== CONT TestPartSizeForNAR/small_stays_at_minimum359=== CONT TestGetStorePathHash/valid_store_path360=== CONT TestSetClientTLSErrors/invalid_ca_file361=== CONT TestSetClientTLS/preserves_debug_logging_transport362=== CONT TestConvertHashToNix32/SRI_format_to_Nix32363=== CONT TestSetClientTLSErrors/missing_ca_file364=== CONT TestFilterOversizedClosures/no_limit_keeps_everything365=== CONT TestSetClientTLSErrors/missing_key_file366=== CONT TestStreamPushBatchesUnderLoad/oneAtATime=true367=== CONT TestSupersededNARStillUploadsListing/listing_upload_fails368=== CONT TestSupersededNARStillUploadsListing/dump_cut_short369=== CONT TestGetStorePathHash/hash_with_wrong_length_should_error370=== CONT TestGetStorePathHash/hash_with_invalid_characters_should_error371=== CONT TestGetStorePathHash/basename_without_hyphen_should_error372=== CONT TestUploadMultipart_SupersededByPeer/exists373=== CONT TestSetClientTLS/rejects_connection_without_client_cert374--- PASS: TestEncodeNixBase32 (0.04s)375 --- PASS: TestEncodeNixBase32/test_string_hash (0.00s)376 --- PASS: TestEncodeNixBase32/empty_input (0.00s)377--- PASS: TestStreamPushReportsEveryPath (0.01s)378--- PASS: TestParsePathInfoJSONMultiplePaths (0.04s)379 --- PASS: TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths (0.00s)380 --- PASS: TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths (0.00s)381--- PASS: TestUploadMultipart_ReturnsAfterDroppedBody (0.02s)382--- PASS: TestScriptTokenEmptyToken (0.04s)383--- PASS: TestUploadBuildLog_FileBodyReplayedOnRetry (0.02s)384--- PASS: TestDoWithRetry_FinalResponseBodyReadable (0.02s)385=== CONT TestSetClientTLS/succeeds_with_client_cert_and_CA386--- PASS: TestPathInfoCACompatibility (0.04s)387 --- PASS: TestPathInfoCACompatibility/null_ca_field (0.00s)388 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_nar_method (0.00s)389 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_text (0.00s)390 --- PASS: TestPathInfoCACompatibility/old_string_format_-_fixed_recursive (0.00s)391 --- PASS: TestPathInfoCACompatibility/old_string_format_-_text (0.00s)392--- PASS: TestParsePathInfoJSON (0.04s)393 --- PASS: TestParsePathInfoJSON/Nix_format (0.00s)394 --- PASS: TestParsePathInfoJSON/invalid_JSON (0.00s)395 --- PASS: TestParsePathInfoJSON/whitespace_only (0.00s)396 --- PASS: TestParsePathInfoJSON/empty_input (0.00s)397 --- PASS: TestParsePathInfoJSON/Lix_format (0.00s)398--- PASS: TestRateLimiterFeedback (0.00s)399 --- PASS: TestRateLimiterFeedback/200_does_not_enable_limiter (0.01s)400 --- PASS: TestRateLimiterFeedback/503_enables_limiter (0.02s)401 --- PASS: TestRateLimiterFeedback/429_enables_limiter (0.02s)402 --- PASS: TestRateLimiterFeedback/400_does_not_enable_limiter (0.00s)403--- PASS: TestPathInfoHashCompatibility (0.04s)404 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) (0.00s)405 --- PASS: TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI (0.00s)406 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_colon (0.00s)407 --- PASS: TestPathInfoHashCompatibility/new_structured_format_with_sha512 (0.00s)408=== CONT TestPartSizeForNAR/capped_at_5_GiB409--- PASS: TestPartSizeForNAR (0.00s)410 --- PASS: TestPartSizeForNAR/zero_stays_at_minimum (0.00s)411 --- PASS: TestPartSizeForNAR/5_TiB_S3_max_object (0.00s)412 --- PASS: TestPartSizeForNAR/1_TiB (0.00s)413 --- PASS: TestPartSizeForNAR/115_GiB_needs_larger_parts (0.00s)414 --- PASS: TestPartSizeForNAR/80_GiB_fits_at_minimum (0.00s)415 --- PASS: TestPartSizeForNAR/small_stays_at_minimum (0.00s)416 --- PASS: TestPartSizeForNAR/capped_at_5_GiB (0.00s)417=== CONT TestUploadMultipart_SupersededByPeer/missing4182026/11/06 06:52:04 INFO Uploading abc-hello (1.0GB)419--- PASS: TestStreamPushBatchesUnderLoad (0.00s)420 --- PASS: TestStreamPushBatchesUnderLoad/oneAtATime=false (0.01s)421 --- PASS: TestStreamPushBatchesUnderLoad/oneAtATime=true (0.00s)422--- PASS: TestGetStorePathHash (0.04s)423 --- PASS: TestGetStorePathHash/valid_store_path (0.00s)424 --- PASS: TestGetStorePathHash/hash_with_wrong_length_should_error (0.00s)425 --- PASS: TestGetStorePathHash/hash_with_invalid_characters_should_error (0.00s)426 --- PASS: TestGetStorePathHash/basename_without_hyphen_should_error (0.00s)427--- PASS: TestConvertHashToNix32 (0.04s)428 --- PASS: TestConvertHashToNix32/invalid_format (0.00s)429 --- PASS: TestConvertHashToNix32/already_Nix32_format (0.00s)430 --- PASS: TestConvertHashToNix32/SRI_format_to_Nix32 (0.00s)431--- PASS: TestSetClientTLSErrors (0.01s)432 --- PASS: TestSetClientTLSErrors/missing_cert_file (0.00s)433 --- PASS: TestSetClientTLSErrors/missing_key_file (0.00s)434 --- PASS: TestSetClientTLSErrors/invalid_ca_file (0.00s)435 --- PASS: TestSetClientTLSErrors/missing_ca_file (0.00s)436--- PASS: TestFilterOversizedClosures (0.04s)437 --- PASS: TestFilterOversizedClosures/all_closures_skipped (0.00s)438 --- PASS: TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped (0.00s)439 --- PASS: TestFilterOversizedClosures/no_limit_keeps_everything (0.00s)4402026/11/06 06:52:04 INFO Uploading abc-hello (1.0GB)4412026/11/06 06:52:04 WARN Request returned retryable status, retrying attempt=1 backoff=1ms status=502 url=http://127.0.0.1:520424422026/11/06 06:52:04 WARN Garbage collection finished on another replica. Its statistics are not available here443--- PASS: TestRunGarbageCollection_FinishedOnAnotherReplica (0.02s)4442026/11/06 06:52:04 WARN Request returned retryable status, retrying attempt=2 backoff=1ms status=502 url=http://127.0.0.1:52042445--- PASS: TestUploadMultipart_SupersededByPeer (0.01s)446 --- PASS: TestUploadMultipart_SupersededByPeer/exists (0.01s)447 --- PASS: TestUploadMultipart_SupersededByPeer/missing (0.01s)4482026/11/06 06:52:04 WARN Request returned retryable status, retrying attempt=3 backoff=1ms status=502 url=http://127.0.0.1:520424492026/11/06 06:52:04 WARN Request returned retryable status, retrying attempt=4 backoff=1ms status=502 url=http://127.0.0.1:520424502026/11/06 06:52:04 WARN Request returned retryable status, retrying attempt=5 backoff=1ms status=502 url=http://127.0.0.1:52042451--- PASS: TestStreamPushRequestLine (0.03s)4522026/11/06 06:52:04 WARN Request returned retryable status, retrying attempt=6 backoff=1ms status=502 url=http://127.0.0.1:520424532026/11/06 06:52:04 WARN Request returned retryable status, retrying attempt=7 backoff=1ms status=502 url=http://127.0.0.1:520424542026/11/06 06:52:04 WARN Request returned retryable status, retrying attempt=8 backoff=1ms status=502 url=http://127.0.0.1:520424552026/11/06 06:52:04 WARN Request returned retryable status, retrying attempt=9 backoff=1ms status=502 url=http://127.0.0.1:520424562026/11/06 06:52:04 WARN Request returned retryable status, retrying attempt=10 backoff=1ms status=502 url=http://127.0.0.1:520424572026/11/06 06:52:04 WARN Request returned retryable status, retrying attempt=11 backoff=1ms status=502 url=http://127.0.0.1:520424582026/11/06 06:52:04 WARN Request returned retryable status, retrying attempt=12 backoff=1ms status=502 url=http://127.0.0.1:520424592026/11/06 06:52:04 WARN Request returned retryable status, retrying attempt=13 backoff=1ms status=502 url=http://127.0.0.1:520424602026/11/06 06:52:04 WARN Request returned retryable status, retrying attempt=14 backoff=1ms status=502 url=http://127.0.0.1:52042461--- PASS: TestRegisterUploadedObjectReusesConnections (0.05s)4622026/11/06 06:52:04 WARN Request returned retryable status, retrying attempt=15 backoff=1ms status=502 url=http://127.0.0.1:52042463--- PASS: TestScriptTokenCachesUntilRefresh (0.08s)4642026/11/06 06:52:04 WARN Request returned retryable status, retrying attempt=16 backoff=1ms status=502 url=http://127.0.0.1:520424652026/11/06 06:52:04 WARN Request returned retryable status, retrying attempt=17 backoff=1ms status=502 url=http://127.0.0.1:52042466--- PASS: TestDumpPathSingleFile (0.10s)467--- PASS: TestRetryTimeoutOutlastsMaxRetries (0.06s)4682026/11/06 06:52:04 http: TLS handshake error from 127.0.0.1:52121: read tcp 127.0.0.1:52031->127.0.0.1:52121: use of closed network connection469--- PASS: TestSetClientTLS (0.04s)470 --- PASS: TestSetClientTLS/preserves_debug_logging_transport (0.01s)471 --- PASS: TestSetClientTLS/succeeds_with_client_cert_and_CA (0.02s)472 --- PASS: TestSetClientTLS/rejects_connection_without_client_cert (0.05s)473--- PASS: TestScriptTokenNoExpiryRerunsEveryCall (0.08s)474--- PASS: TestCaseHackSuffix (0.09s)475--- PASS: TestDumpPathWriterError (0.12s)4762026/11/06 06:52:04 INFO Uploading abc-hello (1.0GB)4772026/11/06 06:52:04 WARN Request failed, retrying attempt=1 backoff=100ms error="Put \"http://127.0.0.1:52120/part/2\": uploading part 1: server returned 404: no such upload\n" url=http://127.0.0.1:52120/part/24782026/11/06 06:52:04 WARN Request failed, retrying attempt=1 backoff=100ms error="Put \"http://127.0.0.1:52120/part/3\": uploading part 1: server returned 404: no such upload\n" url=http://127.0.0.1:52120/part/3479--- PASS: TestDumpPathMatchesNix (0.16s)4802026/11/06 06:52:04 WARN Request failed, retrying attempt=1 backoff=100ms error="Put \"http://127.0.0.1:52120/part/4\": uploading part 1: server returned 404: no such upload\n" url=http://127.0.0.1:52120/part/44812026/11/06 06:52:04 WARN Request failed, retrying attempt=1 backoff=100ms error="Put \"http://127.0.0.1:52120/part/5\": uploading part 1: server returned 404: no such upload\n" url=http://127.0.0.1:52120/part/54822026/11/06 06:52:04 WARN Request failed, retrying attempt=1 backoff=100ms error="Put \"http://127.0.0.1:52120/part/6\": uploading part 1: server returned 404: no such upload\n" url=http://127.0.0.1:52120/part/64832026/11/06 06:52:04 WARN Request failed, retrying attempt=1 backoff=100ms error="Put \"http://127.0.0.1:52120/part/7\": uploading part 1: server returned 404: no such upload\n" url=http://127.0.0.1:52120/part/7484--- PASS: TestSupersededNARStillUploadsListing (0.04s)485 --- PASS: TestSupersededNARStillUploadsListing/listing_upload_fails (0.03s)486 --- PASS: TestSupersededNARStillUploadsListing/small_NAR (0.03s)487 --- PASS: TestSupersededNARStillUploadsListing/dump_cut_short (0.59s)488--- PASS: TestUploadMultipart_PartsInParallel (0.65s)4892026/11/06 06:52:05 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:52020/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:52020/api/uploads/complete4902026/11/06 06:52:05 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"4912026/11/06 06:52:05 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:52020/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:52020/api/uploads/complete4922026/11/06 06:52:05 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"4932026/11/06 06:52:05 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:52020/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:52020/api/uploads/complete4942026/11/06 06:52:05 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"495--- PASS: TestRegisterUploadedObject_BoundedAgainstSilentServer (1.00s)496--- PASS: TestRateLimiterFeedback_400DoesNotCountAsSuccess (1.01s)497PASS498Running server tests...499The files belonging to this database system will be owned by user "_tribuchetbld5".500This user must also own the server process.501502The database cluster will be initialized with locale "C".503The default database encoding has accordingly been set to "SQL_ASCII".504The default text search configuration will be set to "english".505506Data page checksums are enabled.507508creating directory /private/var/tb/5/scratch/87d7ae187515016b/build/postgres985148996/data ... ok509creating subdirectories ... ok510selecting dynamic shared memory implementation ... posix511selecting default "max_connections" ... 100512selecting default "shared_buffers" ... 128MB513selecting default time zone ... UTC514creating configuration files ... ok515running bootstrap script ... ok516performing post-bootstrap initialization ... ok517syncing data to disk ... ok518519initdb: warning: enabling "trust" authentication for local connections520initdb: 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.521522Success. You can now start the database server using:523524 pg_ctl -D /private/var/tb/5/scratch/87d7ae187515016b/build/postgres985148996/data -l logfile start5255262026-11-06 06:52:07.215 UTC [72589] LOG: starting PostgreSQL 18.6 on aarch64-apple-darwin25.6.0, compiled by clang version 21.1.8, 64-bit5272026-11-06 06:52:07.215 UTC [72589] LOG: listening on Unix socket "/private/var/tb/5/scratch/87d7ae187515016b/build/postgres985148996/.s.PGSQL.5432"5282026-11-06 06:52:07.217 UTC [72596] LOG: database system was shut down at 2026-11-06 06:52:07 UTC5292026-11-06 06:52:07.218 UTC [72589] LOG: database system is ready to accept connections530/private/var/tb/5/scratch/87d7ae187515016b/build/postgres985148996:5432 - accepting connections531{"timestamp":"2026-11-06T06:52:09.87463Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"334e3d1c-823e-480b-abae-47a82f1d64be","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(5)"}532=== RUN TestService_AuthMiddleware533=== PAUSE TestService_AuthMiddleware534=== RUN TestService_AuthMiddleware_MTLSProxyHeader535=== PAUSE TestService_AuthMiddleware_MTLSProxyHeader536=== RUN TestService_AuthMiddleware_MTLSBoundSubjects537=== PAUSE TestService_AuthMiddleware_MTLSBoundSubjects538=== RUN TestService_ReadAuthMiddleware539=== PAUSE TestService_ReadAuthMiddleware540=== RUN TestService_AuthMiddleware_OIDC541=== PAUSE TestService_AuthMiddleware_OIDC542=== RUN TestService_RequireScope_OIDC543=== PAUSE TestService_RequireScope_OIDC544=== RUN TestService_ReadScope_PublicByDefault545=== PAUSE TestService_ReadScope_PublicByDefault546=== RUN TestCacheConfigHandler547=== PAUSE TestCacheConfigHandler548=== RUN TestCacheStatsHandler549=== PAUSE TestCacheStatsHandler550=== RUN TestClientCADerivations551=== PAUSE TestClientCADerivations552=== RUN TestClientErrorHandling553=== PAUSE TestClientErrorHandling554=== RUN TestClientIntegration555=== PAUSE TestClientIntegration556=== RUN TestClientMultipleUploads557=== PAUSE TestClientMultipleUploads558=== RUN TestClientWithDependencies559=== PAUSE TestClientWithDependencies560=== RUN TestClientSharedPathCommittedMidPush561=== PAUSE TestClientSharedPathCommittedMidPush562=== RUN TestPinProtectsFromGC563=== PAUSE TestPinProtectsFromGC564=== RUN TestClientPushesUseOnePush565=== PAUSE TestClientPushesUseOnePush566=== RUN TestClientFallsBackToClosures567=== PAUSE TestClientFallsBackToClosures568=== RUN TestDeleteClosuresRacingPins569=== PAUSE TestDeleteClosuresRacingPins570=== RUN TestConcurrentCommitsSharingObjectsDoNotDeadlock571=== PAUSE TestConcurrentCommitsSharingObjectsDoNotDeadlock572=== RUN TestResolveDBConnectionString573=== PAUSE TestResolveDBConnectionString574=== RUN TestConnectWaitsForAPeerMigration575=== PAUSE TestConnectWaitsForAPeerMigration576=== RUN TestLeadElectsOneAndHandsOver577=== PAUSE TestLeadElectsOneAndHandsOver578=== RUN TestLeadIncumbentWinsAfterRestart5792026/11/06 06:52:10 INFO lead: acquired remote=192.0.2.1:12345802026/11/06 06:52:10 INFO lead: released remote=192.0.2.1:12345812026/11/06 06:52:11 INFO lead: acquired remote=192.0.2.1:12345822026/11/06 06:52:12 INFO lead: released remote=192.0.2.1:1234583--- PASS: TestLeadIncumbentWinsAfterRestart (2.15s)584=== RUN TestLeadIncumbentAnnouncesAtOnce585=== PAUSE TestLeadIncumbentAnnouncesAtOnce586=== RUN TestLeadEndsOnShutdown587=== PAUSE TestLeadEndsOnShutdown588=== RUN TestLeadEndsWhenItsConnectionHangs5892026/11/06 06:52:12 INFO lead: acquired remote=192.0.2.1:12345902026-11-06 06:52:13.712 UTC [72637] FATAL: terminating connection due to administrator command5912026/11/06 06:52:13 INFO lead: acquired remote=192.0.2.1:12345922026/11/06 06:52:14 WARN lead: lock connection lost error="timeout: context deadline exceeded"5932026/11/06 06:52:14 INFO lead: released remote=192.0.2.1:12345942026/11/06 06:52:15 INFO lead: released remote=192.0.2.1:1234595--- PASS: TestLeadEndsWhenItsConnectionHangs (2.98s)596=== RUN TestGCAdvisoryLockBlocksConcurrentRun597=== PAUSE TestGCAdvisoryLockBlocksConcurrentRun598=== RUN TestGCBugBareHashReferences599=== PAUSE TestGCBugBareHashReferences600=== RUN TestGCMetrics601=== PAUSE TestGCMetrics602=== RUN TestPushDedupSurvivesConcurrentGC603=== PAUSE TestPushDedupSurvivesConcurrentGC604=== RUN TestDeduplicatedObjectsRecordedAsPending605=== PAUSE TestDeduplicatedObjectsRecordedAsPending606=== RUN TestGCSweepSkipsPendingObjects607=== PAUSE TestGCSweepSkipsPendingObjects608=== RUN TestTombstonedObjectOfferedWithoutWaiting609=== PAUSE TestTombstonedObjectOfferedWithoutWaiting610=== RUN TestGCSweepDeliversEachKeyOnce611=== PAUSE TestGCSweepDeliversEachKeyOnce612=== RUN TestCreatePendingClosureVerifyS3FailureReleasesConnection613=== PAUSE TestCreatePendingClosureVerifyS3FailureReleasesConnection614=== RUN TestForceGCDuringPushOffersSweptObject615=== PAUSE TestForceGCDuringPushOffersSweptObject616=== RUN TestFailedS3DeleteKeepsTombstone617=== PAUSE TestFailedS3DeleteKeepsTombstone618=== RUN TestSweepSkipsRowsLockedByPush619=== PAUSE TestSweepSkipsRowsLockedByPush620=== RUN TestRegisterCompletedObjectNeedsPendingRow621=== PAUSE TestRegisterCompletedObjectNeedsPendingRow622=== RUN TestGetExistingObjectsLocksRows623=== PAUSE TestGetExistingObjectsLocksRows624=== RUN TestSweepRechecksPendingAfterLocking625=== PAUSE TestSweepRechecksPendingAfterLocking626=== RUN TestPushWaitsForSweepHoldingRow627=== PAUSE TestPushWaitsForSweepHoldingRow628=== RUN TestCommitRacingPendingCleanupKeepsObjects629=== PAUSE TestCommitRacingPendingCleanupKeepsObjects630=== RUN TestGCEndsOnShutdown631=== PAUSE TestGCEndsOnShutdown632=== RUN TestGCTaskStore_StartNew633=== PAUSE TestGCTaskStore_StartNew634=== RUN TestGCTaskStore_DeduplicateSameParams635=== PAUSE TestGCTaskStore_DeduplicateSameParams636=== RUN TestGCTaskStore_ConflictDifferentParams637=== PAUSE TestGCTaskStore_ConflictDifferentParams638=== RUN TestGCTaskStore_GetEmpty639=== PAUSE TestGCTaskStore_GetEmpty640=== RUN TestGCTaskStore_GetReturnsLatest641=== PAUSE TestGCTaskStore_GetReturnsLatest642=== RUN TestGCTaskStore_CompletedAllowsNewTask643=== PAUSE TestGCTaskStore_CompletedAllowsNewTask644=== RUN TestGCTaskStore_PhaseUpdates645=== PAUSE TestGCTaskStore_PhaseUpdates646=== RUN TestGCTaskStore_Fail647=== PAUSE TestGCTaskStore_Fail648=== RUN TestGracefulShutdownDrainsInflight649=== PAUSE TestGracefulShutdownDrainsInflight650=== RUN TestService_healthCheckHandler651=== PAUSE TestService_healthCheckHandler652=== RUN TestService_readinessHandler653=== PAUSE TestService_readinessHandler654=== RUN TestGenerateLandingPage655=== PAUSE TestGenerateLandingPage656=== RUN TestCacheConfigHandlerMaxNarSize657=== PAUSE TestCacheConfigHandlerMaxNarSize658=== RUN TestCreatePendingClosureRejectsOversizedNAR659=== PAUSE TestCreatePendingClosureRejectsOversizedNAR660=== RUN TestNARDeduplicationMetadataUploadBug661=== PAUSE TestNARDeduplicationMetadataUploadBug662=== RUN TestMetricsInventory663=== PAUSE TestMetricsInventory664=== RUN TestMetricsCommit665=== PAUSE TestMetricsCommit666=== RUN TestService_NativeMTLS667=== PAUSE TestService_NativeMTLS668=== RUN TestServerTLSConfig669=== PAUSE TestServerTLSConfig670=== RUN TestMultipartCleanup671=== PAUSE TestMultipartCleanup672=== RUN TestMultipartUploadAbortedWhenCancelledBeforeRecorded673=== PAUSE TestMultipartUploadAbortedWhenCancelledBeforeRecorded674=== RUN TestPendingCleanupUsesOneCutoff675=== PAUSE TestPendingCleanupUsesOneCutoff676=== RUN TestObjectStatsTrigger677=== PAUSE TestObjectStatsTrigger678=== RUN TestObjectStatsUpdatedOncePerCommit679=== PAUSE TestObjectStatsUpdatedOncePerCommit680=== RUN TestOrphanedObjectsGC681=== PAUSE TestOrphanedObjectsGC682=== RUN TestOrphanedObjectsGCStressTest683=== PAUSE TestOrphanedObjectsGCStressTest684=== RUN TestCreatePin_ReservedPins685=== PAUSE TestCreatePin_ReservedPins686=== RUN TestPresentReportsOnlyClosureRoots687=== PAUSE TestPresentReportsOnlyClosureRoots688=== RUN TestPresentRefreshesOnlyStaleClosures689=== PAUSE TestPresentRefreshesOnlyStaleClosures690=== RUN TestPresentNotReportedWhileGCDeletesClosure691=== PAUSE TestPresentNotReportedWhileGCDeletesClosure692=== RUN TestParseSingleRange693=== PAUSE TestParseSingleRange694=== RUN TestProxyHeadersOnlyTrustedOnSocket6952026/11/06 06:52:15 INFO Starting HTTP server address=127.0.0.1:522046962026/11/06 06:52:15 INFO Starting HTTP server address=proxy.sock6972026/11/06 06:52:15 WARN mTLS auth: subject not in bound subjects subject="CN=someone"6982026/11/06 06:52:15 INFO Shutdown signal received, draining in-flight requests timeout=10s699--- PASS: TestProxyHeadersOnlyTrustedOnSocket (0.17s)700=== RUN TestIsValidCachePath701=== PAUSE TestIsValidCachePath702=== RUN TestReadProxyNarinfo703=== PAUSE TestReadProxyNarinfo704=== RUN TestReadProxyNarinfoAlreadyDecompressed705=== PAUSE TestReadProxyNarinfoAlreadyDecompressed706=== RUN TestReadProxyContentNegotiation707=== PAUSE TestReadProxyContentNegotiation708=== RUN TestReadProxyNarStreaming709=== PAUSE TestReadProxyNarStreaming710=== RUN TestReadProxy404711=== PAUSE TestReadProxy404712=== RUN TestReadProxyInvalidPath713=== PAUSE TestReadProxyInvalidPath714=== RUN TestReadProxyHead715=== PAUSE TestReadProxyHead716=== RUN TestReadProxyOutlastsServerWriteTimeout717=== PAUSE TestReadProxyOutlastsServerWriteTimeout718=== RUN TestReadProxyConditionalGet719=== PAUSE TestReadProxyConditionalGet720=== RUN TestReadProxyRootRedirectsToIndexHTML721=== PAUSE TestReadProxyRootRedirectsToIndexHTML722=== RUN TestReadProxyDisabled723=== PAUSE TestReadProxyDisabled724=== RUN TestReadRedirectNar725=== PAUSE TestReadRedirectNar726=== RUN TestReadRedirectKeepsNarinfoProxied727=== PAUSE TestReadRedirectKeepsNarinfoProxied728=== RUN TestReadProxyRangeRequest729=== PAUSE TestReadProxyRangeRequest730=== RUN TestReadRedirectUsesPublicS3URL731=== PAUSE TestReadRedirectUsesPublicS3URL732=== RUN TestPush_OverlappingRootsStoreOneRowPerKey733=== PAUSE TestPush_OverlappingRootsStoreOneRowPerKey734=== RUN TestPush_CompleteCommitsEveryRoot735=== PAUSE TestPush_CompleteCommitsEveryRoot736=== RUN TestPush_RepeatedRootCommitsOnce737=== PAUSE TestPush_RepeatedRootCommitsOnce738=== RUN TestPush_CompleteWaitsForCleanupOfThePush739=== PAUSE TestPush_CompleteWaitsForCleanupOfThePush740=== RUN TestPush_RootsAreLockedInByteOrder741=== PAUSE TestPush_RootsAreLockedInByteOrder742=== RUN TestPush_SkippedKeySurvivesGCBeforeCommit743=== PAUSE TestPush_SkippedKeySurvivesGCBeforeCommit744=== RUN TestPush_RejectsBadRequests745=== PAUSE TestPush_RejectsBadRequests746=== RUN TestPush_SignsNarinfosOfItsPendingObjects747=== PAUSE TestPush_SignsNarinfosOfItsPendingObjects748=== RUN TestRedundantMultipartUpload749=== PAUSE TestRedundantMultipartUpload750=== RUN TestCompleteMultipartUpload_ErrorButObjectExists751=== PAUSE TestCompleteMultipartUpload_ErrorButObjectExists752=== RUN TestCompletedNarNotReofferedAcrossClosures753=== PAUSE TestCompletedNarNotReofferedAcrossClosures754=== RUN TestPresignedUploadRegisteredBeforeCommit755=== PAUSE TestPresignedUploadRegisteredBeforeCommit756=== RUN TestService_Rustfstest757=== PAUSE TestService_Rustfstest758=== RUN TestParseSize759=== PAUSE TestParseSize760=== RUN TestSkippedUploadsHandler761=== PAUSE TestSkippedUploadsHandler762=== RUN TestSystemdListenerNotActivated763--- PASS: TestSystemdListenerNotActivated (0.00s)764=== RUN TestWatchdogBeatsWhenHealthy765--- PASS: TestWatchdogBeatsWhenHealthy (0.03s)766=== RUN TestWatchdogSkipsWhenUnhealthy7672026/11/06 06:52:15 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7682026/11/06 06:52:15 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7692026/11/06 06:52:15 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7702026/11/06 06:52:15 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7712026/11/06 06:52:15 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7722026/11/06 06:52:15 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7732026/11/06 06:52:15 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7742026/11/06 06:52:15 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7752026/11/06 06:52:15 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7762026/11/06 06:52:15 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"777--- PASS: TestWatchdogSkipsWhenUnhealthy (0.20s)778=== RUN TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle779=== PAUSE TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle780=== RUN TestProxyWriteTimeout781=== PAUSE TestProxyWriteTimeout782=== RUN TestPendingClosureWriteTimeout783=== PAUSE TestPendingClosureWriteTimeout784=== RUN TestIsValidUploadKey785=== PAUSE TestIsValidUploadKey786=== RUN TestUploadHandlersRejectInvalidKeys787=== PAUSE TestUploadHandlersRejectInvalidKeys788=== RUN TestUploadHandlersRejectOversizedBody789=== PAUSE TestUploadHandlersRejectOversizedBody790=== RUN TestService_cleanupPendingClosuresHandler791=== PAUSE TestService_cleanupPendingClosuresHandler792=== RUN TestService_createPendingClosureHandler793=== PAUSE TestService_createPendingClosureHandler794=== RUN TestService_verifyS3Integrity795=== PAUSE TestService_verifyS3Integrity796=== RUN TestService_verifyS3ReuploadsStaleNarinfo797=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo798=== RUN TestCompleteMultipartUnregistered799=== PAUSE TestCompleteMultipartUnregistered800=== RUN TestCreatePendingClosure_SmallNARUsesSimplePUT801=== PAUSE TestCreatePendingClosure_SmallNARUsesSimplePUT802=== CONT TestPush_CompleteCommitsEveryRoot803=== CONT TestGCEndsOnShutdown804=== CONT TestTombstonedObjectOfferedWithoutWaiting805=== CONT TestService_healthCheckHandler806=== RUN TestGCEndsOnShutdown/before_the_run807=== PAUSE TestGCEndsOnShutdown/before_the_run808=== CONT TestService_AuthMiddleware809=== CONT TestPush_OverlappingRootsStoreOneRowPerKey810=== CONT TestGCTaskStore_ConflictDifferentParams811--- PASS: TestGCTaskStore_ConflictDifferentParams (0.00s)812=== CONT TestPush_SignsNarinfosOfItsPendingObjects813=== CONT TestReadRedirectUsesPublicS3URL814=== CONT TestReadProxyRangeRequest815=== CONT TestReadRedirectKeepsNarinfoProxied816=== CONT TestReadRedirectNar817=== CONT TestGCTaskStore_DeduplicateSameParams818=== CONT TestGCTaskStore_StartNew819=== CONT TestReadProxyDisabled820=== CONT TestSkippedUploadsHandler821=== CONT TestPresentRefreshesOnlyStaleClosures822=== CONT TestGracefulShutdownDrainsInflight823=== CONT TestPresentReportsOnlyClosureRoots824=== CONT TestGCTaskStore_Fail825=== CONT TestPush_RootsAreLockedInByteOrder826=== CONT TestGCTaskStore_PhaseUpdates827=== CONT TestGCTaskStore_CompletedAllowsNewTask828=== CONT TestGCTaskStore_GetReturnsLatest829=== CONT TestPush_SkippedKeySurvivesGCBeforeCommit830=== CONT TestGCTaskStore_GetEmpty831=== RUN TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete832--- PASS: TestGCTaskStore_DeduplicateSameParams (0.00s)833=== CONT TestCreatePin_ReservedPins834--- PASS: TestGCTaskStore_StartNew (0.00s)835--- PASS: TestGCTaskStore_Fail (0.00s)836--- PASS: TestGCTaskStore_GetReturnsLatest (0.00s)8372026/11/06 06:52:15 INFO Client skipped oversized paths paths=3 nar_bytes=5000000000838--- PASS: TestGCTaskStore_GetEmpty (0.00s)839--- PASS: TestGCTaskStore_PhaseUpdates (0.00s)840--- PASS: TestGCTaskStore_CompletedAllowsNewTask (0.00s)841=== CONT TestGCBugBareHashReferences842=== CONT TestPush_CompleteWaitsForCleanupOfThePush843=== CONT TestOrphanedObjectsGCStressTest844=== CONT TestPush_RejectsBadRequests845=== PAUSE TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete846=== RUN TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark847=== PAUSE TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark848=== CONT TestOrphanedObjectsGC849=== CONT TestGCSweepSkipsPendingObjects8502026/11/06 06:52:15 INFO Starting HTTP server address=127.0.0.1:52206851--- PASS: TestSkippedUploadsHandler (0.00s)852=== CONT TestObjectStatsUpdatedOncePerCommit8532026/11/06 06:52:15 INFO Shutdown signal received, draining in-flight requests timeout=10s854--- PASS: TestGracefulShutdownDrainsInflight (0.09s)855=== CONT TestObjectStatsTrigger8562026/11/06 06:52:16 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:52208/oidc8572026/11/06 06:52:17 INFO Received uploads request method=POST path=/api/pending_closures858--- PASS: TestTombstonedObjectOfferedWithoutWaiting (2.02s)859=== CONT TestDeduplicatedObjectsRecordedAsPending860=== RUN TestPush_RejectsBadRequests/no_roots861=== PAUSE TestPush_RejectsBadRequests/no_roots862=== RUN TestPush_RejectsBadRequests/no_objects863=== PAUSE TestPush_RejectsBadRequests/no_objects864=== RUN TestPush_RejectsBadRequests/bad_root865=== PAUSE TestPush_RejectsBadRequests/bad_root866=== RUN TestPush_RejectsBadRequests/root_not_in_objects867=== PAUSE TestPush_RejectsBadRequests/root_not_in_objects868=== CONT TestPushDedupSurvivesConcurrentGC869--- PASS: TestService_healthCheckHandler (2.40s)870=== CONT TestGCMetrics871--- PASS: TestReadProxyRangeRequest (2.63s)872=== CONT TestLeadEndsOnShutdown873--- PASS: TestReadRedirectNar (2.77s)874=== CONT TestGCAdvisoryLockBlocksConcurrentRun875--- PASS: TestReadRedirectUsesPublicS3URL (2.91s)876=== CONT TestPendingCleanupUsesOneCutoff877--- PASS: TestReadProxyDisabled (3.05s)878=== CONT TestMultipartCleanup8792026/11/06 06:52:18 WARN Authentication failed token_preview=wrongtoken token_length=10 reason="static API token mismatch"880--- PASS: TestService_AuthMiddleware (3.25s)881=== CONT TestServerTLSConfig882=== RUN TestServerTLSConfig/no_client_CA883=== PAUSE TestServerTLSConfig/no_client_CA884=== RUN TestServerTLSConfig/missing_CA_file885=== PAUSE TestServerTLSConfig/missing_CA_file886=== RUN TestServerTLSConfig/not_a_PEM_file887=== PAUSE TestServerTLSConfig/not_a_PEM_file888=== CONT TestMultipartUploadAbortedWhenCancelledBeforeRecorded889--- PASS: TestReadRedirectKeepsNarinfoProxied (3.69s)890=== CONT TestLeadIncumbentAnnouncesAtOnce8912026/11/06 06:52:19 INFO Received push request method=POST path=/api/pushes8922026/11/06 06:52:19 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign8932026/11/06 06:52:19 INFO Signed narinfos id=1 count=18942026/11/06 06:52:19 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign8952026/11/06 06:52:19 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign8962026/11/06 06:52:19 ERROR Failed to sign narinfos signer="index 1" error="signing key cannot be nil"8972026/11/06 06:52:19 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign8982026/11/06 06:52:19 ERROR Failed to sign narinfos signer=niks3-test-1 error="signer failed"8992026/11/06 06:52:19 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign9002026/11/06 06:52:19 ERROR Signer returned unexpected signature count signer=niks3-test-1 got=0 want=19012026/11/06 06:52:19 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign9022026/11/06 06:52:19 ERROR Signer returned unexpected object key signer=niks3-test-1 object_key=unexpected.narinfo903--- PASS: TestPush_SignsNarinfosOfItsPendingObjects (3.98s)904=== CONT TestPush_RepeatedRootCommitsOnce9052026/11/06 06:52:19 INFO Received push request method=POST path=/api/pushes906--- PASS: TestPush_OverlappingRootsStoreOneRowPerKey (4.19s)907=== CONT TestLeadElectsOneAndHandsOver908--- PASS: TestPresentReportsOnlyClosureRoots (4.38s)909=== CONT TestClientPushesUseOnePush9102026/11/06 06:52:20 INFO Received push request method=POST path=/api/pushes9112026-11-06 06:52:20.497 UTC [72750] ERROR: Push does not exist: id=19122026-11-06 06:52:20.497 UTC [72750] CONTEXT: PL/pgSQL function commit_push(bigint) line 11 at RAISE9132026-11-06 06:52:20.497 UTC [72750] STATEMENT: SELECT commit_push($1)914--- PASS: TestPush_CompleteWaitsForCleanupOfThePush (4.97s)915=== CONT TestClientErrorHandling916=== RUN TestClientErrorHandling/InvalidStorePath917=== PAUSE TestClientErrorHandling/InvalidStorePath918=== RUN TestClientErrorHandling/InvalidAuthToken919=== PAUSE TestClientErrorHandling/InvalidAuthToken920=== RUN TestClientErrorHandling/ServerNotAvailable921=== PAUSE TestClientErrorHandling/ServerNotAvailable922=== CONT TestPinProtectsFromGC9232026/11/06 06:52:20 INFO Received uploads request method=POST path=/api/pending_closures9242026/11/06 06:52:20 INFO Aborted multipart uploads count=0 kept=09252026/11/06 06:52:20 WARN Force mode enabled - objects will be deleted immediately without grace period9262026/11/06 06:52:20 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=09272026/11/06 06:52:20 INFO Vacuumed table table=pending_closures9282026/11/06 06:52:20 INFO Vacuumed table table=pending_objects9292026/11/06 06:52:20 INFO Vacuumed table table=multipart_uploads9302026/11/06 06:52:20 INFO Vacuumed table table=closures9312026/11/06 06:52:20 INFO Vacuumed table table=objects9322026/11/06 06:52:20 INFO Received push request method=POST path=/api/pushes933--- PASS: TestGCSweepSkipsPendingObjects (5.27s)934=== CONT TestClientCADerivations9352026-11-06 06:52:21.000 UTC [72757] ERROR: could not obtain lock on row in relation "closures"9362026-11-06 06:52:21.000 UTC [72757] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT9372026-11-06 06:52:21.004 UTC [72757] ERROR: could not obtain lock on row in relation "closures"9382026-11-06 06:52:21.004 UTC [72757] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT9392026-11-06 06:52:21.008 UTC [72757] ERROR: could not obtain lock on row in relation "closures"9402026-11-06 06:52:21.008 UTC [72757] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT9412026-11-06 06:52:21.012 UTC [72757] ERROR: could not obtain lock on row in relation "closures"9422026-11-06 06:52:21.012 UTC [72757] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT9432026-11-06 06:52:21.019 UTC [72757] ERROR: could not obtain lock on row in relation "closures"9442026-11-06 06:52:21.019 UTC [72757] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT945--- PASS: TestPush_RootsAreLockedInByteOrder (5.52s)946=== CONT TestCacheStatsHandler947--- PASS: TestGCBugBareHashReferences (5.92s)948=== CONT TestResolveDBConnectionString949=== RUN TestResolveDBConnectionString/flag_wins950=== PAUSE TestResolveDBConnectionString/flag_wins951=== RUN TestResolveDBConnectionString/file_when_flag_empty952=== PAUSE TestResolveDBConnectionString/file_when_flag_empty953=== RUN TestResolveDBConnectionString/missing_file_is_an_error954=== PAUSE TestResolveDBConnectionString/missing_file_is_an_error955=== RUN TestResolveDBConnectionString/PGHOST_allows_empty956=== PAUSE TestResolveDBConnectionString/PGHOST_allows_empty957=== RUN TestResolveDBConnectionString/nothing_configured958=== PAUSE TestResolveDBConnectionString/nothing_configured959=== CONT TestConcurrentCommitsSharingObjectsDoNotDeadlock9602026/11/06 06:52:21 INFO Received push request method=POST path=/api/pushes9612026/11/06 06:52:21 INFO Received complete push request method=POST path=/api/pushes/1/complete9622026/11/06 06:52:21 INFO Completed push id=1 objects=4 duration=30.496417ms9632026/11/06 06:52:21 INFO Received push request method=POST path=/api/pushes9642026/11/06 06:52:21 INFO Aborted multipart uploads count=0 kept=09652026/11/06 06:52:21 WARN Force mode enabled - objects will be deleted immediately without grace period9662026/11/06 06:52:21 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=0967--- PASS: TestPresentRefreshesOnlyStaleClosures (6.35s)968=== CONT TestClientSharedPathCommittedMidPush9692026/11/06 06:52:21 INFO Vacuumed table table=pending_closures9702026/11/06 06:52:21 INFO Vacuumed table table=pending_objects9712026/11/06 06:52:21 INFO Vacuumed table table=multipart_uploads9722026/11/06 06:52:22 INFO Vacuumed table table=closures9732026/11/06 06:52:22 INFO Vacuumed table table=objects9742026/11/06 06:52:22 INFO Received complete push request method=POST path=/api/pushes/2/complete9752026/11/06 06:52:22 INFO Completed push id=2 objects=4 duration=13.151792ms976--- PASS: TestPush_SkippedKeySurvivesGCBeforeCommit (6.63s)977=== CONT TestClientWithDependencies978=== NAME TestOrphanedObjectsGC979 orphaned_objects_gc_test.go:287: GC Test Summary:980 orphaned_objects_gc_test.go:288: - Kept: 2 objects from closure A981 orphaned_objects_gc_test.go:289: - Deleted: 2 objects from closure B982 orphaned_objects_gc_test.go:290: - Deleted: 6 orphaned chain objects (X1->X2->X3)983 orphaned_objects_gc_test.go:291: - Deleted: 2 orphaned single objects (Y)984 orphaned_objects_gc_test.go:292: - Total deleted: 10 objects985--- PASS: TestOrphanedObjectsGC (6.81s)986=== CONT TestDeleteClosuresRacingPins987--- PASS: TestObjectStatsUpdatedOncePerCommit (6.99s)988=== CONT TestClientMultipleUploads989--- PASS: TestObjectStatsTrigger (7.02s)990=== CONT TestClientFallsBackToClosures9912026/11/06 06:52:22 INFO Received push request method=POST path=/api/pushes9922026/11/06 06:52:22 INFO Received complete push request method=POST path=/api/pushes/1/complete9932026/11/06 06:52:23 INFO Completed push id=1 objects=6 duration=37.369042ms994--- PASS: TestPush_CompleteCommitsEveryRoot (7.50s)995=== CONT TestClientIntegration9962026/11/06 06:52:23 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux9972026/11/06 06:52:23 WARN Refused reserved pin name=worker-x86_64-linux9982026/11/06 06:52:23 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux9992026/11/06 06:52:23 INFO Received create pin request method=POST path=/api/pins/my-app10002026/11/06 06:52:23 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux1001--- PASS: TestCreatePin_ReservedPins (7.77s)1002=== CONT TestService_ReadAuthMiddleware10032026/11/06 06:52:23 INFO Received uploads request method=POST path=/api/pending_closures10042026/11/06 06:52:24 INFO Received uploads request method=POST path=/api/pending_closures1005--- PASS: TestDeduplicatedObjectsRecordedAsPending (6.54s)1006=== CONT TestService_AuthMiddleware_MTLSProxyHeader10072026/11/06 06:52:24 INFO Aborted multipart uploads count=0 kept=010082026/11/06 06:52:24 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=010092026/11/06 06:52:24 INFO Vacuumed table table=pending_closures10102026/11/06 06:52:24 INFO Vacuumed table table=pending_objects10112026/11/06 06:52:24 INFO Vacuumed table table=multipart_uploads10122026/11/06 06:52:24 INFO Vacuumed table table=closures10132026/11/06 06:52:24 INFO Vacuumed table table=objects10142026/11/06 06:52:24 INFO Aborted multipart uploads count=0 kept=010152026/11/06 06:52:24 WARN Force mode enabled - objects will be deleted immediately without grace period10162026/11/06 06:52:24 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=010172026/11/06 06:52:24 INFO Vacuumed table table=pending_closures10182026/11/06 06:52:24 INFO Vacuumed table table=pending_objects10192026/11/06 06:52:24 INFO Vacuumed table table=multipart_uploads10202026/11/06 06:52:24 INFO Vacuumed table table=closures10212026/11/06 06:52:24 INFO Vacuumed table table=objects1022--- PASS: TestPushDedupSurvivesConcurrentGC (6.71s)1023=== CONT TestService_AuthMiddleware_MTLSBoundSubjects10242026/11/06 06:52:24 INFO Aborted multipart uploads count=0 kept=010252026/11/06 06:52:24 WARN Force mode enabled - objects will be deleted immediately without grace period10262026/11/06 06:52:24 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=010272026/11/06 06:52:24 INFO Vacuumed table table=pending_closures10282026/11/06 06:52:24 INFO Vacuumed table table=pending_objects10292026/11/06 06:52:24 INFO Vacuumed table table=multipart_uploads10302026/11/06 06:52:24 INFO Vacuumed table table=closures10312026/11/06 06:52:24 INFO Vacuumed table table=objects1032--- PASS: TestGCMetrics (6.68s)1033=== CONT TestCacheConfigHandler1034=== RUN TestCacheConfigHandler/full_config,_no_issuer1035=== PAUSE TestCacheConfigHandler/full_config,_no_issuer1036=== RUN TestCacheConfigHandler/no_cache_url_configured1037=== PAUSE TestCacheConfigHandler/no_cache_url_configured1038=== RUN TestCacheConfigHandler/no_signing_keys1039=== PAUSE TestCacheConfigHandler/no_signing_keys1040=== RUN TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1041=== PAUSE TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1042=== CONT TestService_ReadScope_PublicByDefault10432026/11/06 06:52:24 INFO lead: acquired remote=192.0.2.1:123410442026/11/06 06:52:25 ERROR failed to check GC advisory lock error="query pg_locks: failed to connect to `user=_tribuchetbld5 database=niks3`: /nonexistent/.s.PGSQL.5432 (/nonexistent): dial error: dial unix /nonexistent/.s.PGSQL.5432: connect: no such file or directory"1045--- PASS: TestGCAdvisoryLockBlocksConcurrentRun (6.97s)1046=== CONT TestReadProxyRootRedirectsToIndexHTML10472026/11/06 06:52:25 INFO Received uploads request method=POST path=/api/pending_closures10482026/11/06 06:52:25 INFO Received uploads request method=POST path=/api/pending_closures10492026/11/06 06:52:25 INFO Received cleanup request method=DELETE path=/api/pending_closures10502026/11/06 06:52:25 INFO lead: released remote=192.0.2.1:12341051--- PASS: TestLeadEndsOnShutdown (7.77s)1052=== CONT TestCreatePendingClosure_SmallNARUsesSimplePUT10532026/11/06 06:52:25 INFO Received uploads request method=POST path=/api/pending_closures10542026/11/06 06:52:26 INFO Received cleanup request method=DELETE path=/api/pending_closures10552026/11/06 06:52:26 WARN Failed to abort upload, keeping its closure key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst error="Get \"http://127.0.0.1:1/bucket34/?location=\": dial tcp 127.0.0.1:1: connect: connection refused" code=""10562026/11/06 06:52:26 INFO Aborted multipart uploads count=0 kept=110572026/11/06 06:52:26 INFO Received cleanup request method=DELETE path=/api/pending_closures10582026/11/06 06:52:26 INFO Aborted multipart uploads count=1 kept=01059--- PASS: TestMultipartCleanup (7.70s)1060=== CONT TestService_AuthMiddleware_OIDC10612026/11/06 06:52:26 INFO Received uploads request method=POST path=/api/pending_closures10622026/11/06 06:52:26 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:52313/oidc1063--- PASS: TestMultipartUploadAbortedWhenCancelledBeforeRecorded (7.66s)1064=== CONT TestCompleteMultipartUnregistered10652026/11/06 06:52:26 INFO lead: acquired remote=192.0.2.1:123410662026/11/06 06:52:26 INFO lead: released remote=192.0.2.1:12341067--- PASS: TestLeadIncumbentAnnouncesAtOnce (7.40s)1068=== CONT TestService_RequireScope_OIDC10692026/11/06 06:52:26 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:52321/oidc10702026/11/06 06:52:26 INFO Received push request method=POST path=/api/pushes10712026/11/06 06:52:26 INFO Received complete push request method=POST path=/api/pushes/1/complete10722026/11/06 06:52:27 INFO Completed push id=1 objects=4 duration=44.297042ms1073--- PASS: TestPush_RepeatedRootCommitsOnce (7.52s)1074=== CONT TestService_verifyS3ReuploadsStaleNarinfo1075=== RUN TestService_verifyS3ReuploadsStaleNarinfo/lost,_other_NAR_pushed1076=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo/lost,_other_NAR_pushed1077=== RUN TestService_verifyS3ReuploadsStaleNarinfo/intact,_other_NAR_pushed1078=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo/intact,_other_NAR_pushed1079=== RUN TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost1080=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost1081=== RUN TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost,_second_pushed1082=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost,_second_pushed1083=== RUN TestService_verifyS3ReuploadsStaleNarinfo/lost,_same_NAR_pushed1084=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo/lost,_same_NAR_pushed1085=== CONT TestService_verifyS3Integrity10862026/11/06 06:52:27 INFO lead: acquired remote=192.0.2.1:12341087=== NAME TestPinProtectsFromGC1088 client_integration_test.go:778: Pinned store path: /private/var/tb/5/scratch/87d7ae187515016b/build/TestPinProtectsFromGC1601802468/001/store/1pnmba5lpmhlb5pnaximycl0f24b1ba3-pinned-file.txt1089 client_integration_test.go:779: Unpinned store path: /private/var/tb/5/scratch/87d7ae187515016b/build/TestPinProtectsFromGC1601802468/001/store/6kalww2cpjs7jwz6d34dshg2hrgvaqnw-unpinned-file.txt10902026/11/06 06:52:28 INFO Received push request method=POST path=/api/pushes10912026/11/06 06:52:28 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)10922026/11/06 06:52:28 INFO Uploading qb99br2zp1ql9xgh37rh2pdacaaicpz7-shared-dep (136B)10932026/11/06 06:52:28 INFO Uploading zs6f3dz3bplaymjdkan2jnwyahggzfp2-b (256B)10942026/11/06 06:52:28 INFO Received push request method=POST path=/api/pushes10952026/11/06 06:52:28 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)10962026/11/06 06:52:28 INFO Uploading 1pnmba5lpmhlb5pnaximycl0f24b1ba3-pinned-file.txt (128B)10972026/11/06 06:52:28 WARN Failed to register uploaded object key=qb99br2zp1ql9xgh37rh2pdacaaicpz7.ls error="server returned 404: 404 page not found\n"10982026/11/06 06:52:28 WARN Failed to register uploaded object key=zs6f3dz3bplaymjdkan2jnwyahggzfp2.ls error="server returned 404: 404 page not found\n"10992026/11/06 06:52:28 WARN Failed to register uploaded object key=4frq1y14z7n1rwml7avq3pawgy31ra13.ls error="server returned 404: 404 page not found\n"11002026/11/06 06:52:28 WARN Failed to register uploaded object key=nar/0dkddl6hwsgzsai2fri87ys6yg3ci4gs0nm8bxj753fcppijl90v.nar.zst error="server returned 404: 404 page not found\n"11012026/11/06 06:52:28 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"11022026/11/06 06:52:28 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign11032026/11/06 06:52:28 INFO Signed narinfos id=1 count=311042026/11/06 06:52:28 INFO Uploading 3 narinfos11052026/11/06 06:52:28 WARN Failed to register uploaded object key=1pnmba5lpmhlb5pnaximycl0f24b1ba3.ls error="server returned 404: 404 page not found\n"11062026/11/06 06:52:28 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign11072026/11/06 06:52:28 WARN Failed to register uploaded object key=nar/0qmhsg42pqsz7x6hh02j8gznnac3yi3qpjhrqbwvz88i194jbb5s.nar.zst error="server returned 404: 404 page not found\n"11082026/11/06 06:52:28 INFO Signed narinfos id=1 count=111092026/11/06 06:52:28 INFO Uploading 1 narinfos11102026/11/06 06:52:28 WARN Failed to register uploaded object key=qb99br2zp1ql9xgh37rh2pdacaaicpz7.narinfo error="server returned 404: 404 page not found\n"11112026/11/06 06:52:28 WARN Failed to register uploaded object key=4frq1y14z7n1rwml7avq3pawgy31ra13.narinfo error="server returned 404: 404 page not found\n"11122026/11/06 06:52:28 INFO Received complete push request method=POST path=/api/pushes/1/complete11132026/11/06 06:52:28 WARN Failed to register uploaded object key=zs6f3dz3bplaymjdkan2jnwyahggzfp2.narinfo error="server returned 404: 404 page not found\n"11142026/11/06 06:52:28 INFO Received complete push request method=POST path=/api/pushes/1/complete11152026/11/06 06:52:28 WARN Failed to register uploaded object key=1pnmba5lpmhlb5pnaximycl0f24b1ba3.narinfo error="server returned 404: 404 page not found\n"11162026/11/06 06:52:28 INFO Completed push id=1 objects=8 duration=26.770041ms11172026/11/06 06:52:28 INFO Upload complete. (326ms)1118=== NAME TestClientPushesUseOnePush1119 client_pushes_test.go:97: Retrieved narinfo from S3:1120 StorePath: /private/var/tb/5/scratch/87d7ae187515016b/build/TestClientPushesUseOnePush2444508750/001/store/qb99br2zp1ql9xgh37rh2pdacaaicpz7-shared-dep1121 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1122 Compression: zstd1123 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821124 NarSize: 1361125 References: 1126 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1127 client_pushes_test.go:97: Retrieved narinfo from S3:1128 StorePath: /private/var/tb/5/scratch/87d7ae187515016b/build/TestClientPushesUseOnePush2444508750/001/store/4frq1y14z7n1rwml7avq3pawgy31ra13-a1129 URL: nar/0dkddl6hwsgzsai2fri87ys6yg3ci4gs0nm8bxj753fcppijl90v.nar.zst1130 Compression: zstd1131 NarHash: sha256:0dkddl6hwsgzsai2fri87ys6yg3ci4gs0nm8bxj753fcppijl90v1132 NarSize: 2561133 References: /private/var/tb/5/scratch/87d7ae187515016b/build/TestClientPushesUseOnePush2444508750/001/store/qb99br2zp1ql9xgh37rh2pdacaaicpz7-shared-dep1134 CA: text:sha256:0a8dk4vj4cwlazqgf3q5k7l8rmbvswgvmxjpr4bss4w44pzw368m11352026/11/06 06:52:28 INFO Completed push id=1 objects=3 duration=12.688708ms11362026/11/06 06:52:28 INFO Upload complete. (312ms)1137 client_pushes_test.go:97: Retrieved narinfo from S3:1138 StorePath: /private/var/tb/5/scratch/87d7ae187515016b/build/TestClientPushesUseOnePush2444508750/001/store/zs6f3dz3bplaymjdkan2jnwyahggzfp2-b1139 URL: nar/0dkddl6hwsgzsai2fri87ys6yg3ci4gs0nm8bxj753fcppijl90v.nar.zst1140 Compression: zstd1141 NarHash: sha256:0dkddl6hwsgzsai2fri87ys6yg3ci4gs0nm8bxj753fcppijl90v1142 NarSize: 2561143 References: /private/var/tb/5/scratch/87d7ae187515016b/build/TestClientPushesUseOnePush2444508750/001/store/qb99br2zp1ql9xgh37rh2pdacaaicpz7-shared-dep1144 CA: text:sha256:0a8dk4vj4cwlazqgf3q5k7l8rmbvswgvmxjpr4bss4w44pzw368m1145--- PASS: TestCacheStatsHandler (7.27s)1146=== CONT TestReadProxyConditionalGet1147--- PASS: TestClientPushesUseOnePush (8.41s)1148=== CONT TestService_createPendingClosureHandler11492026/11/06 06:52:28 INFO lead: released remote=192.0.2.1:123411502026/11/06 06:52:28 INFO Received push request method=POST path=/api/pushes11512026/11/06 06:52:28 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)11522026/11/06 06:52:28 INFO lead: acquired remote=192.0.2.1:123411532026/11/06 06:52:28 INFO Uploading 6kalww2cpjs7jwz6d34dshg2hrgvaqnw-unpinned-file.txt (128B)11542026/11/06 06:52:28 WARN Failed to register uploaded object key=6kalww2cpjs7jwz6d34dshg2hrgvaqnw.ls error="server returned 404: 404 page not found\n"11552026/11/06 06:52:28 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign11562026/11/06 06:52:28 INFO Signed narinfos id=2 count=111572026/11/06 06:52:28 WARN Failed to register uploaded object key=nar/0gh0wdnr6gmk4r5sfzzh12isnl14rgmkrwy1ws41hpsrlndclg5h.nar.zst error="server returned 404: 404 page not found\n"11582026/11/06 06:52:28 INFO Uploading 1 narinfos11592026/11/06 06:52:28 INFO Received complete push request method=POST path=/api/pushes/2/complete11602026/11/06 06:52:28 WARN Failed to register uploaded object key=6kalww2cpjs7jwz6d34dshg2hrgvaqnw.narinfo error="server returned 404: 404 page not found\n"11612026/11/06 06:52:28 INFO Completed push id=2 objects=3 duration=840.042µs11622026/11/06 06:52:28 INFO Upload complete. (167ms)1163=== NAME TestClientCADerivations1164 client_ca_test.go:136: Built CA derivation: /private/var/tb/5/scratch/87d7ae187515016b/build/TestClientCADerivations1838722742/001/store/k090pzgx26dbbx6x2fqhk3xlqpdcx8z4-ca-test11652026/11/06 06:52:28 INFO Starting cleanup of old closures method=DELETE path=/api/closures11662026/11/06 06:52:28 INFO Garbage collection started11672026/11/06 06:52:28 INFO Aborted multipart uploads count=0 kept=011682026/11/06 06:52:28 WARN Force mode enabled - objects will be deleted immediately without grace period1169 client_ca_test.go:139: Found 1 dependencies (including self)11702026/11/06 06:52:28 INFO Received push request method=POST path=/api/pushes11712026/11/06 06:52:28 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)11722026/11/06 06:52:28 INFO Uploading k090pzgx26dbbx6x2fqhk3xlqpdcx8z4-ca-test (144B)11732026/11/06 06:52:28 WARN Failed to register uploaded object key=k090pzgx26dbbx6x2fqhk3xlqpdcx8z4.ls error="server returned 404: 404 page not found\n"11742026/11/06 06:52:28 WARN Failed to register uploaded object key=nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst error="server returned 404: 404 page not found\n"11752026/11/06 06:52:28 WARN Failed to register uploaded object key=log/f8l8q1dmfn0ann2rk7r2hvayd22cm556-ca-test.drv error="server returned 404: 404 page not found\n"11762026/11/06 06:52:28 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign11772026/11/06 06:52:28 INFO Signed narinfos id=1 count=111782026/11/06 06:52:28 INFO Uploading 1 narinfos11792026/11/06 06:52:28 INFO Received complete push request method=POST path=/api/pushes/1/complete11802026/11/06 06:52:28 WARN Failed to register uploaded object key=k090pzgx26dbbx6x2fqhk3xlqpdcx8z4.narinfo error="server returned 404: 404 page not found\n"11812026/11/06 06:52:28 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=011822026/11/06 06:52:29 INFO Completed push id=1 objects=4 duration=27.468041ms11832026/11/06 06:52:29 INFO Upload complete. (364ms)11842026/11/06 06:52:29 INFO Vacuumed table table=pending_closures1185 client_ca_test.go:180: Narinfo contains CA field: StorePath: /private/var/tb/5/scratch/87d7ae187515016b/build/TestClientCADerivations1838722742/001/store/k090pzgx26dbbx6x2fqhk3xlqpdcx8z4-ca-test1186 URL: nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst1187 Compression: zstd1188 NarHash: sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1189 NarSize: 1441190 References: 1191 Deriver: /private/var/tb/5/scratch/87d7ae187515016b/build/TestClientCADerivations1838722742/001/store/f8l8q1dmfn0ann2rk7r2hvayd22cm556-ca-test.drv1192 CA: fixed:r:sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1193 client_ca_test.go:185: Checking for realisation files in S3...1194 client_ca_test.go:207: No realisation files uploaded - this is expected for locally built CA derivations1195 client_ca_test.go:208: Locally built CA derivations don't have DrvOutput IDs until they're substituted from a cache11962026/11/06 06:52:29 INFO Vacuumed table table=pending_objects11972026/11/06 06:52:29 INFO Vacuumed table table=multipart_uploads11982026/11/06 06:52:29 INFO Vacuumed table table=closures1199 client_ca_test.go:258: nix copy output: error: binary cache 's3://bucket41?endpoint=http://localhost:52138®ion=eu-west-1' is for Nix stores with prefix '/nix/store', not '/private/var/tb/5/scratch/87d7ae187515016b/build/TestClientCADerivations1838722742/001/store'1200 client_ca_test.go:259: nix copy failed (might be expected with isolated stores): exit status 112012026/11/06 06:52:29 INFO Vacuumed table table=objects1202--- PASS: TestClientCADerivations (8.35s)1203=== CONT TestService_cleanupPendingClosuresHandler12042026/11/06 06:52:29 INFO Received push request method=POST path=/api/pushes12052026/11/06 06:52:29 INFO Uploading 2 paths to 127.0.0.1 (0 already cached)12062026/11/06 06:52:29 INFO Uploading hhx7k4wa1j8mkij6gl3m5blwmsxga5aq-shared-dep (136B)12072026/11/06 06:52:29 INFO Uploading ca881gd2sr01h5pdbniz5d98rk9cqqaz-top (264B)12082026/11/06 06:52:29 WARN Failed to register uploaded object key=hhx7k4wa1j8mkij6gl3m5blwmsxga5aq.ls error="server returned 404: 404 page not found\n"12092026/11/06 06:52:29 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"12102026/11/06 06:52:29 WARN Failed to register uploaded object key=ca881gd2sr01h5pdbniz5d98rk9cqqaz.ls error="server returned 404: 404 page not found\n"12112026/11/06 06:52:29 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign12122026/11/06 06:52:29 WARN Failed to register uploaded object key=nar/1y7qhf6vvkxf7r5jnkhg45sjipwsymd82vp9038l1kihr896fhf3.nar.zst error="server returned 404: 404 page not found\n"12132026/11/06 06:52:29 INFO Signed narinfos id=1 count=212142026/11/06 06:52:29 INFO Uploading 2 narinfos12152026/11/06 06:52:29 WARN Failed to register uploaded object key=ca881gd2sr01h5pdbniz5d98rk9cqqaz.narinfo error="server returned 404: 404 page not found\n"12162026/11/06 06:52:29 INFO Received complete push request method=POST path=/api/pushes/1/complete12172026/11/06 06:52:29 WARN Failed to register uploaded object key=hhx7k4wa1j8mkij6gl3m5blwmsxga5aq.narinfo error="server returned 404: 404 page not found\n"12182026/11/06 06:52:29 INFO Completed push id=1 objects=6 duration=25.151959ms12192026/11/06 06:52:29 INFO Upload complete. (222ms)1220=== NAME TestClientSharedPathCommittedMidPush1221 client_integration_test.go:727: Retrieved narinfo from S3:1222 StorePath: /private/var/tb/5/scratch/87d7ae187515016b/build/TestClientSharedPathCommittedMidPush706138969/001/store/hhx7k4wa1j8mkij6gl3m5blwmsxga5aq-shared-dep1223 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1224 Compression: zstd1225 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821226 NarSize: 1361227 References: 1228 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1229 client_integration_test.go:727: Retrieved narinfo from S3:1230 StorePath: /private/var/tb/5/scratch/87d7ae187515016b/build/TestClientSharedPathCommittedMidPush706138969/001/store/ca881gd2sr01h5pdbniz5d98rk9cqqaz-top1231 URL: nar/1y7qhf6vvkxf7r5jnkhg45sjipwsymd82vp9038l1kihr896fhf3.nar.zst1232 Compression: zstd1233 NarHash: sha256:1y7qhf6vvkxf7r5jnkhg45sjipwsymd82vp9038l1kihr896fhf31234 NarSize: 2641235 References: /private/var/tb/5/scratch/87d7ae187515016b/build/TestClientSharedPathCommittedMidPush706138969/001/store/hhx7k4wa1j8mkij6gl3m5blwmsxga5aq-shared-dep1236 CA: text:sha256:025afmnf86ppgdsbif9m4nv5fv9js2bz4x3idi70468dcrbjfhgw1237=== NAME TestClientWithDependencies1238 client_integration_test.go:660: Built derivation: /private/var/tb/5/scratch/87d7ae187515016b/build/TestClientWithDependencies2377672433/001/store/lpbqf7ksnjiwznm2i3nlli65jq3m1vw1-test-script12392026/11/06 06:52:29 INFO lead: released remote=192.0.2.1:12341240--- PASS: TestLeadElectsOneAndHandsOver (9.78s)1241=== CONT TestUploadHandlersRejectOversizedBody1242--- PASS: TestClientSharedPathCommittedMidPush (7.64s)1243=== CONT TestReadProxyOutlastsServerWriteTimeout1244=== NAME TestClientWithDependencies1245 client_integration_test.go:662: Found 1 dependencies (including self)1246=== RUN TestUploadHandlersRejectOversizedBody/create_pending_closure1247=== PAUSE TestUploadHandlersRejectOversizedBody/create_pending_closure1248=== RUN TestUploadHandlersRejectOversizedBody/complete_multipart1249=== PAUSE TestUploadHandlersRejectOversizedBody/complete_multipart1250=== RUN TestUploadHandlersRejectOversizedBody/request_more_parts1251=== PAUSE TestUploadHandlersRejectOversizedBody/request_more_parts1252=== CONT TestUploadHandlersRejectInvalidKeys1253=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info1254=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info1255=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal1256=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal1257=== RUN TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key1258=== PAUSE TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key1259=== RUN TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key1260=== PAUSE TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key1261=== CONT TestIsValidUploadKey1262=== RUN TestIsValidUploadKey/narinfo1263=== PAUSE TestIsValidUploadKey/narinfo1264=== RUN TestIsValidUploadKey/nar_zst1265=== PAUSE TestIsValidUploadKey/nar_zst1266=== RUN TestIsValidUploadKey/nar_xz1267=== PAUSE TestIsValidUploadKey/nar_xz1268=== RUN TestIsValidUploadKey/nar_plain1269=== PAUSE TestIsValidUploadKey/nar_plain1270=== RUN TestIsValidUploadKey/listing1271=== PAUSE TestIsValidUploadKey/listing1272=== RUN TestIsValidUploadKey/build_log1273=== PAUSE TestIsValidUploadKey/build_log1274=== RUN TestIsValidUploadKey/build_log_home-manager_file1275=== PAUSE TestIsValidUploadKey/build_log_home-manager_file1276=== RUN TestIsValidUploadKey/build_log_plus_in_name1277=== PAUSE TestIsValidUploadKey/build_log_plus_in_name1278=== RUN TestIsValidUploadKey/build_log_question_mark1279=== PAUSE TestIsValidUploadKey/build_log_question_mark1280=== RUN TestIsValidUploadKey/build_log_equals1281=== PAUSE TestIsValidUploadKey/build_log_equals1282=== RUN TestIsValidUploadKey/realisation1283=== PAUSE TestIsValidUploadKey/realisation1284=== RUN TestIsValidUploadKey/realisation_plus_in_output1285=== PAUSE TestIsValidUploadKey/realisation_plus_in_output1286=== RUN TestIsValidUploadKey/nix-cache-info1287=== PAUSE TestIsValidUploadKey/nix-cache-info1288=== RUN TestIsValidUploadKey/index.html1289=== PAUSE TestIsValidUploadKey/index.html1290=== RUN TestIsValidUploadKey/narinfo_key,_nar_type1291=== PAUSE TestIsValidUploadKey/narinfo_key,_nar_type1292=== RUN TestIsValidUploadKey/nar_key,_narinfo_type1293=== PAUSE TestIsValidUploadKey/nar_key,_narinfo_type1294=== RUN TestIsValidUploadKey/listing_key,_narinfo_type1295=== PAUSE TestIsValidUploadKey/listing_key,_narinfo_type1296=== RUN TestIsValidUploadKey/traversal1297=== PAUSE TestIsValidUploadKey/traversal1298=== RUN TestIsValidUploadKey/traversal_nar1299=== PAUSE TestIsValidUploadKey/traversal_nar1300=== RUN TestIsValidUploadKey/absolute1301=== PAUSE TestIsValidUploadKey/absolute1302=== RUN TestIsValidUploadKey/empty_key1303=== PAUSE TestIsValidUploadKey/empty_key1304=== RUN TestIsValidUploadKey/unknown_type1305=== PAUSE TestIsValidUploadKey/unknown_type1306=== CONT TestPendingClosureWriteTimeout1307=== RUN TestPendingClosureWriteTimeout/empty1308=== PAUSE TestPendingClosureWriteTimeout/empty1309=== RUN TestPendingClosureWriteTimeout/400_objects1310=== PAUSE TestPendingClosureWriteTimeout/400_objects1311=== RUN TestPendingClosureWriteTimeout/670k_objects1312=== PAUSE TestPendingClosureWriteTimeout/670k_objects1313=== RUN TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline1314=== PAUSE TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline1315=== CONT TestProxyWriteTimeout1316=== RUN TestProxyWriteTimeout/narinfo1317=== PAUSE TestProxyWriteTimeout/narinfo1318=== RUN TestProxyWriteTimeout/1_GiB_nar1319=== PAUSE TestProxyWriteTimeout/1_GiB_nar1320=== RUN TestProxyWriteTimeout/10_GiB_nar1321=== PAUSE TestProxyWriteTimeout/10_GiB_nar1322=== RUN TestProxyWriteTimeout/unknown_size1323=== PAUSE TestProxyWriteTimeout/unknown_size1324=== CONT TestReadProxyHead1325--- PASS: TestConcurrentCommitsSharingObjectsDoNotDeadlock (8.17s)1326=== CONT TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle13272026/11/06 06:52:29 INFO Received push request method=POST path=/api/pushes13282026/11/06 06:52:29 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)13292026/11/06 06:52:29 INFO Uploading lpbqf7ksnjiwznm2i3nlli65jq3m1vw1-test-script (136B)13302026/11/06 06:52:29 WARN Failed to register uploaded object key=lpbqf7ksnjiwznm2i3nlli65jq3m1vw1.ls error="server returned 404: 404 page not found\n"13312026/11/06 06:52:29 WARN Failed to register uploaded object key=nar/1s7yghixzpinyqm7g59kyn3sav81pmnsdi5v63m6x4r2vacy907j.nar.zst error="server returned 404: 404 page not found\n"13322026/11/06 06:52:29 WARN Failed to register uploaded object key=log/8y1jsf5irhcwypyys9086s46ra7y5fjd-test-script.drv error="server returned 404: 404 page not found\n"13332026/11/06 06:52:29 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign13342026/11/06 06:52:29 INFO Signed narinfos id=1 count=113352026/11/06 06:52:29 INFO Uploading 1 narinfos13362026/11/06 06:52:29 INFO Received complete push request method=POST path=/api/pushes/1/complete13372026/11/06 06:52:29 WARN Failed to register uploaded object key=lpbqf7ksnjiwznm2i3nlli65jq3m1vw1.narinfo error="server returned 404: 404 page not found\n"13382026/11/06 06:52:29 INFO Completed push id=1 objects=4 duration=22.647417ms13392026/11/06 06:52:29 INFO Upload complete. (267ms)1340=== NAME TestClientWithDependencies1341 client_integration_test.go:664: Skipping nix copy test - isolated store (/private/var/tb/5/scratch/87d7ae187515016b/build/TestClientWithDependencies2377672433/001/store) requires matching store prefix1342--- PASS: TestClientWithDependencies (7.78s)1343=== CONT TestReadProxyInvalidPath13442026/11/06 06:52:30 INFO Received uploads request method=POST path=/api/pending_closures13452026/11/06 06:52:30 INFO Received uploads request method=POST path=/api/pending_closures13462026/11/06 06:52:30 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)1347=== NAME TestClientMultipleUploads1348 client_integration_test.go:405: Created store path 0: /private/var/tb/5/scratch/87d7ae187515016b/build/TestClientMultipleUploads1074026515/001/store/xqf1b8s6wh7lwaf4md1qi3nr053b1nd2-test-file-0.txt13492026/11/06 06:52:30 INFO Uploading zpsyw2dz1kdjgh459zpsdxgng2pxbkps-b (256B)13502026/11/06 06:52:30 INFO Uploading picsfzw2cqcrv2wsv37hz0lppdf6sybv-shared-dep (136B)13512026/11/06 06:52:30 WARN Failed to register uploaded object key=lk5ad47q9987n45b0yiki89kxim5npcv.ls error="server returned 404: 404 page not found\n"13522026/11/06 06:52:30 WARN Failed to register uploaded object key=zpsyw2dz1kdjgh459zpsdxgng2pxbkps.ls error="server returned 404: 404 page not found\n"13532026/11/06 06:52:30 WARN Failed to register uploaded object key=nar/0x3s5f4fisczm5kc46w8i8639xiva93l25vqkkb8iwica5vpsvpz.nar.zst error="server returned 404: 404 page not found\n"13542026/11/06 06:52:30 WARN Failed to register uploaded object key=picsfzw2cqcrv2wsv37hz0lppdf6sybv.ls error="server returned 404: 404 page not found\n"13552026/11/06 06:52:30 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"13562026/11/06 06:52:30 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign13572026/11/06 06:52:30 INFO Signed narinfos id=2 count=213582026/11/06 06:52:30 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign13592026/11/06 06:52:30 INFO Signed narinfos id=1 count=213602026/11/06 06:52:30 INFO Uploading 4 narinfos1361 client_integration_test.go:405: Created store path 1: /private/var/tb/5/scratch/87d7ae187515016b/build/TestClientMultipleUploads1074026515/001/store/8xy56z2jwjg20aj4zg0q2fyazd85450i-test-file-1.txt13622026/11/06 06:52:30 WARN Failed to register uploaded object key=lk5ad47q9987n45b0yiki89kxim5npcv.narinfo error="server returned 404: 404 page not found\n"13632026/11/06 06:52:30 WARN Failed to register uploaded object key=picsfzw2cqcrv2wsv37hz0lppdf6sybv.narinfo error="server returned 404: 404 page not found\n"13642026/11/06 06:52:30 WARN Failed to register uploaded object key=zpsyw2dz1kdjgh459zpsdxgng2pxbkps.narinfo error="server returned 404: 404 page not found\n"13652026/11/06 06:52:30 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete13662026/11/06 06:52:30 WARN Failed to register uploaded object key=picsfzw2cqcrv2wsv37hz0lppdf6sybv.narinfo error="server returned 404: 404 page not found\n"1367 client_integration_test.go:405: Created store path 2: /private/var/tb/5/scratch/87d7ae187515016b/build/TestClientMultipleUploads1074026515/001/store/lhhq5jwrm6j9rp1d8qmvhs6q2cdbw862-test-file-2.txt13682026/11/06 06:52:30 INFO Completed upload id=1 objects=6 duration=23.91775ms13692026/11/06 06:52:30 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete13702026/11/06 06:52:30 INFO Completed upload id=2 objects=6 duration=1.014584ms13712026/11/06 06:52:30 INFO Upload complete. (373ms)1372=== NAME TestClientFallsBackToClosures1373 client_pushes_test.go:112: Retrieved narinfo from S3:1374 StorePath: /private/var/tb/5/scratch/87d7ae187515016b/build/TestClientFallsBackToClosures412651533/001/store/picsfzw2cqcrv2wsv37hz0lppdf6sybv-shared-dep1375 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1376 Compression: zstd1377 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821378 NarSize: 1361379 References: 1380 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1381 client_pushes_test.go:112: Retrieved narinfo from S3:1382 StorePath: /private/var/tb/5/scratch/87d7ae187515016b/build/TestClientFallsBackToClosures412651533/001/store/lk5ad47q9987n45b0yiki89kxim5npcv-a1383 URL: nar/0x3s5f4fisczm5kc46w8i8639xiva93l25vqkkb8iwica5vpsvpz.nar.zst1384 Compression: zstd1385 NarHash: sha256:0x3s5f4fisczm5kc46w8i8639xiva93l25vqkkb8iwica5vpsvpz1386 NarSize: 2561387 References: /private/var/tb/5/scratch/87d7ae187515016b/build/TestClientFallsBackToClosures412651533/001/store/picsfzw2cqcrv2wsv37hz0lppdf6sybv-shared-dep1388 CA: text:sha256:1kasi53d0dk42m29qa75k5x4hvf75d1fl1fvizkq4fir6jakyz521389 client_pushes_test.go:112: Retrieved narinfo from S3:1390 StorePath: /private/var/tb/5/scratch/87d7ae187515016b/build/TestClientFallsBackToClosures412651533/001/store/zpsyw2dz1kdjgh459zpsdxgng2pxbkps-b1391 URL: nar/0x3s5f4fisczm5kc46w8i8639xiva93l25vqkkb8iwica5vpsvpz.nar.zst1392 Compression: zstd1393 NarHash: sha256:0x3s5f4fisczm5kc46w8i8639xiva93l25vqkkb8iwica5vpsvpz1394 NarSize: 2561395 References: /private/var/tb/5/scratch/87d7ae187515016b/build/TestClientFallsBackToClosures412651533/001/store/picsfzw2cqcrv2wsv37hz0lppdf6sybv-shared-dep1396 CA: text:sha256:1kasi53d0dk42m29qa75k5x4hvf75d1fl1fvizkq4fir6jakyz5213972026/11/06 06:52:30 INFO Received push request method=POST path=/api/pushes1398--- PASS: TestClientFallsBackToClosures (7.80s)1399=== CONT TestRedundantMultipartUpload1400=== NAME TestClientIntegration1401 client_integration_test.go:291: Created store path: /private/var/tb/5/scratch/87d7ae187515016b/build/TestClientIntegration4166851386/002/store/q9zajbz3n9d44bf9wzj8ga34r3s22dva-test-file.txt14022026/11/06 06:52:30 INFO Uploading 3 paths to 127.0.0.1 (0 already cached)14032026/11/06 06:52:30 INFO Uploading xqf1b8s6wh7lwaf4md1qi3nr053b1nd2-test-file-0.txt (160B)14042026/11/06 06:52:30 INFO Uploading lhhq5jwrm6j9rp1d8qmvhs6q2cdbw862-test-file-2.txt (160B)14052026/11/06 06:52:30 INFO Uploading 8xy56z2jwjg20aj4zg0q2fyazd85450i-test-file-1.txt (160B)1406--- PASS: TestService_ReadAuthMiddleware (7.18s)1407=== CONT TestReadProxy40414082026/11/06 06:52:30 WARN Failed to register uploaded object key=xqf1b8s6wh7lwaf4md1qi3nr053b1nd2.ls error="server returned 404: 404 page not found\n"14092026/11/06 06:52:30 INFO Received push request method=POST path=/api/pushes14102026/11/06 06:52:30 WARN Failed to register uploaded object key=lhhq5jwrm6j9rp1d8qmvhs6q2cdbw862.ls error="server returned 404: 404 page not found\n"14112026/11/06 06:52:30 WARN Failed to register uploaded object key=nar/1823g6vx4q5zqvr73m7lkq1wpk40fin7bsc792di430yk7sg4lka.nar.zst error="server returned 404: 404 page not found\n"14122026/11/06 06:52:30 WARN Failed to register uploaded object key=8xy56z2jwjg20aj4zg0q2fyazd85450i.ls error="server returned 404: 404 page not found\n"14132026/11/06 06:52:30 WARN Failed to register uploaded object key=nar/0ahq3izw3h0b0c08p3xdfclh758fwxnp85ccvflasb4vnfsv50ri.nar.zst error="server returned 404: 404 page not found\n"14142026/11/06 06:52:30 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign14152026/11/06 06:52:30 WARN Failed to register uploaded object key=nar/13p9pqi0ga6fx2apcwls9hjnv7nmf740ggpn5zvfzdsp5vz2bbg4.nar.zst error="server returned 404: 404 page not found\n"14162026/11/06 06:52:30 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=014172026/11/06 06:52:30 INFO Signed narinfos id=1 count=314182026/11/06 06:52:30 INFO Uploading 3 narinfos1419=== NAME TestOrphanedObjectsGCStressTest1420 orphaned_objects_gc_test.go:422: Created 10 active closures, 5 to-delete closures, 20 orphaned chains14212026/11/06 06:52:30 INFO Received create pin request method=POST path=/api/pins/myapp14222026/11/06 06:52:30 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)14232026/11/06 06:52:30 INFO Uploading q9zajbz3n9d44bf9wzj8ga34r3s22dva-test-file.txt (152B)14242026/11/06 06:52:30 WARN Failed to register uploaded object key=lhhq5jwrm6j9rp1d8qmvhs6q2cdbw862.narinfo error="server returned 404: 404 page not found\n"14252026/11/06 06:52:30 WARN Failed to register uploaded object key=xqf1b8s6wh7lwaf4md1qi3nr053b1nd2.narinfo error="server returned 404: 404 page not found\n"14262026/11/06 06:52:30 INFO Received complete push request method=POST path=/api/pushes/1/complete14272026/11/06 06:52:30 WARN Failed to register uploaded object key=8xy56z2jwjg20aj4zg0q2fyazd85450i.narinfo error="server returned 404: 404 page not found\n"14282026/11/06 06:52:30 WARN Failed to register uploaded object key=q9zajbz3n9d44bf9wzj8ga34r3s22dva.ls error="server returned 404: 404 page not found\n"14292026/11/06 06:52:30 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign14302026/11/06 06:52:30 WARN Failed to register uploaded object key=nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst error="server returned 404: 404 page not found\n"14312026/11/06 06:52:30 INFO Signed narinfos id=1 count=114322026/11/06 06:52:30 INFO Uploading 1 narinfos1433 orphaned_objects_gc_test.go:440: Marked 210 objects for deletion14342026/11/06 06:52:30 INFO Created/updated pin name=myapp store_path=/private/var/tb/5/scratch/87d7ae187515016b/build/TestPinProtectsFromGC1601802468/001/store/1pnmba5lpmhlb5pnaximycl0f24b1ba3-pinned-file.txt narinfo_key=1pnmba5lpmhlb5pnaximycl0f24b1ba3.narinfo14352026/11/06 06:52:30 INFO Completed push id=1 objects=9 duration=39.597916ms14362026/11/06 06:52:30 INFO Upload complete. (307ms)1437=== NAME TestClientMultipleUploads1438 client_integration_test.go:416: Uploaded 3 paths in 347.913542ms14392026/11/06 06:52:30 INFO Starting cleanup of old closures method=DELETE path=/api/closures14402026/11/06 06:52:30 INFO Garbage collection started14412026/11/06 06:52:30 INFO Aborted multipart uploads count=0 kept=014422026/11/06 06:52:30 WARN Force mode enabled - objects will be deleted immediately without grace period14432026/11/06 06:52:30 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=014442026/11/06 06:52:30 INFO Vacuumed table table=pending_closures14452026/11/06 06:52:30 INFO Received complete push request method=POST path=/api/pushes/1/complete14462026/11/06 06:52:30 WARN Failed to register uploaded object key=q9zajbz3n9d44bf9wzj8ga34r3s22dva.narinfo error="server returned 404: 404 page not found\n"14472026/11/06 06:52:30 INFO Vacuumed table table=pending_objects14482026/11/06 06:52:30 INFO Vacuumed table table=multipart_uploads1449--- PASS: TestClientMultipleUploads (8.26s)1450=== CONT TestReadProxyNarStreaming14512026/11/06 06:52:30 INFO Completed push id=1 objects=3 duration=68.466333ms14522026/11/06 06:52:30 INFO Vacuumed table table=closures14532026/11/06 06:52:30 INFO Upload complete. (289ms)14542026/11/06 06:52:30 INFO Vacuumed table table=objects14552026/11/06 06:52:30 INFO All 1 paths already cached1456=== NAME TestClientIntegration1457 client_integration_test.go:317: Retrieved narinfo from S3:1458 StorePath: /private/var/tb/5/scratch/87d7ae187515016b/build/TestClientIntegration4166851386/002/store/q9zajbz3n9d44bf9wzj8ga34r3s22dva-test-file.txt1459 URL: nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst1460 Compression: zstd1461 NarHash: sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11462 NarSize: 1521463 References: 1464 CA: fixed:r:sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11465 client_integration_test.go:318: Retrieved .ls file from S3 (compressed size: 77 bytes)1466 client_integration_test.go:318: Decompressed .ls content (64 bytes):1467 {"version":1,"root":{"type":"regular","size":39,"narOffset":96}}1468--- PASS: TestService_AuthMiddleware_MTLSProxyHeader (6.75s)1469=== CONT TestParseSize1470--- PASS: TestParseSize (0.00s)1471=== CONT TestReadProxyContentNegotiation14722026/11/06 06:52:31 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted,O=Other"14732026/11/06 06:52:31 WARN mTLS auth: bound subjects configured but subject DN unavailable14742026/11/06 06:52:31 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted"1475--- PASS: TestService_AuthMiddleware_MTLSBoundSubjects (6.74s)1476=== CONT TestService_Rustfstest14772026/11/06 06:52:31 INFO Received push request method=POST path=/api/pushes14782026/11/06 06:52:31 INFO Object in database but missing from S3 key=q9zajbz3n9d44bf9wzj8ga34r3s22dva.ls14792026/11/06 06:52:31 WARN Found objects in DB but missing from S3, will re-upload count=114802026/11/06 06:52:31 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)14812026/11/06 06:52:31 INFO Received complete push request method=POST path=/api/pushes/2/complete14822026/11/06 06:52:31 WARN Failed to register uploaded object key=q9zajbz3n9d44bf9wzj8ga34r3s22dva.ls error="server returned 404: 404 page not found\n"14832026/11/06 06:52:31 INFO Completed push id=2 objects=3 duration=1.3375ms14842026/11/06 06:52:31 INFO Upload complete. (115ms)1485=== NAME TestClientIntegration1486 client_integration_test.go:335: Retrieved .ls file from S3 (compressed size: 62 bytes)1487 client_integration_test.go:335: Decompressed .ls content (49 bytes):1488 {"version":1,"root":{"type":"regular","size":39}}1489--- PASS: TestService_ReadScope_PublicByDefault (6.88s)1490=== CONT TestReadProxyNarinfoAlreadyDecompressed14912026/11/06 06:52:31 INFO Received push request method=POST path=/api/pushes14922026/11/06 06:52:31 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)14932026/11/06 06:52:31 INFO Received complete push request method=POST path=/api/pushes/3/complete14942026/11/06 06:52:31 WARN Failed to register uploaded object key=q9zajbz3n9d44bf9wzj8ga34r3s22dva.ls error="server returned 404: 404 page not found\n"14952026/11/06 06:52:31 INFO Completed push id=3 objects=3 duration=790.333µs14962026/11/06 06:52:31 INFO Upload complete. (136ms)1497=== NAME TestClientIntegration1498 client_integration_test.go:352: Retrieved .ls file from S3 (compressed size: 62 bytes)1499 client_integration_test.go:352: Decompressed .ls content (49 bytes):1500 {"version":1,"root":{"type":"regular","size":39}}1501 client_integration_test.go:363: Testing garbage collection...15022026/11/06 06:52:31 INFO Starting cleanup of old closures method=DELETE path=/api/closures15032026/11/06 06:52:31 INFO Garbage collection started15042026/11/06 06:52:31 INFO Aborted multipart uploads count=0 kept=015052026/11/06 06:52:31 WARN Force mode enabled - objects will be deleted immediately without grace period15062026/11/06 06:52:31 INFO Aborted multipart uploads count=1 kept=015072026/11/06 06:52:31 INFO Received cleanup request method=DELETE path=/api/pending_closures15082026/11/06 06:52:31 INFO Aborted multipart uploads count=1 kept=01509--- PASS: TestPendingCleanupUsesOneCutoff (13.45s)1510=== CONT TestPresignedUploadRegisteredBeforeCommit1511--- PASS: TestReadProxyRootRedirectsToIndexHTML (6.65s)1512=== CONT TestCompletedNarNotReofferedAcrossClosures15132026/11/06 06:52:32 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=015142026/11/06 06:52:32 INFO Received uploads request method=POST path=/api/pending_closures15152026/11/06 06:52:32 INFO Vacuumed table table=pending_closures15162026/11/06 06:52:32 INFO Vacuumed table table=pending_objects15172026/11/06 06:52:32 INFO Vacuumed table table=multipart_uploads15182026/11/06 06:52:32 INFO Vacuumed table table=closures1519--- PASS: TestCreatePendingClosure_SmallNARUsesSimplePUT (6.49s)1520=== CONT TestReadProxyNarinfo15212026/11/06 06:52:32 INFO Vacuumed table table=objects1522=== RUN TestService_AuthMiddleware_OIDC/valid_OIDC_token1523=== PAUSE TestService_AuthMiddleware_OIDC/valid_OIDC_token1524=== RUN TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1525=== PAUSE TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1526=== RUN TestService_AuthMiddleware_OIDC/malformed_token_rejected1527=== PAUSE TestService_AuthMiddleware_OIDC/malformed_token_rejected1528=== RUN TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1529=== PAUSE TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1530=== CONT TestCompleteMultipartUpload_ErrorButObjectExists1531=== NAME TestPinProtectsFromGC1532 client_integration_test.go:887: Pin successfully protected closure from garbage collection1533--- PASS: TestPinProtectsFromGC (12.32s)1534=== CONT TestIsValidCachePath1535=== RUN TestIsValidCachePath/narinfo1536=== PAUSE TestIsValidCachePath/narinfo1537=== RUN TestIsValidCachePath/narinfo_all_nix_base32_chars1538=== PAUSE TestIsValidCachePath/narinfo_all_nix_base32_chars1539=== RUN TestIsValidCachePath/nar_zst1540=== PAUSE TestIsValidCachePath/nar_zst1541=== RUN TestIsValidCachePath/nar_xz1542=== PAUSE TestIsValidCachePath/nar_xz1543=== RUN TestIsValidCachePath/nar_bz21544=== PAUSE TestIsValidCachePath/nar_bz21545=== RUN TestIsValidCachePath/nar_uncompressed1546=== PAUSE TestIsValidCachePath/nar_uncompressed1547=== RUN TestIsValidCachePath/ls1548=== PAUSE TestIsValidCachePath/ls1549=== RUN TestIsValidCachePath/log1550=== PAUSE TestIsValidCachePath/log1551=== RUN TestIsValidCachePath/realisation1552=== PAUSE TestIsValidCachePath/realisation1553=== RUN TestIsValidCachePath/nix-cache-info1554=== PAUSE TestIsValidCachePath/nix-cache-info1555=== RUN TestIsValidCachePath/index.html1556=== PAUSE TestIsValidCachePath/index.html1557=== RUN TestIsValidCachePath/traversal_parent1558=== PAUSE TestIsValidCachePath/traversal_parent1559=== RUN TestIsValidCachePath/traversal_in_middle1560=== PAUSE TestIsValidCachePath/traversal_in_middle1561=== RUN TestIsValidCachePath/invalid_char_e1562=== PAUSE TestIsValidCachePath/invalid_char_e1563=== RUN TestIsValidCachePath/invalid_char_u1564=== PAUSE TestIsValidCachePath/invalid_char_u1565=== RUN TestIsValidCachePath/random_path1566=== PAUSE TestIsValidCachePath/random_path1567=== RUN TestIsValidCachePath/empty1568=== PAUSE TestIsValidCachePath/empty1569=== RUN TestIsValidCachePath/leading_slash1570=== PAUSE TestIsValidCachePath/leading_slash1571=== RUN TestIsValidCachePath/wrong_extension1572=== PAUSE TestIsValidCachePath/wrong_extension1573=== RUN TestIsValidCachePath/short_hash1574=== PAUSE TestIsValidCachePath/short_hash1575=== CONT TestMetricsCommit15762026/11/06 06:52:33 INFO Received complete multipart upload request method=POST path=/api/multipart/complete15772026/11/06 06:52:33 ERROR Failed to get multipart upload error="no rows in result set" upload_id=does-not-exist object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst1578--- PASS: TestCompleteMultipartUnregistered (6.60s)1579=== CONT TestMetricsInventory1580=== RUN TestService_RequireScope_OIDC/builder_may_write1581=== PAUSE TestService_RequireScope_OIDC/builder_may_write1582=== RUN TestService_RequireScope_OIDC/builder_may_not_admin1583=== PAUSE TestService_RequireScope_OIDC/builder_may_not_admin1584=== RUN TestService_RequireScope_OIDC/ops_may_admin1585=== PAUSE TestService_RequireScope_OIDC/ops_may_admin1586=== RUN TestService_RequireScope_OIDC/ops_may_not_write1587=== PAUSE TestService_RequireScope_OIDC/ops_may_not_write1588=== RUN TestService_RequireScope_OIDC/reader_may_not_write1589=== PAUSE TestService_RequireScope_OIDC/reader_may_not_write1590=== RUN TestService_RequireScope_OIDC/static_token_may_admin1591=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin1592=== RUN TestService_RequireScope_OIDC/static_token_may_write1593=== PAUSE TestService_RequireScope_OIDC/static_token_may_write1594=== RUN TestService_RequireScope_OIDC/reader_may_read1595=== PAUSE TestService_RequireScope_OIDC/reader_may_read1596=== RUN TestService_RequireScope_OIDC/writer_implies_read1597=== PAUSE TestService_RequireScope_OIDC/writer_implies_read1598=== RUN TestService_RequireScope_OIDC/anonymous_may_not_read1599=== PAUSE TestService_RequireScope_OIDC/anonymous_may_not_read1600=== RUN TestService_RequireScope_OIDC/reader_may_read_with_netrc1601=== PAUSE TestService_RequireScope_OIDC/reader_may_read_with_netrc1602=== RUN TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1603=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1604=== RUN TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read1605=== PAUSE TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read1606=== RUN TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1607=== PAUSE TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1608=== CONT TestNARDeduplicationMetadataUploadBug16092026/11/06 06:52:33 INFO Received uploads request method=POST path=/api/pending_closures16102026/11/06 06:52:33 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=01611=== NAME TestClientIntegration1612 client_integration_test.go:370: Objects in database after GC:1613 client_integration_test.go:370: Successfully deleted all objects with GC --force1614--- PASS: TestClientIntegration (10.88s)1615=== CONT TestConnectWaitsForAPeerMigration1616--- PASS: TestDeleteClosuresRacingPins (11.86s)1617=== CONT TestService_NativeMTLS1618--- PASS: TestReadProxyConditionalGet (5.90s)1619=== CONT TestCommitRacingPendingCleanupKeepsObjects16202026/11/06 06:52:34 INFO Received uploads request method=POST path=/api/pending_closures16212026/11/06 06:52:34 INFO Received uploads request method=POST path=/api/pending_closures16222026/11/06 06:52:34 INFO Received uploads request method=POST path=/api/pending_closures16232026/11/06 06:52:35 INFO Received cleanup request method=DELETE path=/api/pending_closures16242026/11/06 06:52:35 INFO Aborted multipart uploads count=0 kept=016252026/11/06 06:52:35 INFO Received uploads request method=POST path=/api/pending_closures16262026/11/06 06:52:35 INFO Received cleanup request method=DELETE path=/api/pending_closures16272026/11/06 06:52:35 INFO Aborted multipart uploads count=1 kept=016282026/11/06 06:52:35 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete16292026-11-06 06:52:35.275 UTC [72903] ERROR: Closure does not exist: id=116302026-11-06 06:52:35.275 UTC [72903] CONTEXT: PL/pgSQL function commit_pending_closure(bigint) line 13 at RAISE16312026-11-06 06:52:35.275 UTC [72903] STATEMENT: -- name: CommitPendingClosure :one1632 SELECT commit_pending_closure($1::bigint)::bigint1633 1634--- PASS: TestService_cleanupPendingClosuresHandler (6.12s)1635=== CONT TestPushWaitsForSweepHoldingRow16362026/11/06 06:52:35 INFO Received uploads request method=POST path=/api/pending_closures16372026/11/06 06:52:36 INFO Received complete multipart upload request method=POST path=/api/multipart/complete16382026/11/06 06:52:36 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst upload_id=NWJiOTg2ZjctM2QzNS00YzUzLThmM2MtMmNjMzYwZDg1NjJkLjE2OWJhNmY0LTA4ODMtNDViYy04Y2RhLTg2OWYzM2YwNTFmOXgxNzkzOTQ3OTUzODMzMzMyMDAw parts=1016392026/11/06 06:52:36 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete16402026/11/06 06:52:36 INFO Completed upload id=1 objects=2 duration=51.821708ms16412026/11/06 06:52:36 INFO Received uploads request method=POST path=/api/pending_closures16422026/11/06 06:52:36 INFO Received uploads request method=POST path=/api/pending_closures16432026/11/06 06:52:36 INFO Object in database but missing from S3 key=dadb44fdadb44fdadb44fdadb44f0000.narinfo16442026/11/06 06:52:36 WARN Found objects in DB but missing from S3, will re-upload count=11645--- PASS: TestService_verifyS3Integrity (9.23s)1646=== CONT TestSweepRechecksPendingAfterLocking1647--- PASS: TestReadProxyHead (6.95s)1648=== CONT TestGetExistingObjectsLocksRows16492026/11/06 06:52:36 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1650--- PASS: TestReadProxyInvalidPath (7.01s)1651=== CONT TestCreatePendingClosureRejectsOversizedNAR16522026/11/06 06:52:36 INFO Received uploads request method=POST path=/api/pending_closures1653--- PASS: TestCreatePendingClosureRejectsOversizedNAR (0.00s)1654=== CONT TestRegisterCompletedObjectNeedsPendingRow16552026/11/06 06:52:36 INFO Received complete multipart upload request method=POST path=/api/multipart/complete16562026/11/06 06:52:37 INFO Completed multipart upload object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst upload_id=NWJiOTg2ZjctM2QzNS00YzUzLThmM2MtMmNjMzYwZDg1NjJkLjQwNjFmMmM0LTFiZGItNGJiYi04MjAxLTI1MjZjYjMxZWRiYXgxNzkzOTQ3OTU0NjYyODc4MDAw parts=1016572026/11/06 06:52:37 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete16582026/11/06 06:52:37 INFO Completed upload id=1 objects=2 duration=34.138541ms16592026/11/06 06:52:37 INFO Received get closure request method=GET path=/api/closures/0000000000000000000000000000000016602026/11/06 06:52:37 INFO Received uploads request method=POST path=/api/pending_closures16612026/11/06 06:52:37 INFO Starting cleanup of old closures method=DELETE path=/api/closures16622026/11/06 06:52:37 INFO Aborted multipart uploads count=0 kept=016632026/11/06 06:52:37 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=016642026/11/06 06:52:37 INFO Vacuumed table table=pending_closures16652026/11/06 06:52:37 INFO Received uploads request method=POST path=/api/pending_closures16662026/11/06 06:52:37 INFO Vacuumed table table=pending_objects16672026/11/06 06:52:37 INFO Vacuumed table table=multipart_uploads16682026/11/06 06:52:37 INFO Vacuumed table table=closures16692026/11/06 06:52:37 INFO Vacuumed table table=objects16702026/11/06 06:52:37 INFO Received get closure request method=GET path=/api/closures/0000000000000000000000000000000016712026/11/06 06:52:37 INFO Received uploads request method=POST path=/api/pending_closures1672--- PASS: TestService_createPendingClosureHandler (9.27s)1673=== CONT TestCacheConfigHandlerMaxNarSize1674--- PASS: TestCacheConfigHandlerMaxNarSize (0.00s)1675=== CONT TestGenerateLandingPage1676--- PASS: TestGenerateLandingPage (0.00s)1677=== CONT TestService_readinessHandler1678--- PASS: TestReadProxyContentNegotiation (7.81s)1679=== CONT TestSweepSkipsRowsLockedByPush1680--- PASS: TestReadProxy404 (8.22s)1681=== CONT TestFailedS3DeleteKeepsTombstone1682--- PASS: TestReadProxyNarStreaming (8.08s)1683=== CONT TestForceGCDuringPushOffersSweptObject1684=== RUN TestForceGCDuringPushOffersSweptObject/before_pending_rows1685=== PAUSE TestForceGCDuringPushOffersSweptObject/before_pending_rows1686=== RUN TestForceGCDuringPushOffersSweptObject/after_presence_check1687=== PAUSE TestForceGCDuringPushOffersSweptObject/after_presence_check1688=== CONT TestCreatePendingClosureVerifyS3FailureReleasesConnection1689--- PASS: TestService_Rustfstest (7.96s)1690=== CONT TestParseSingleRange1691=== RUN TestParseSingleRange/none1692=== PAUSE TestParseSingleRange/none1693=== RUN TestParseSingleRange/unknown_unit1694=== PAUSE TestParseSingleRange/unknown_unit1695=== RUN TestParseSingleRange/multi-range_ignored1696=== PAUSE TestParseSingleRange/multi-range_ignored1697=== RUN TestParseSingleRange/malformed_no_dash1698=== PAUSE TestParseSingleRange/malformed_no_dash1699=== RUN TestParseSingleRange/malformed_both_empty1700=== PAUSE TestParseSingleRange/malformed_both_empty1701=== RUN TestParseSingleRange/malformed_end_before_start1702=== PAUSE TestParseSingleRange/malformed_end_before_start1703=== RUN TestParseSingleRange/closed1704=== PAUSE TestParseSingleRange/closed1705=== RUN TestParseSingleRange/open-ended1706=== PAUSE TestParseSingleRange/open-ended1707=== RUN TestParseSingleRange/end_clamped_to_size1708=== PAUSE TestParseSingleRange/end_clamped_to_size1709=== RUN TestParseSingleRange/suffix1710=== PAUSE TestParseSingleRange/suffix1711=== RUN TestParseSingleRange/suffix_exceeds_size1712=== PAUSE TestParseSingleRange/suffix_exceeds_size1713=== RUN TestParseSingleRange/single_byte1714=== PAUSE TestParseSingleRange/single_byte1715=== RUN TestParseSingleRange/start_past_EOF1716=== PAUSE TestParseSingleRange/start_past_EOF1717=== RUN TestParseSingleRange/start_far_past_EOF1718=== PAUSE TestParseSingleRange/start_far_past_EOF1719=== CONT TestPresentNotReportedWhileGCDeletesClosure1720=== RUN TestPresentNotReportedWhileGCDeletesClosure/stale1721=== PAUSE TestPresentNotReportedWhileGCDeletesClosure/stale1722=== RUN TestPresentNotReportedWhileGCDeletesClosure/fresh1723=== PAUSE TestPresentNotReportedWhileGCDeletesClosure/fresh1724=== CONT TestGCSweepDeliversEachKeyOnce1725--- PASS: TestReadProxyNarinfoAlreadyDecompressed (8.23s)1726=== CONT TestGCEndsOnShutdown/before_the_run1727--- PASS: TestReadProxyOutlastsServerWriteTimeout (10.34s)1728=== CONT TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark17292026/11/06 06:52:40 INFO Received complete multipart upload request method=POST path=/api/multipart/complete17302026/11/06 06:52:40 INFO Received uploads request method=POST path=/api/pending_closures17312026/11/06 06:52:40 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=NWJiOTg2ZjctM2QzNS00YzUzLThmM2MtMmNjMzYwZDg1NjJkLmM1MmExY2Y3LTY5OTItNGEzYy05NmM2LWRlZjEyNTMzYzU1MXgxNzkzOTQ3OTU3NTMwMzQ2MDAw parts=1217322026/11/06 06:52:40 INFO Received uploads request method=POST path=/api/pending_closures17332026/11/06 06:52:40 INFO Registered completed upload object_key=nar/jjjjjjjjjjjjjjjjjjjjjjjjjjjjjj0100000000000000000000.nar.zst17342026/11/06 06:52:40 INFO Received uploads request method=POST path=/api/pending_closures1735--- PASS: TestPresignedUploadRegisteredBeforeCommit (8.38s)1736=== CONT TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete17372026/11/06 06:52:40 WARN Rate limiter enabled after throttle name=s3-test rate=517382026/11/06 06:52:40 WARN S3 rate limit hit operation="complete multipart upload" error="Please reduce your request rate."1739=== NAME TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle1740 throttle_test.go:213: Proxy stats: total=13, throttled=10, completeMultipart=101741 throttle_test.go:215: Rate limiter: enabled=true, rate=5.001742--- PASS: TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle (10.65s)1743=== CONT TestPush_RejectsBadRequests/no_roots17442026/11/06 06:52:40 INFO Received push request method=POST path=/api/pushes1745=== CONT TestPush_RejectsBadRequests/bad_root17462026/11/06 06:52:40 INFO Received push request method=POST path=/api/pushes1747=== CONT TestPush_RejectsBadRequests/root_not_in_objects17482026/11/06 06:52:40 INFO Received uploads request method=POST path=/api/pending_closures17492026/11/06 06:52:40 INFO Received push request method=POST path=/api/pushes1750=== CONT TestPush_RejectsBadRequests/no_objects17512026/11/06 06:52:40 INFO Received push request method=POST path=/api/pushes1752=== CONT TestServerTLSConfig/no_client_CA1753=== CONT TestServerTLSConfig/not_a_PEM_file1754--- PASS: TestPush_RejectsBadRequests (2.22s)1755 --- PASS: TestPush_RejectsBadRequests/no_roots (0.00s)1756 --- PASS: TestPush_RejectsBadRequests/bad_root (0.00s)1757 --- PASS: TestPush_RejectsBadRequests/root_not_in_objects (0.01s)1758 --- PASS: TestPush_RejectsBadRequests/no_objects (0.00s)1759=== CONT TestServerTLSConfig/missing_CA_file1760--- PASS: TestServerTLSConfig (0.00s)1761 --- PASS: TestServerTLSConfig/no_client_CA (0.00s)1762 --- PASS: TestServerTLSConfig/not_a_PEM_file (0.05s)1763 --- PASS: TestServerTLSConfig/missing_CA_file (0.00s)1764=== CONT TestClientErrorHandling/InvalidStorePath17652026/11/06 06:52:40 INFO Received uploads request method=POST path=/api/pending_closures17662026/11/06 06:52:41 ERROR Failed to decode narinfo key=3hcdxyjf9yiq7qf3i4548drb6sjmwa1v.narinfo limit=16777216 error=<nil>1767--- PASS: TestReadProxyNarinfo (8.90s)1768=== CONT TestClientErrorHandling/ServerNotAvailable17692026/11/06 06:52:41 INFO Received uploads request method=POST path=/api/pending_closures17702026/11/06 06:52:42 INFO Received complete multipart upload request method=POST path=/api/multipart/complete17712026/11/06 06:52:42 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified key does not exist." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=NWJiOTg2ZjctM2QzNS00YzUzLThmM2MtMmNjMzYwZDg1NjJkLjlkNmMwYzNjLTQyNDItNDhkOC1iMTI3LWQ0M2RjZmVlYjIxY3gxNzkzOTQ3OTYxNjc1OTU3MDAw17722026/11/06 06:52:42 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/present17732026/11/06 06:52:42 INFO Received push request method=POST path=/api/pushes17742026/11/06 06:52:42 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=NWJiOTg2ZjctM2QzNS00YzUzLThmM2MtMmNjMzYwZDg1NjJkLjlkNmMwYzNjLTQyNDItNDhkOC1iMTI3LWQ0M2RjZmVlYjIxY3gxNzkzOTQ3OTYxNjc1OTU3MDAw parts=11775--- PASS: TestCompleteMultipartUpload_ErrorButObjectExists (9.51s)1776=== CONT TestClientErrorHandling/InvalidAuthToken17772026/11/06 06:52:42 INFO Received complete push request method=POST path=/api/pushes/1/complete17782026/11/06 06:52:42 WARN Request failed, retrying attempt=2 backoff=219.738721ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present17792026/11/06 06:52:42 INFO Completed push id=1 objects=4 duration=62.707334ms17802026/11/06 06:52:42 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete17812026/11/06 06:52:42 INFO Completed upload id=2 objects=2 duration=561.458µs1782--- PASS: TestMetricsCommit (9.48s)1783=== CONT TestResolveDBConnectionString/flag_wins1784=== CONT TestResolveDBConnectionString/PGHOST_allows_empty1785=== CONT TestResolveDBConnectionString/nothing_configured1786=== CONT TestResolveDBConnectionString/missing_file_is_an_error1787=== CONT TestResolveDBConnectionString/file_when_flag_empty1788=== CONT TestCacheConfigHandler/full_config,_no_issuer1789=== CONT TestCacheConfigHandler/no_signing_keys1790=== CONT TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1791=== CONT TestCacheConfigHandler/no_cache_url_configured1792--- PASS: TestResolveDBConnectionString (0.02s)1793 --- PASS: TestResolveDBConnectionString/flag_wins (0.00s)1794 --- PASS: TestResolveDBConnectionString/PGHOST_allows_empty (0.00s)1795 --- PASS: TestResolveDBConnectionString/nothing_configured (0.00s)1796 --- PASS: TestResolveDBConnectionString/missing_file_is_an_error (0.00s)1797 --- PASS: TestResolveDBConnectionString/file_when_flag_empty (0.00s)1798--- PASS: TestCacheConfigHandler (0.01s)1799 --- PASS: TestCacheConfigHandler/full_config,_no_issuer (0.00s)1800 --- PASS: TestCacheConfigHandler/no_signing_keys (0.00s)1801 --- PASS: TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator (0.00s)1802 --- PASS: TestCacheConfigHandler/no_cache_url_configured (0.00s)1803=== CONT TestService_verifyS3ReuploadsStaleNarinfo/lost,_other_NAR_pushed18042026/11/06 06:52:42 WARN Request failed, retrying attempt=3 backoff=364.582252ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present1805--- PASS: TestMetricsInventory (9.63s)1806=== CONT TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost,_second_pushed18072026/11/06 06:52:42 WARN Request failed, retrying attempt=4 backoff=782.697026ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present18082026/11/06 06:52:42 INFO Received complete multipart upload request method=POST path=/api/multipart/complete18092026/11/06 06:52:43 WARN Failed to abort redundant multipart upload, keeping its row object_key=nar/gggggggggggggggggggggggggggggg0200000000000000000000.nar.zst upload_id=NWJiOTg2ZjctM2QzNS00YzUzLThmM2MtMmNjMzYwZDg1NjJkLmI1NzFjNGE3LTA5MWItNDI3My1iZTI2LTYwN2E3NTgyYTY1N3gxNzkzOTQ3OTYwMzIzNTc2MDAw error="Get \"http://127.0.0.1:1/bucket67/?location=\": dial tcp 127.0.0.1:1: connect: connection refused"18102026/11/06 06:52:43 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0200000000000000000000.nar.zst upload_id=NWJiOTg2ZjctM2QzNS00YzUzLThmM2MtMmNjMzYwZDg1NjJkLjE2ZDQ2NjlmLWI1NmYtNGM2Ni05OTM0LWExNWQ0NzAyN2I5N3gxNzkzOTQ3OTYwMjYzNDM2MDAw parts=1218112026/11/06 06:52:43 INFO Received cleanup request method=DELETE path=/api/pending_closures18122026/11/06 06:52:43 INFO Aborted multipart uploads count=1 kept=01813--- PASS: TestRedundantMultipartUpload (12.72s)1814=== CONT TestService_verifyS3ReuploadsStaleNarinfo/lost,_same_NAR_pushed18152026/11/06 06:52:43 INFO Received complete multipart upload request method=POST path=/api/multipart/complete18162026/11/06 06:52:43 INFO Completed multipart upload object_key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhh0100000000000000000000.nar.zst upload_id=NWJiOTg2ZjctM2QzNS00YzUzLThmM2MtMmNjMzYwZDg1NjJkLjk3NGY2ZjI1LTdlMTEtNDBiNi1iYTExLWY4NDUxMmIyOWVjY3gxNzkzOTQ3OTYwNjY5NzMxMDAw parts=1218172026/11/06 06:52:43 INFO Received uploads request method=POST path=/api/pending_closures1818--- PASS: TestCompletedNarNotReofferedAcrossClosures (11.64s)1819=== CONT TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost18202026/11/06 06:52:43 WARN Request failed, retrying attempt=5 backoff=1.626680323s error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present1821=== NAME TestNARDeduplicationMetadataUploadBug1822 metadata_upload_test.go:48: First store path: /private/var/tb/5/scratch/87d7ae187515016b/build/TestNARDeduplicationMetadataUploadBug3182711822/001/store/xfh7vfv2pv12qmy439qmzdywza77ikcp-file1.txt18232026/11/06 06:52:43 INFO Aborted multipart uploads count=0 kept=018242026/11/06 06:52:43 WARN Force mode enabled - objects will be deleted immediately without grace period18252026/11/06 06:52:43 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=018262026/11/06 06:52:43 INFO Received push request method=POST path=/api/pushes18272026/11/06 06:52:43 INFO Vacuumed table table=pending_closures18282026/11/06 06:52:43 INFO Vacuumed table table=pending_objects18292026/11/06 06:52:43 INFO Vacuumed table table=multipart_uploads18302026/11/06 06:52:43 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)18312026/11/06 06:52:43 INFO Uploading xfh7vfv2pv12qmy439qmzdywza77ikcp-file1.txt (160B)18322026/11/06 06:52:43 INFO Vacuumed table table=closures18332026/11/06 06:52:43 INFO Vacuumed table table=objects1834--- PASS: TestConnectWaitsForAPeerMigration (10.00s)1835=== CONT TestService_verifyS3ReuploadsStaleNarinfo/intact,_other_NAR_pushed18362026/11/06 06:52:43 WARN mTLS auth: subject not in bound subjects subject="CN=reader"18372026/11/06 06:52:43 WARN mTLS auth: subject not in bound subjects subject="CN=reader"1838--- PASS: TestService_NativeMTLS (9.73s)1839=== CONT TestUploadHandlersRejectOversizedBody/create_pending_closure18402026/11/06 06:52:43 INFO Received uploads request method=POST path=/1841--- PASS: TestCommitRacingPendingCleanupKeepsObjects (9.72s)1842=== CONT TestUploadHandlersRejectOversizedBody/request_more_parts18432026/11/06 06:52:43 INFO Received request for more parts method=POST path=/18442026/11/06 06:52:43 WARN Failed to register uploaded object key=xfh7vfv2pv12qmy439qmzdywza77ikcp.ls error="server returned 404: 404 page not found\n"18452026/11/06 06:52:43 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign1846=== CONT TestUploadHandlersRejectOversizedBody/complete_multipart18472026/11/06 06:52:43 WARN Failed to register uploaded object key=nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst error="server returned 404: 404 page not found\n"18482026/11/06 06:52:43 INFO Signed narinfos id=1 count=118492026/11/06 06:52:43 INFO Received complete multipart upload request method=POST path=/18502026/11/06 06:52:43 INFO Uploading 1 narinfos1851=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info18522026/11/06 06:52:44 INFO Received uploads request method=POST path=/1853=== CONT TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key18542026/11/06 06:52:44 INFO Received complete multipart upload request method=POST path=/1855=== CONT TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key18562026/11/06 06:52:44 INFO Received request for more parts method=POST path=/1857=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal18582026/11/06 06:52:44 INFO Received uploads request method=POST path=/1859--- PASS: TestUploadHandlersRejectInvalidKeys (0.01s)1860 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info (0.01s)1861 --- PASS: TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key (0.01s)1862 --- PASS: TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key (0.00s)1863 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal (0.00s)1864=== CONT TestIsValidUploadKey/narinfo1865=== CONT TestIsValidUploadKey/realisation_plus_in_output1866=== CONT TestIsValidUploadKey/unknown_type1867=== CONT TestIsValidUploadKey/empty_key1868=== CONT TestIsValidUploadKey/absolute1869=== CONT TestIsValidUploadKey/traversal_nar1870=== CONT TestIsValidUploadKey/traversal1871=== CONT TestIsValidUploadKey/listing_key,_narinfo_type1872=== CONT TestIsValidUploadKey/nar_key,_narinfo_type1873=== CONT TestIsValidUploadKey/narinfo_key,_nar_type1874=== CONT TestIsValidUploadKey/index.html1875=== CONT TestIsValidUploadKey/nix-cache-info1876=== CONT TestIsValidUploadKey/build_log_home-manager_file1877=== CONT TestIsValidUploadKey/realisation1878=== CONT TestIsValidUploadKey/build_log_equals1879=== CONT TestIsValidUploadKey/build_log_question_mark1880=== CONT TestIsValidUploadKey/build_log_plus_in_name1881=== CONT TestIsValidUploadKey/nar_plain1882=== CONT TestIsValidUploadKey/build_log1883=== CONT TestIsValidUploadKey/listing1884=== CONT TestIsValidUploadKey/nar_xz1885=== CONT TestIsValidUploadKey/nar_zst1886--- PASS: TestIsValidUploadKey (0.03s)1887 --- PASS: TestIsValidUploadKey/narinfo (0.00s)1888 --- PASS: TestIsValidUploadKey/realisation_plus_in_output (0.00s)1889 --- PASS: TestIsValidUploadKey/unknown_type (0.00s)1890 --- PASS: TestIsValidUploadKey/empty_key (0.00s)1891 --- PASS: TestIsValidUploadKey/absolute (0.00s)1892 --- PASS: TestIsValidUploadKey/traversal_nar (0.00s)1893 --- PASS: TestIsValidUploadKey/traversal (0.00s)1894 --- PASS: TestIsValidUploadKey/listing_key,_narinfo_type (0.00s)1895 --- PASS: TestIsValidUploadKey/nar_key,_narinfo_type (0.00s)1896 --- PASS: TestIsValidUploadKey/narinfo_key,_nar_type (0.00s)1897 --- PASS: TestIsValidUploadKey/index.html (0.00s)1898 --- PASS: TestIsValidUploadKey/nix-cache-info (0.00s)1899 --- PASS: TestIsValidUploadKey/build_log_home-manager_file (0.00s)1900 --- PASS: TestIsValidUploadKey/realisation (0.00s)1901 --- PASS: TestIsValidUploadKey/build_log_equals (0.00s)1902 --- PASS: TestIsValidUploadKey/build_log_question_mark (0.00s)1903 --- PASS: TestIsValidUploadKey/build_log_plus_in_name (0.00s)1904 --- PASS: TestIsValidUploadKey/nar_plain (0.00s)1905 --- PASS: TestIsValidUploadKey/build_log (0.00s)1906 --- PASS: TestIsValidUploadKey/listing (0.00s)1907 --- PASS: TestIsValidUploadKey/nar_xz (0.00s)1908 --- PASS: TestIsValidUploadKey/nar_zst (0.00s)1909=== CONT TestPendingClosureWriteTimeout/empty1910=== CONT TestPendingClosureWriteTimeout/670k_objects1911=== CONT TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline19122026/11/06 06:52:44 INFO Received complete push request method=POST path=/api/pushes/1/complete19132026/11/06 06:52:44 WARN Failed to register uploaded object key=xfh7vfv2pv12qmy439qmzdywza77ikcp.narinfo error="server returned 404: 404 page not found\n"19142026/11/06 06:52:44 INFO Completed push id=1 objects=3 duration=41.314166ms19152026/11/06 06:52:44 INFO Upload complete. (354ms)1916=== NAME TestNARDeduplicationMetadataUploadBug1917 metadata_upload_test.go:54: Retrieved narinfo from S3:1918 StorePath: /private/var/tb/5/scratch/87d7ae187515016b/build/TestNARDeduplicationMetadataUploadBug3182711822/001/store/xfh7vfv2pv12qmy439qmzdywza77ikcp-file1.txt1919 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1920 Compression: zstd1921 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1922 NarSize: 1601923 References: 1924 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1925 metadata_upload_test.go:55: Retrieved .ls file from S3 (compressed size: 77 bytes)1926 metadata_upload_test.go:55: Decompressed .ls content (64 bytes):1927 {"version":1,"root":{"type":"regular","size":44,"narOffset":96}}1928 metadata_upload_test.go:64: Second store path (same content): /private/var/tb/5/scratch/87d7ae187515016b/build/TestNARDeduplicationMetadataUploadBug3182711822/001/store/d0nh4yzn1kfdj8anvqagdlfdl1nnqkh1-file2.txt19292026/11/06 06:52:44 INFO Received push request method=POST path=/api/pushes19302026/11/06 06:52:44 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)19312026/11/06 06:52:44 INFO Received uploads request method=POST path=/api/pending_closures19322026/11/06 06:52:44 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign19332026/11/06 06:52:44 WARN Failed to register uploaded object key=d0nh4yzn1kfdj8anvqagdlfdl1nnqkh1.ls error="server returned 404: 404 page not found\n"19342026/11/06 06:52:44 INFO Signed narinfos id=2 count=119352026/11/06 06:52:44 INFO Uploading 1 narinfos1936--- PASS: TestUploadHandlersRejectOversizedBody (0.10s)1937 --- PASS: TestUploadHandlersRejectOversizedBody/request_more_parts (0.03s)1938 --- PASS: TestUploadHandlersRejectOversizedBody/complete_multipart (0.02s)1939 --- PASS: TestUploadHandlersRejectOversizedBody/create_pending_closure (0.42s)1940=== CONT TestPendingClosureWriteTimeout/400_objects1941=== CONT TestProxyWriteTimeout/narinfo1942=== CONT TestProxyWriteTimeout/10_GiB_nar1943=== CONT TestProxyWriteTimeout/unknown_size1944=== CONT TestProxyWriteTimeout/1_GiB_nar1945--- PASS: TestProxyWriteTimeout (0.00s)1946 --- PASS: TestProxyWriteTimeout/narinfo (0.00s)1947 --- PASS: TestProxyWriteTimeout/10_GiB_nar (0.00s)1948 --- PASS: TestProxyWriteTimeout/unknown_size (0.00s)1949 --- PASS: TestProxyWriteTimeout/1_GiB_nar (0.00s)1950=== CONT TestService_AuthMiddleware_OIDC/valid_OIDC_token1951=== CONT TestService_AuthMiddleware_OIDC/malformed_token_rejected19522026/11/06 06:52:44 WARN Authentication failed token_preview=not-a-valid-jwt token_length=15 oidc_error="no provider could verify the token (signature or issuer mismatch)" oidc_provider="" tried_providers=[test]1953=== CONT TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1954=== CONT TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected19552026/11/06 06:52:44 INFO Received complete push request method=POST path=/api/pushes/2/complete19562026/11/06 06:52:44 WARN Failed to register uploaded object key=d0nh4yzn1kfdj8anvqagdlfdl1nnqkh1.narinfo error="server returned 404: 404 page not found\n"19572026/11/06 06:52:44 WARN Authentication failed token_preview=eyJhbGciOi...BQRQ9WMxtg token_length=701 oidc_error="no rule matched: claim \"repository_owner\" value [otherorg] not in allowed patterns [myorg]" oidc_provider=test tried_providers=[test]19582026/11/06 06:52:44 INFO Completed push id=2 objects=3 duration=783.375µs1959=== CONT TestIsValidCachePath/narinfo1960=== CONT TestIsValidCachePath/index.html1961=== CONT TestIsValidCachePath/short_hash1962=== CONT TestIsValidCachePath/wrong_extension1963=== CONT TestIsValidCachePath/leading_slash1964=== CONT TestIsValidCachePath/empty1965=== CONT TestIsValidCachePath/random_path1966=== CONT TestIsValidCachePath/invalid_char_u1967=== CONT TestIsValidCachePath/invalid_char_e1968=== CONT TestIsValidCachePath/traversal_in_middle1969=== CONT TestIsValidCachePath/traversal_parent1970=== CONT TestIsValidCachePath/nar_uncompressed1971=== CONT TestIsValidCachePath/nix-cache-info1972=== CONT TestIsValidCachePath/realisation1973=== CONT TestIsValidCachePath/log1974=== CONT TestIsValidCachePath/ls1975=== CONT TestIsValidCachePath/nar_xz19762026/11/06 06:52:44 INFO Upload complete. (156ms)1977=== CONT TestIsValidCachePath/nar_bz21978=== CONT TestIsValidCachePath/nar_zst1979=== CONT TestIsValidCachePath/narinfo_all_nix_base32_chars1980--- PASS: TestIsValidCachePath (0.00s)1981 --- PASS: TestIsValidCachePath/narinfo (0.00s)1982 --- PASS: TestIsValidCachePath/index.html (0.00s)1983 --- PASS: TestIsValidCachePath/short_hash (0.00s)1984 --- PASS: TestIsValidCachePath/wrong_extension (0.00s)1985 --- PASS: TestIsValidCachePath/leading_slash (0.00s)1986 --- PASS: TestIsValidCachePath/empty (0.00s)1987 --- PASS: TestIsValidCachePath/random_path (0.00s)1988 --- PASS: TestIsValidCachePath/invalid_char_u (0.00s)1989 --- PASS: TestIsValidCachePath/invalid_char_e (0.00s)1990 --- PASS: TestIsValidCachePath/traversal_in_middle (0.00s)1991 --- PASS: TestIsValidCachePath/traversal_parent (0.00s)1992 --- PASS: TestIsValidCachePath/nar_uncompressed (0.00s)1993 --- PASS: TestIsValidCachePath/nix-cache-info (0.00s)1994 --- PASS: TestIsValidCachePath/realisation (0.00s)1995 --- PASS: TestIsValidCachePath/log (0.00s)1996 --- PASS: TestIsValidCachePath/ls (0.00s)1997 --- PASS: TestIsValidCachePath/nar_xz (0.00s)1998 --- PASS: TestIsValidCachePath/nar_bz2 (0.00s)1999 --- PASS: TestIsValidCachePath/nar_zst (0.00s)2000 --- PASS: TestIsValidCachePath/narinfo_all_nix_base32_chars (0.00s)2001=== CONT TestService_RequireScope_OIDC/builder_may_write2002--- PASS: TestService_AuthMiddleware_OIDC (6.35s)2003 --- PASS: TestService_AuthMiddleware_OIDC/valid_OIDC_token (0.00s)2004 --- PASS: TestService_AuthMiddleware_OIDC/malformed_token_rejected (0.00s)2005 --- PASS: TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured (0.00s)2006 --- PASS: TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected (0.01s)2007=== CONT TestService_RequireScope_OIDC/reader_may_read2008=== CONT TestService_RequireScope_OIDC/empty_netrc_password_may_not_read2009=== CONT TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read20102026/11/06 06:52:44 WARN Authentication failed token_preview=wrong token_length=5 oidc_error="no provider could verify the token (signature or issuer mismatch)" oidc_provider="" tried_providers=[test]2011=== CONT TestService_RequireScope_OIDC/static_token_may_admin_with_netrc2012=== CONT TestService_RequireScope_OIDC/reader_may_read_with_netrc2013=== NAME TestNARDeduplicationMetadataUploadBug2014 metadata_upload_test.go:76: Retrieved narinfo from S3:2015 StorePath: /private/var/tb/5/scratch/87d7ae187515016b/build/TestNARDeduplicationMetadataUploadBug3182711822/001/store/d0nh4yzn1kfdj8anvqagdlfdl1nnqkh1-file2.txt2016 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst2017 Compression: zstd2018 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf2019 NarSize: 1602020 References: 2021 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf2022=== CONT TestService_RequireScope_OIDC/anonymous_may_not_read2023=== CONT TestService_RequireScope_OIDC/writer_implies_read2024=== NAME TestNARDeduplicationMetadataUploadBug2025 metadata_upload_test.go:77: Retrieved .ls file from S3 (compressed size: 62 bytes)2026 metadata_upload_test.go:77: Decompressed .ls content (49 bytes):2027 {"version":1,"root":{"type":"regular","size":44}}2028=== CONT TestService_RequireScope_OIDC/reader_may_not_write2029=== CONT TestService_RequireScope_OIDC/static_token_may_write2030=== CONT TestService_RequireScope_OIDC/static_token_may_admin2031=== CONT TestService_RequireScope_OIDC/ops_may_admin2032=== CONT TestService_RequireScope_OIDC/ops_may_not_write2033=== CONT TestService_RequireScope_OIDC/builder_may_not_admin2034=== CONT TestForceGCDuringPushOffersSweptObject/before_pending_rows2035--- PASS: TestService_RequireScope_OIDC (6.80s)2036 --- PASS: TestService_RequireScope_OIDC/builder_may_write (0.00s)2037 --- PASS: TestService_RequireScope_OIDC/reader_may_read (0.00s)2038 --- PASS: TestService_RequireScope_OIDC/empty_netrc_password_may_not_read (0.00s)2039 --- PASS: TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read (0.00s)2040 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin_with_netrc (0.00s)2041 --- PASS: TestService_RequireScope_OIDC/reader_may_read_with_netrc (0.00s)2042 --- PASS: TestService_RequireScope_OIDC/anonymous_may_not_read (0.00s)2043 --- PASS: TestService_RequireScope_OIDC/writer_implies_read (0.00s)2044 --- PASS: TestService_RequireScope_OIDC/reader_may_not_write (0.00s)2045 --- PASS: TestService_RequireScope_OIDC/static_token_may_write (0.00s)2046 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin (0.00s)2047 --- PASS: TestService_RequireScope_OIDC/ops_may_admin (0.00s)2048 --- PASS: TestService_RequireScope_OIDC/ops_may_not_write (0.00s)2049 --- PASS: TestService_RequireScope_OIDC/builder_may_not_admin (0.00s)2050--- PASS: TestNARDeduplicationMetadataUploadBug (11.07s)2051=== CONT TestForceGCDuringPushOffersSweptObject/after_presence_check20522026/11/06 06:52:44 INFO Aborted multipart uploads count=0 kept=020532026/11/06 06:52:44 WARN Force mode enabled - objects will be deleted immediately without grace period20542026/11/06 06:52:44 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=020552026/11/06 06:52:44 INFO Vacuumed table table=pending_closures2056--- PASS: TestPushWaitsForSweepHoldingRow (9.54s)2057=== CONT TestParseSingleRange/none2058=== CONT TestPresentNotReportedWhileGCDeletesClosure/stale20592026/11/06 06:52:44 INFO Vacuumed table table=pending_objects20602026/11/06 06:52:44 INFO Vacuumed table table=multipart_uploads20612026/11/06 06:52:44 INFO Vacuumed table table=closures20622026/11/06 06:52:44 INFO Vacuumed table table=objects2063--- PASS: TestSweepRechecksPendingAfterLocking (8.63s)2064=== CONT TestParseSingleRange/start_far_past_EOF2065=== CONT TestParseSingleRange/start_past_EOF2066=== CONT TestParseSingleRange/single_byte2067=== CONT TestParseSingleRange/suffix_exceeds_size2068=== CONT TestParseSingleRange/suffix2069=== CONT TestParseSingleRange/end_clamped_to_size2070=== CONT TestParseSingleRange/open-ended2071=== CONT TestParseSingleRange/closed2072=== CONT TestParseSingleRange/malformed_end_before_start2073=== CONT TestParseSingleRange/malformed_both_empty2074=== CONT TestParseSingleRange/malformed_no_dash2075=== CONT TestParseSingleRange/multi-range_ignored2076=== CONT TestParseSingleRange/unknown_unit2077--- PASS: TestParseSingleRange (0.02s)2078 --- PASS: TestParseSingleRange/none (0.00s)2079 --- PASS: TestParseSingleRange/start_far_past_EOF (0.00s)2080 --- PASS: TestParseSingleRange/start_past_EOF (0.00s)2081 --- PASS: TestParseSingleRange/single_byte (0.00s)2082 --- PASS: TestParseSingleRange/suffix_exceeds_size (0.00s)2083 --- PASS: TestParseSingleRange/suffix (0.00s)2084 --- PASS: TestParseSingleRange/end_clamped_to_size (0.00s)2085 --- PASS: TestParseSingleRange/open-ended (0.00s)2086 --- PASS: TestParseSingleRange/closed (0.00s)2087 --- PASS: TestParseSingleRange/malformed_end_before_start (0.00s)2088 --- PASS: TestParseSingleRange/malformed_both_empty (0.00s)2089 --- PASS: TestParseSingleRange/malformed_no_dash (0.00s)2090 --- PASS: TestParseSingleRange/multi-range_ignored (0.00s)2091 --- PASS: TestParseSingleRange/unknown_unit (0.00s)2092=== CONT TestPresentNotReportedWhileGCDeletesClosure/fresh2093--- PASS: TestGetExistingObjectsLocksRows (8.46s)20942026/11/06 06:52:45 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-config2095--- PASS: TestRegisterCompletedObjectNeedsPendingRow (8.38s)20962026/11/06 06:52:45 WARN Request failed, retrying attempt=2 backoff=198.981053ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config20972026/11/06 06:52:45 WARN Request failed, retrying attempt=3 backoff=393.232613ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config20982026/11/06 06:52:45 WARN readiness check failed error="closed pool"2099--- PASS: TestService_readinessHandler (8.02s)21002026/11/06 06:52:46 INFO Received uploads request method=POST path=/api/pending_closures21012026/11/06 06:52:46 WARN Request failed, retrying attempt=4 backoff=878.606566ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21022026/11/06 06:52:46 INFO Aborted multipart uploads count=0 kept=021032026/11/06 06:52:46 WARN Force mode enabled - objects will be deleted immediately without grace period21042026/11/06 06:52:46 ERROR failed to remove object object=nar/dddddddddddddddddddddddddddddddddddddddddddddddddddd.nar.zst error="Access Denied."21052026/11/06 06:52:46 ERROR failed to remove object object=dddddddddddddddddddddddddddddddd.narinfo error="Access Denied."2106--- PASS: TestFailedS3DeleteKeepsTombstone (7.71s)21072026/11/06 06:52:46 INFO Aborted multipart uploads count=0 kept=021082026/11/06 06:52:46 WARN Force mode enabled - objects will be deleted immediately without grace period21092026/11/06 06:52:46 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=021102026/11/06 06:52:46 INFO Vacuumed table table=pending_closures21112026/11/06 06:52:46 INFO Vacuumed table table=pending_objects21122026/11/06 06:52:46 INFO Vacuumed table table=multipart_uploads21132026/11/06 06:52:46 INFO Vacuumed table table=closures21142026/11/06 06:52:46 INFO Vacuumed table table=objects21152026/11/06 06:52:46 INFO Aborted multipart uploads count=0 kept=021162026/11/06 06:52:46 WARN Force mode enabled - objects will be deleted immediately without grace period21172026/11/06 06:52:46 INFO Received uploads request method=POST path=/api/pending_closures21182026/11/06 06:52:46 WARN Request failed, retrying attempt=5 backoff=1.525596335s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21192026/11/06 06:52:47 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=021202026/11/06 06:52:47 INFO Vacuumed table table=pending_closures21212026/11/06 06:52:47 INFO Vacuumed table table=pending_objects2122--- PASS: TestCreatePendingClosureVerifyS3FailureReleasesConnection (8.29s)21232026/11/06 06:52:47 INFO Vacuumed table table=multipart_uploads21242026/11/06 06:52:47 INFO Vacuumed table table=closures21252026/11/06 06:52:47 INFO Vacuumed table table=objects2126--- PASS: TestSweepSkipsRowsLockedByPush (8.54s)21272026/11/06 06:52:47 INFO Aborted multipart uploads count=0 kept=021282026/11/06 06:52:47 WARN Force mode enabled - objects will be deleted immediately without grace period21292026/11/06 06:52:48 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=021302026/11/06 06:52:48 INFO Vacuumed table table=pending_closures21312026/11/06 06:52:48 INFO Vacuumed table table=pending_objects21322026/11/06 06:52:48 INFO Vacuumed table table=multipart_uploads21332026/11/06 06:52:48 INFO Vacuumed table table=closures21342026/11/06 06:52:48 INFO Vacuumed table table=objects2135--- PASS: TestGCSweepDeliversEachKeyOnce (8.85s)21362026/11/06 06:52:48 INFO Aborted multipart uploads count=0 kept=021372026/11/06 06:52:48 WARN Force mode enabled - objects will be deleted immediately without grace period21382026-11-06 06:52:48.161 UTC [73057] ERROR: canceling statement due to user request21392026-11-06 06:52:48.161 UTC [73057] CONTEXT: SQL statement "UPDATE object_stats s2140 SET object_count = s.object_count + n.n - o.n,2141 total_bytes = s.total_bytes + n.bytes - o.bytes2142 FROM (2143 SELECT count(*) AS n, coalesce(sum(size), 0) AS bytes2144 FROM new_rows WHERE deleted_at IS NULL2145 ) AS n,2146 (2147 SELECT count(*) AS n, coalesce(sum(size), 0) AS bytes2148 FROM old_rows WHERE deleted_at IS NULL2149 ) AS o2150 WHERE s.id AND (n.n <> o.n OR n.bytes <> o.bytes)"2151 PL/pgSQL function object_stats_update() line 3 at SQL statement21522026-11-06 06:52:48.161 UTC [73057] STATEMENT: -- name: MarkStaleObjects :execrows2153 WITH RECURSIVE ct AS (2154 SELECT timezone('UTC', now()) AS now2155 ),2156 closure_reach AS (2157 -- Start with all closure keys2158 SELECT o.key, o.refs2159 FROM objects o2160 INNER JOIN closures c ON o.key = c.key2161 UNION2162 -- Recursively add all referenced objects2163 SELECT o.key, o.refs2164 FROM objects o2165 INNER JOIN closure_reach cr ON o.key = ANY(cr.refs)2166 ),2167 reachable_objects AS (2168 SELECT DISTINCT key FROM closure_reach2169 ),2170 stale_objects AS (2171 SELECT o.key2172 FROM objects AS o, ct2173 WHERE2174 NOT EXISTS (2175 SELECT 12176 FROM reachable_objects ro2177 WHERE ro.key = o.key2178 )2179 AND NOT EXISTS (2180 SELECT 12181 FROM pending_objects AS po2182 WHERE po.key = o.key2183 )2184 AND o.deleted_at IS NULL -- Only mark fresh objects2185 ORDER BY o.key COLLATE "C" -- lock in key order, like commit_pending_closure2186 FOR UPDATE2187 )2188 UPDATE objects2189 SET2190 deleted_at = ct.now,2191 first_deleted_at = COALESCE(first_deleted_at, ct.now)2192 FROM stale_objects, ct2193 WHERE objects.key = stale_objects.key2194 21952026/11/06 06:52:48 INFO Aborted multipart uploads count=0 kept=021962026/11/06 06:52:48 WARN Force mode enabled - objects will be deleted immediately without grace period21972026/11/06 06:52:48 ERROR failed to remove object object=nar/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa.nar.zst error="Post \"http://localhost:52138/bucket93/?delete=\": context canceled"2198--- PASS: TestGCEndsOnShutdown (0.00s)2199 --- PASS: TestGCEndsOnShutdown/before_the_run (8.04s)2200 --- PASS: TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark (8.30s)2201 --- PASS: TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete (8.06s)22022026/11/06 06:52:48 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"22032026/11/06 06:52:48 WARN Request failed, retrying attempt=1 backoff=100ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22042026/11/06 06:52:48 WARN Request failed, retrying attempt=2 backoff=182.558596ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22052026/11/06 06:52:48 WARN Request failed, retrying attempt=3 backoff=420.852905ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22062026/11/06 06:52:49 WARN Request failed, retrying attempt=4 backoff=864.507551ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22072026/11/06 06:52:49 INFO Received uploads request method=POST path=/api/pending_closures22082026/11/06 06:52:50 WARN Request failed, retrying attempt=5 backoff=1.541922808s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22092026/11/06 06:52:51 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"22102026/11/06 06:52:51 INFO Received uploads request method=POST path=/api/pending_closures22112026/11/06 06:52:51 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"22122026/11/06 06:52:51 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_closures22132026/11/06 06:52:51 WARN Request failed, retrying attempt=2 backoff=202.888874ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures22142026/11/06 06:52:51 WARN Request failed, retrying attempt=3 backoff=415.575746ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures22152026/11/06 06:52:52 INFO Received uploads request method=POST path=/api/pending_closures22162026/11/06 06:52:52 WARN Request failed, retrying attempt=4 backoff=868.803682ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures22172026/11/06 06:52:53 INFO Received uploads request method=POST path=/api/pending_closures22182026/11/06 06:52:53 WARN Request failed, retrying attempt=5 backoff=1.662372602s error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures2219=== NAME TestOrphanedObjectsGCStressTest2220 orphaned_objects_gc_test.go:503: Stress test completed successfully:2221 orphaned_objects_gc_test.go:504: - Active objects preserved: 202222 orphaned_objects_gc_test.go:505: - Objects deleted: 2102223 orphaned_objects_gc_test.go:506: - Total GC'd: 2102224--- PASS: TestOrphanedObjectsGCStressTest (37.75s)22252026/11/06 06:52:53 INFO Received complete multipart upload request method=POST path=/api/multipart/complete22262026/11/06 06:52:53 INFO Received uploads request method=POST path=/api/pending_closures22272026/11/06 06:52:53 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000100000000000000000000.nar.zst upload_id=NWJiOTg2ZjctM2QzNS00YzUzLThmM2MtMmNjMzYwZDg1NjJkLmUwZTEzYTU5LWNkZjMtNDY0My1iZmVkLTBmOGZkYjRmN2FjMHgxNzkzOTQ3OTY5NTE4OTgwMDAw parts=1022282026/11/06 06:52:53 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete22292026/11/06 06:52:53 INFO Completed upload id=1 objects=3 duration=10.467667ms22302026/11/06 06:52:53 INFO Received uploads request method=POST path=/api/pending_closures22312026/11/06 06:52:53 INFO Received uploads request method=POST path=/api/pending_closures22322026/11/06 06:52:53 INFO Object in database but missing from S3 key=nar/dadb44fdadb44fdadb44fdadb44f000100000000000000000000.nar.zst22332026/11/06 06:52:53 WARN Narinfo references a NAR missing from S3, will re-upload narinfo=dadb44fdadb44fdadb44fdadb44f0001.narinfo22342026/11/06 06:52:54 INFO Received complete multipart upload request method=POST path=/api/multipart/complete22352026/11/06 06:52:54 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000400000000000000000000.nar.zst upload_id=NWJiOTg2ZjctM2QzNS00YzUzLThmM2MtMmNjMzYwZDg1NjJkLmZhOGU1ZmMxLTg1YWYtNDg0ZC1hNjJmLWZiOWU2ZTRhYzYwM3gxNzkzOTQ3OTcxMjUyMzI4MDAw parts=1022362026/11/06 06:52:54 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete22372026/11/06 06:52:54 INFO Completed upload id=1 objects=3 duration=20.8805ms22382026/11/06 06:52:54 INFO Received uploads request method=POST path=/api/pending_closures22392026/11/06 06:52:54 INFO Received uploads request method=POST path=/api/pending_closures22402026/11/06 06:52:54 INFO Aborted multipart uploads count=0 kept=022412026/11/06 06:52:54 WARN Force mode enabled - objects will be deleted immediately without grace period22422026/11/06 06:52:54 INFO Received complete multipart upload request method=POST path=/api/multipart/complete22432026/11/06 06:52:54 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=1 objects-deleted-after-grace-period=1 objects-failed-to-delete=022442026/11/06 06:52:54 INFO Vacuumed table table=pending_closures22452026/11/06 06:52:54 INFO Vacuumed table table=pending_objects22462026/11/06 06:52:54 INFO Vacuumed table table=multipart_uploads22472026/11/06 06:52:54 INFO Vacuumed table table=closures22482026/11/06 06:52:54 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000500000000000000000000.nar.zst upload_id=NWJiOTg2ZjctM2QzNS00YzUzLThmM2MtMmNjMzYwZDg1NjJkLjE2NTU5ZDI1LWI3ZTgtNGMxOS1hOWRhLTZkN2MxNDljYTY3ZngxNzkzOTQ3OTcyMTczMDI1MDAw parts=1022492026/11/06 06:52:54 INFO Vacuumed table table=objects22502026/11/06 06:52:54 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete22512026/11/06 06:52:54 INFO Received uploads request method=POST path=/api/pending_closures22522026/11/06 06:52:54 INFO Completed upload id=1 objects=3 duration=9.200708ms22532026/11/06 06:52:54 INFO Aborted multipart uploads count=0 kept=022542026/11/06 06:52:54 WARN Force mode enabled - objects will be deleted immediately without grace period22552026/11/06 06:52:54 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=02256--- PASS: TestPendingClosureWriteTimeout (0.00s)2257 --- PASS: TestPendingClosureWriteTimeout/empty (0.00s)2258 --- PASS: TestPendingClosureWriteTimeout/670k_objects (0.00s)2259 --- PASS: TestPendingClosureWriteTimeout/400_objects (0.00s)2260 --- PASS: TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline (10.63s)22612026/11/06 06:52:54 INFO Vacuumed table table=pending_closures22622026/11/06 06:52:54 INFO Vacuumed table table=pending_objects22632026/11/06 06:52:54 INFO Vacuumed table table=multipart_uploads22642026/11/06 06:52:54 INFO Vacuumed table table=closures22652026/11/06 06:52:54 INFO Vacuumed table table=objects2266--- PASS: TestForceGCDuringPushOffersSweptObject (0.00s)2267 --- PASS: TestForceGCDuringPushOffersSweptObject/before_pending_rows (10.32s)2268 --- PASS: TestForceGCDuringPushOffersSweptObject/after_presence_check (10.35s)22692026/11/06 06:52:54 INFO Received complete multipart upload request method=POST path=/api/multipart/complete2270--- PASS: TestClientErrorHandling (0.00s)2271 --- PASS: TestClientErrorHandling/InvalidStorePath (8.30s)2272 --- PASS: TestClientErrorHandling/InvalidAuthToken (9.30s)2273 --- PASS: TestClientErrorHandling/ServerNotAvailable (13.64s)22742026/11/06 06:52:54 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000300000000000000000000.nar.zst upload_id=NWJiOTg2ZjctM2QzNS00YzUzLThmM2MtMmNjMzYwZDg1NjJkLmY3MmEyZjg1LTNkYWEtNDU0OC1hZmZlLWM5MjUxMjc3MGZmMXgxNzkzOTQ3OTczMTk2NzQxMDAw parts=1022752026/11/06 06:52:55 INFO Received uploads request method=POST path=/api/pending_closures22762026/11/06 06:52:55 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete22772026/11/06 06:52:55 INFO Object in database but missing from S3 key=nar/dadb44fdadb44fdadb44fdadb44f000500000000000000000000.nar.zst22782026/11/06 06:52:55 WARN Found objects in DB but missing from S3, will re-upload count=122792026/11/06 06:52:55 INFO Completed upload id=1 objects=3 duration=10.331083ms22802026/11/06 06:52:55 INFO Received uploads request method=POST path=/api/pending_closures22812026/11/06 06:52:55 INFO Received complete multipart upload request method=POST path=/api/multipart/complete22822026/11/06 06:52:55 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000200000000000000000000.nar.zst upload_id=NWJiOTg2ZjctM2QzNS00YzUzLThmM2MtMmNjMzYwZDg1NjJkLmY2NTRiOTM3LTA4ZDktNDExZS1hNWJlLWFjNTViZDU4NjNiOHgxNzkzOTQ3OTczNTI2NDI4MDAw parts=1022832026/11/06 06:52:55 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete22842026/11/06 06:52:55 INFO Completed upload id=1 objects=3 duration=10.594125ms22852026/11/06 06:52:55 INFO Received uploads request method=POST path=/api/pending_closures22862026/11/06 06:52:55 INFO Received complete multipart upload request method=POST path=/api/multipart/complete22872026/11/06 06:52:55 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f100400000000000000000000.nar.zst upload_id=NWJiOTg2ZjctM2QzNS00YzUzLThmM2MtMmNjMzYwZDg1NjJkLjg1NmUyYzQwLTY0Y2MtNGY5Ni05Yjg5LTNmMDFhODAyZDFkZHgxNzkzOTQ3OTc0MjU1NzM0MDAw parts=1022882026/11/06 06:52:55 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete22892026/11/06 06:52:55 INFO Completed upload id=2 objects=3 duration=1.170833ms2290--- PASS: TestPresentNotReportedWhileGCDeletesClosure (0.00s)2291 --- PASS: TestPresentNotReportedWhileGCDeletesClosure/stale (10.56s)2292 --- PASS: TestPresentNotReportedWhileGCDeletesClosure/fresh (10.76s)22932026/11/06 06:52:55 INFO Received uploads request method=POST path=/api/pending_closures22942026/11/06 06:52:55 INFO Object in database but missing from S3 key=nar/dadb44fdadb44fdadb44fdadb44f000400000000000000000000.nar.zst22952026/11/06 06:52:55 WARN Narinfo references a NAR missing from S3, will re-upload narinfo=dadb44fdadb44fdadb44fdadb44f0004.narinfo22962026/11/06 06:52:56 INFO Received complete multipart upload request method=POST path=/api/multipart/complete22972026/11/06 06:52:56 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f100300000000000000000000.nar.zst upload_id=NWJiOTg2ZjctM2QzNS00YzUzLThmM2MtMmNjMzYwZDg1NjJkLjAxMTVmNTRjLWFmODctNGFlMi04ODQyLWE0ZTY2YjQ3ZGU4ZXgxNzkzOTQ3OTc1MDY0ODMzMDAw parts=1022982026/11/06 06:52:56 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete22992026/11/06 06:52:56 INFO Completed upload id=2 objects=3 duration=983.667µs23002026/11/06 06:52:56 INFO Received uploads request method=POST path=/api/pending_closures23012026/11/06 06:52:56 INFO Object in database but missing from S3 key=nar/dadb44fdadb44fdadb44fdadb44f000300000000000000000000.nar.zst23022026/11/06 06:52:56 WARN Narinfo references a NAR missing from S3, will re-upload narinfo=dadb44fdadb44fdadb44fdadb44f0003.narinfo2303--- PASS: TestService_verifyS3ReuploadsStaleNarinfo (0.01s)2304 --- PASS: TestService_verifyS3ReuploadsStaleNarinfo/lost,_other_NAR_pushed (11.69s)2305 --- PASS: TestService_verifyS3ReuploadsStaleNarinfo/lost,_same_NAR_pushed (11.91s)2306 --- PASS: TestService_verifyS3ReuploadsStaleNarinfo/intact,_other_NAR_pushed (11.35s)2307 --- PASS: TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost,_second_pushed (13.20s)2308 --- PASS: TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost (12.65s)2309PASS2310{"timestamp":"2026-11-06T06:52:56.242287Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:52712","error_kind":"io_error","error":"Cancelled","result":"transport_error","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":2561,"threadName":"rustfs-worker","threadId":"ThreadId(11)"}2311{"timestamp":"2026-11-06T06:52:56.242431Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:52714","error_kind":"io_error","error":"Cancelled","result":"transport_error","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":2561,"threadName":"rustfs-worker","threadId":"ThreadId(6)"}2312{"timestamp":"2026-11-06T06:52:56.243803Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:52457","error_kind":"io_error","error":"Cancelled","result":"transport_error","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":2561,"threadName":"rustfs-worker","threadId":"ThreadId(11)"}2313{"timestamp":"2026-11-06T06:52:56.243843Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:52698","error_kind":"io_error","error":"Cancelled","result":"transport_error","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":2561,"threadName":"rustfs-worker","threadId":"ThreadId(5)"}2314{"timestamp":"2026-11-06T06:52:56.244233Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:52505","error_kind":"io_error","error":"Cancelled","result":"transport_error","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":2561,"threadName":"rustfs-worker","threadId":"ThreadId(5)"}23152026-11-06 06:52:56.371 UTC [72589] LOG: received smart shutdown request23162026-11-06 06:52:56.374 UTC [72589] LOG: background worker "logical replication launcher" (PID 72599) exited with exit code 123172026-11-06 06:52:56.379 UTC [72594] LOG: shutting down23182026-11-06 06:52:56.380 UTC [72594] LOG: checkpoint starting: shutdown immediate23192026-11-06 06:52:58.057 UTC [72594] LOG: checkpoint complete: wrote 11944 buffers (72.9%), wrote 5 SLRU buffers; 0 WAL file(s) added, 0 removed, 32 recycled; write=0.894 s, sync=0.726 s, total=1.678 s; sync files=35725, longest=0.001 s, average=0.001 s; distance=525259 kB, estimate=525259 kB; lsn=0/2187FD30, redo lsn=0/2187FD3023202026-11-06 06:52:58.066 UTC [72589] LOG: database system is shut down2321Running OIDC tests...2322=== RUN TestAudienceForIssuer2323=== PAUSE TestAudienceForIssuer2324=== RUN TestGlobMatch2325=== PAUSE TestGlobMatch2326=== RUN TestValidateToken_ValidToken2327=== PAUSE TestValidateToken_ValidToken2328=== RUN TestValidateToken_WrongAudience2329=== PAUSE TestValidateToken_WrongAudience2330=== RUN TestValidateToken_Expired2331=== PAUSE TestValidateToken_Expired2332=== RUN TestValidateToken_BoundClaimsMismatch2333=== PAUSE TestValidateToken_BoundClaimsMismatch2334=== RUN TestValidateToken_BoundSubjectMismatch2335=== PAUSE TestValidateToken_BoundSubjectMismatch2336=== RUN TestValidateToken_MultipleProviders2337=== PAUSE TestValidateToken_MultipleProviders2338=== RUN TestValidateToken_NoMatchingProvider2339=== PAUSE TestValidateToken_NoMatchingProvider2340=== RUN TestValidateToken_KubernetesServiceAccount2341=== PAUSE TestValidateToken_KubernetesServiceAccount2342=== RUN TestNewValidator_KubernetesRequiresCA2343=== PAUSE TestNewValidator_KubernetesRequiresCA2344=== RUN TestValidateToken_KubernetesIssuerFromOwnToken2345=== PAUSE TestValidateToken_KubernetesIssuerFromOwnToken2346=== RUN TestPins_ReservedForMatchingRule2347=== PAUSE TestPins_ReservedForMatchingRule2348=== RUN TestPins_TopLevelShorthand2349=== PAUSE TestPins_TopLevelShorthand2350=== RUN TestPins_ConfigValidation2351=== PAUSE TestPins_ConfigValidation2352=== RUN TestScopes_LegacyProviderDefaultsToWrite2353=== PAUSE TestScopes_LegacyProviderDefaultsToWrite2354=== RUN TestScopes_Rules2355=== PAUSE TestScopes_Rules2356=== RUN TestScopes_ConfigValidation2357=== PAUSE TestScopes_ConfigValidation2358=== CONT TestAudienceForIssuer2359--- PASS: TestAudienceForIssuer (0.00s)2360=== CONT TestValidateToken_BoundClaimsMismatch2361=== CONT TestValidateToken_MultipleProviders2362=== CONT TestValidateToken_Expired2363=== CONT TestValidateToken_WrongAudience2364=== CONT TestValidateToken_ValidToken2365=== CONT TestValidateToken_KubernetesServiceAccount2366=== CONT TestGlobMatch2367=== RUN TestGlobMatch/foo_foo2368=== PAUSE TestGlobMatch/foo_foo2369=== RUN TestGlobMatch/foo_bar2370=== PAUSE TestGlobMatch/foo_bar2371=== RUN TestGlobMatch/*_2372=== PAUSE TestGlobMatch/*_2373=== RUN TestGlobMatch/*_anything2374=== PAUSE TestGlobMatch/*_anything2375=== RUN TestGlobMatch/foo*_foo2376=== PAUSE TestGlobMatch/foo*_foo2377=== RUN TestGlobMatch/foo*_foobar2378=== PAUSE TestGlobMatch/foo*_foobar2379=== RUN TestGlobMatch/foo*_bar2380=== PAUSE TestGlobMatch/foo*_bar2381=== RUN TestGlobMatch/*bar_bar2382=== PAUSE TestGlobMatch/*bar_bar2383=== RUN TestGlobMatch/*bar_foobar2384=== PAUSE TestGlobMatch/*bar_foobar2385=== RUN TestGlobMatch/*bar_foo2386=== PAUSE TestGlobMatch/*bar_foo2387=== RUN TestGlobMatch/foo*bar_foobar2388=== PAUSE TestGlobMatch/foo*bar_foobar2389=== RUN TestGlobMatch/foo*bar_foo123bar2390=== PAUSE TestGlobMatch/foo*bar_foo123bar2391=== RUN TestGlobMatch/foo*bar_foobarbaz2392=== PAUSE TestGlobMatch/foo*bar_foobarbaz2393=== RUN TestGlobMatch/*/*_foo/bar2394=== PAUSE TestGlobMatch/*/*_foo/bar2395=== RUN TestGlobMatch/*/*_foo2396=== PAUSE TestGlobMatch/*/*_foo2397=== RUN TestGlobMatch/refs/heads/*_refs/heads/main2398=== PAUSE TestGlobMatch/refs/heads/*_refs/heads/main2399=== RUN TestGlobMatch/refs/heads/*_refs/tags/v1.02400=== PAUSE TestGlobMatch/refs/heads/*_refs/tags/v1.02401=== RUN TestGlobMatch/refs/*/main_refs/heads/main2402=== PAUSE TestGlobMatch/refs/*/main_refs/heads/main2403=== RUN TestGlobMatch/fo?_foo2404=== PAUSE TestGlobMatch/fo?_foo2405=== RUN TestGlobMatch/fo?_fo2406=== PAUSE TestGlobMatch/fo?_fo2407=== RUN TestGlobMatch/fo?_fooo2408=== PAUSE TestGlobMatch/fo?_fooo2409=== RUN TestGlobMatch/?oo_foo2410=== PAUSE TestGlobMatch/?oo_foo2411=== RUN TestGlobMatch/?oo_boo2412=== PAUSE TestGlobMatch/?oo_boo2413=== RUN TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2414=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2415=== RUN TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2416=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2417=== CONT TestGlobMatch/foo_foo2418=== CONT TestScopes_ConfigValidation2419=== CONT TestGlobMatch/*/*_foo/bar2420=== CONT TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2421=== CONT TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2422=== CONT TestGlobMatch/?oo_boo2423=== CONT TestGlobMatch/?oo_foo2424=== CONT TestGlobMatch/fo?_fooo2425=== CONT TestGlobMatch/fo?_fo2426=== CONT TestGlobMatch/fo?_foo2427=== CONT TestGlobMatch/refs/*/main_refs/heads/main2428=== CONT TestGlobMatch/refs/heads/*_refs/tags/v1.02429=== CONT TestGlobMatch/refs/heads/*_refs/heads/main2430=== CONT TestGlobMatch/*/*_foo2431=== CONT TestGlobMatch/*bar_bar2432=== CONT TestGlobMatch/foo*bar_foobarbaz2433=== CONT TestGlobMatch/foo*bar_foo123bar2434=== CONT TestGlobMatch/foo*bar_foobar2435=== CONT TestGlobMatch/*bar_foo2436=== CONT TestGlobMatch/*bar_foobar2437=== CONT TestGlobMatch/foo*_foo2438=== CONT TestGlobMatch/foo*_bar2439=== CONT TestGlobMatch/foo*_foobar2440=== CONT TestGlobMatch/*_2441=== CONT TestGlobMatch/*_anything2442=== CONT TestGlobMatch/foo_bar2443--- PASS: TestGlobMatch (0.00s)2444 --- PASS: TestGlobMatch/foo_foo (0.00s)2445 --- PASS: TestGlobMatch/*/*_foo/bar (0.00s)2446 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main (0.00s)2447 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main (0.00s)2448 --- PASS: TestGlobMatch/?oo_boo (0.00s)2449 --- PASS: TestGlobMatch/?oo_foo (0.00s)2450 --- PASS: TestGlobMatch/fo?_fooo (0.00s)2451 --- PASS: TestGlobMatch/fo?_fo (0.00s)2452 --- PASS: TestGlobMatch/fo?_foo (0.00s)2453 --- PASS: TestGlobMatch/refs/*/main_refs/heads/main (0.00s)2454 --- PASS: TestGlobMatch/refs/heads/*_refs/tags/v1.0 (0.00s)2455 --- PASS: TestGlobMatch/refs/heads/*_refs/heads/main (0.00s)2456 --- PASS: TestGlobMatch/*/*_foo (0.00s)2457 --- PASS: TestGlobMatch/*bar_bar (0.00s)2458 --- PASS: TestGlobMatch/foo*bar_foobarbaz (0.00s)2459 --- PASS: TestGlobMatch/foo*bar_foo123bar (0.00s)2460 --- PASS: TestGlobMatch/foo*bar_foobar (0.00s)2461 --- PASS: TestGlobMatch/*bar_foo (0.00s)2462 --- PASS: TestGlobMatch/*bar_foobar (0.00s)2463 --- PASS: TestGlobMatch/foo*_foo (0.00s)2464 --- PASS: TestGlobMatch/foo*_bar (0.00s)2465 --- PASS: TestGlobMatch/foo*_foobar (0.00s)2466 --- PASS: TestGlobMatch/*_ (0.00s)2467 --- PASS: TestGlobMatch/*_anything (0.00s)2468 --- PASS: TestGlobMatch/foo_bar (0.00s)2469=== CONT TestScopes_Rules2470=== CONT TestScopes_LegacyProviderDefaultsToWrite2471=== CONT TestValidateToken_NoMatchingProvider2472=== CONT TestPins_ConfigValidation2473=== CONT TestPins_TopLevelShorthand2474=== CONT TestPins_ReservedForMatchingRule2475=== CONT TestValidateToken_KubernetesIssuerFromOwnToken2476=== CONT TestValidateToken_BoundSubjectMismatch2477=== CONT TestNewValidator_KubernetesRequiresCA2478--- PASS: TestScopes_ConfigValidation (0.01s)2479--- PASS: TestPins_ConfigValidation (0.00s)24802026/11/06 06:52:59 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:52722/oidc24812026/11/06 06:52:59 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:52721/oidc2482--- PASS: TestPins_ReservedForMatchingRule (0.08s)2483--- PASS: TestValidateToken_BoundClaimsMismatch (0.10s)24842026/11/06 06:53:00 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:52726/oidc24852026/11/06 06:53:00 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:52728/oidc2486--- PASS: TestScopes_LegacyProviderDefaultsToWrite (0.10s)24872026/11/06 06:53:00 INFO OIDC provider initialized name=kubernetes issuer=https://oidc.eks.invalid/id/ABC1232488--- PASS: TestScopes_Rules (0.12s)2489--- PASS: TestValidateToken_KubernetesIssuerFromOwnToken (0.11s)24902026/11/06 06:53:00 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:52733/oidc24912026/11/06 06:53:00 http: TLS handshake error from 127.0.0.1:52731: read tcp 127.0.0.1:52730->127.0.0.1:52731: use of closed network connection2492--- PASS: TestNewValidator_KubernetesRequiresCA (0.10s)2493--- PASS: TestPins_TopLevelShorthand (0.12s)24942026/11/06 06:53:00 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:52735/oidc2495--- PASS: TestValidateToken_Expired (0.14s)24962026/11/06 06:53:00 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:52738/oidc24972026/11/06 06:53:00 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:52742/oidc2498--- PASS: TestValidateToken_ValidToken (0.17s)24992026/11/06 06:53:00 INFO OIDC provider initialized name=kubernetes issuer=https://127.0.0.1:527402500--- PASS: TestValidateToken_BoundSubjectMismatch (0.15s)2501--- PASS: TestValidateToken_KubernetesServiceAccount (0.18s)25022026/11/06 06:53:00 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:52737/oidc2503--- PASS: TestValidateToken_NoMatchingProvider (0.20s)25042026/11/06 06:53:00 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:52747/oidc2505--- PASS: TestValidateToken_WrongAudience (0.21s)25062026/11/06 06:53:00 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:52744/oidc25072026/11/06 06:53:00 INFO OIDC provider initialized name=provider2 issuer=http://127.0.0.1:52749/oidc2508--- PASS: TestValidateToken_MultipleProviders (0.24s)2509PASS2510Running hook tests...2511=== RUN TestSendPathsEmpty2512=== PAUSE TestSendPathsEmpty2513=== RUN TestQueueEnqueueAndFetch2514=== PAUSE TestQueueEnqueueAndFetch2515=== RUN TestQueueDeduplication2516=== PAUSE TestQueueDeduplication2517=== RUN TestQueueRemove2518=== PAUSE TestQueueRemove2519=== RUN TestQueueFetchBatchLimit2520=== PAUSE TestQueueFetchBatchLimit2521=== RUN TestQueueRetryMovesToBack2522=== PAUSE TestQueueRetryMovesToBack2523=== RUN TestQueueFetchRemoveLifecycle2524=== PAUSE TestQueueFetchRemoveLifecycle2525=== RUN TestQueueConcurrentWriters2526=== PAUSE TestQueueConcurrentWriters2527=== RUN TestQueueRemoveLargeClosure2528=== PAUSE TestQueueRemoveLargeClosure2529=== RUN TestServerClientIntegration2530--- PASS: TestServerClientIntegration (0.00s)2531=== RUN TestServerQueueError25322026/11/06 06:53:00 ERROR Failed to queue paths error="permission denied" count=12533--- PASS: TestServerQueueError (0.00s)2534=== RUN TestGetListenerSocketActivation2535 server_test.go:145: systemd socket activation does not exist on darwin2536--- SKIP: TestGetListenerSocketActivation (0.00s)2537=== RUN TestServerStalledClientDoesNotBlockShutdown2538=== PAUSE TestServerStalledClientDoesNotBlockShutdown2539=== RUN TestServerBacksOffOnAcceptErrors2540=== PAUSE TestServerBacksOffOnAcceptErrors2541=== RUN TestDrainIsolatesPoisonPath2542=== PAUSE TestDrainIsolatesPoisonPath2543=== RUN TestRunNotBlockedByPoisonHead2544=== PAUSE TestRunNotBlockedByPoisonHead2545=== RUN TestDrainGivesUpWhenServerDown2546=== PAUSE TestDrainGivesUpWhenServerDown2547=== RUN TestFailedPathPrunedByLaterClosure2548=== PAUSE TestFailedPathPrunedByLaterClosure2549=== RUN TestWorkerUploadsAndRemoves2550=== PAUSE TestWorkerUploadsAndRemoves2551=== RUN TestWorkerSkipsGCdPaths2552=== PAUSE TestWorkerSkipsGCdPaths2553=== RUN TestWorkerPrunesClosureDeps2554=== PAUSE TestWorkerPrunesClosureDeps2555=== RUN TestDrainTimeout2556=== PAUSE TestDrainTimeout2557=== RUN TestWorkerRemoveFailureIsNotProgress2558=== PAUSE TestWorkerRemoveFailureIsNotProgress2559=== RUN TestWorkerKeepsPathItCannotStat2560=== PAUSE TestWorkerKeepsPathItCannotStat2561=== CONT TestSendPathsEmpty2562=== CONT TestWorkerSkipsGCdPaths2563--- PASS: TestSendPathsEmpty (0.00s)2564=== CONT TestWorkerKeepsPathItCannotStat2565=== CONT TestWorkerRemoveFailureIsNotProgress2566=== CONT TestDrainTimeout2567=== CONT TestWorkerPrunesClosureDeps2568=== CONT TestDrainIsolatesPoisonPath2569=== CONT TestServerBacksOffOnAcceptErrors25702026/11/06 06:53:00 ERROR Accept failed error="too many open files"2571=== CONT TestServerStalledClientDoesNotBlockShutdown2572=== CONT TestQueueRemoveLargeClosure2573=== CONT TestQueueConcurrentWriters2574=== CONT TestFailedPathPrunedByLaterClosure2575=== CONT TestWorkerUploadsAndRemoves2576=== CONT TestQueueFetchRemoveLifecycle2577=== CONT TestQueueRemove2578=== CONT TestQueueDeduplication2579=== CONT TestQueueRetryMovesToBack2580=== CONT TestQueueEnqueueAndFetch2581=== CONT TestDrainGivesUpWhenServerDown2582=== CONT TestQueueFetchBatchLimit2583=== CONT TestRunNotBlockedByPoisonHead25842026/11/06 06:53:00 ERROR Accept failed error="too many open files"25852026/11/06 06:53:00 INFO Upload queue status pending=225862026/11/06 06:53:00 INFO Uploading batch count=225872026/11/06 06:53:00 INFO Upload queue status pending=225882026/11/06 06:53:00 INFO Uploading batch count=125892026/11/06 06:53:00 INFO Uploading batch count=125902026/11/06 06:53:00 ERROR Upload failed error="upload failed" count=125912026/11/06 06:53:00 ERROR Accept failed error="too many open files"25922026/11/06 06:53:00 INFO Uploading batch count=225932026/11/06 06:53:00 INFO Uploading batch count=12594--- PASS: TestQueueDeduplication (0.02s)25952026/11/06 06:53:00 WARN Cannot stat store path, will retry later path=/private/var/tb/5/scratch/87d7ae187515016b/build/TestWorkerKeepsPathItCannotStat559363089/002/locked/aaa error="stat /private/var/tb/5/scratch/87d7ae187515016b/build/TestWorkerKeepsPathItCannotStat559363089/002/locked/aaa: permission denied"2596--- PASS: TestQueueFetchRemoveLifecycle (0.02s)25972026/11/06 06:53:00 WARN Cannot stat store path, will retry later path=/private/var/tb/5/scratch/87d7ae187515016b/build/TestWorkerKeepsPathItCannotStat559363089/002/locked/aaa error="stat /private/var/tb/5/scratch/87d7ae187515016b/build/TestWorkerKeepsPathItCannotStat559363089/002/locked/aaa: permission denied"25982026/11/06 06:53:00 INFO Uploading batch count=225992026/11/06 06:53:00 ERROR Upload failed error="upload failed" count=226002026/11/06 06:53:00 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/5/scratch/87d7ae187515016b/build/TestDrainGivesUpWhenServerDown2791081008/002/a2601--- PASS: TestQueueRetryMovesToBack (0.02s)26022026/11/06 06:53:00 INFO Uploading batch count=426032026/11/06 06:53:00 ERROR Upload failed error="upload failed" count=426042026/11/06 06:53:00 INFO Uploading batch count=126052026/11/06 06:53:00 WARN Cannot stat store path, will retry later path=/private/var/tb/5/scratch/87d7ae187515016b/build/TestWorkerKeepsPathItCannotStat559363089/002/locked/aaa error="stat /private/var/tb/5/scratch/87d7ae187515016b/build/TestWorkerKeepsPathItCannotStat559363089/002/locked/aaa: permission denied"2606--- PASS: TestQueueRemove (0.02s)26072026/11/06 06:53:00 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/5/scratch/87d7ae187515016b/build/TestDrainIsolatesPoisonPath2659262181/002/bbb26082026/11/06 06:53:00 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/5/scratch/87d7ae187515016b/build/TestDrainGivesUpWhenServerDown2791081008/002/b26092026/11/06 06:53:00 INFO Upload queue status pending=226102026/11/06 06:53:00 ERROR Drain finished with paths left in queue remaining=126112026/11/06 06:53:00 WARN Store path no longer exists (garbage collected?), removing from queue path=/private/var/tb/5/scratch/87d7ae187515016b/build/TestWorkerSkipsGCdPaths1473457459/002/nonexistent26122026/11/06 06:53:00 INFO Uploading batch count=226132026/11/06 06:53:00 ERROR Upload failed error="upload failed" count=226142026/11/06 06:53:00 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/5/scratch/87d7ae187515016b/build/TestDrainGivesUpWhenServerDown2791081008/002/c26152026/11/06 06:53:00 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/5/scratch/87d7ae187515016b/build/TestDrainGivesUpWhenServerDown2791081008/002/d2616--- PASS: TestQueueEnqueueAndFetch (0.01s)26172026/11/06 06:53:00 INFO Uploading batch count=126182026/11/06 06:53:00 INFO Uploading batch count=226192026/11/06 06:53:00 ERROR Upload failed error="upload failed" count=226202026/11/06 06:53:00 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/5/scratch/87d7ae187515016b/build/TestDrainGivesUpWhenServerDown2791081008/002/e2621--- PASS: TestFailedPathPrunedByLaterClosure (0.02s)26222026/11/06 06:53:00 INFO Upload queue status pending=326232026/11/06 06:53:00 INFO Uploading batch count=126242026/11/06 06:53:00 ERROR Upload failed error="upload failed" count=12625--- PASS: TestQueueFetchBatchLimit (0.01s)26262026/11/06 06:53:00 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/5/scratch/87d7ae187515016b/build/TestDrainGivesUpWhenServerDown2791081008/002/f26272026/11/06 06:53:00 INFO Uploading batch count=126282026/11/06 06:53:00 ERROR Upload failed error="upload failed" count=126292026/11/06 06:53:00 WARN Store path no longer exists (garbage collected?), removing from queue path=/private/var/tb/5/scratch/87d7ae187515016b/build/TestWorkerRemoveFailureIsNotProgress1788708451/002/nonexistent26302026/11/06 06:53:00 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=126312026/11/06 06:53:00 WARN Store path no longer exists (garbage collected?), removing from queue path=/private/var/tb/5/scratch/87d7ae187515016b/build/TestWorkerRemoveFailureIsNotProgress1788708451/002/nonexistent26322026/11/06 06:53:00 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=126332026/11/06 06:53:00 INFO Uploading batch count=126342026/11/06 06:53:00 ERROR Upload failed error="upload failed" count=126352026/11/06 06:53:00 WARN Store path no longer exists (garbage collected?), removing from queue path=/private/var/tb/5/scratch/87d7ae187515016b/build/TestWorkerRemoveFailureIsNotProgress1788708451/002/nonexistent26362026/11/06 06:53:00 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=12637--- PASS: TestWorkerKeepsPathItCannotStat (0.02s)26382026/11/06 06:53:00 ERROR Drain finished with paths left in queue remaining=126392026/11/06 06:53:00 INFO Uploading batch count=126402026/11/06 06:53:00 ERROR Upload failed error="upload failed" count=126412026/11/06 06:53:00 ERROR Drain finished with paths left in queue remaining=1026422026/11/06 06:53:00 ERROR Drain finished with paths left in queue remaining=12643--- PASS: TestWorkerRemoveFailureIsNotProgress (0.02s)2644--- PASS: TestDrainIsolatesPoisonPath (0.02s)2645--- PASS: TestDrainGivesUpWhenServerDown (0.02s)2646--- PASS: TestWorkerUploadsAndRemoves (0.03s)26472026/11/06 06:53:00 ERROR Accept failed error="too many open files"2648--- PASS: TestWorkerPrunesClosureDeps (0.04s)2649--- PASS: TestWorkerSkipsGCdPaths (0.04s)2650--- PASS: TestQueueRemoveLargeClosure (0.04s)2651--- PASS: TestQueueConcurrentWriters (0.05s)26522026/11/06 06:53:00 ERROR Accept failed error="too many open files"26532026/11/06 06:53:00 ERROR Accept failed error="too many open files"26542026/11/06 06:53:00 ERROR Failed to decode request error="read unix /private/var/tb/5/scratch/87d7ae187515016b/build/hook3719511113/test.sock->: i/o timeout"26552026/11/06 06:53:00 ERROR Failed to write response error="write unix /private/var/tb/5/scratch/87d7ae187515016b/build/hook3719511113/test.sock->: i/o timeout"2656--- PASS: TestServerStalledClientDoesNotBlockShutdown (0.20s)26572026/11/06 06:53:00 ERROR Upload failed error="context deadline exceeded" count=226582026/11/06 06:53:00 ERROR Drain finished with paths left in queue remaining=42659--- PASS: TestDrainTimeout (0.22s)26602026/11/06 06:53:00 ERROR Accept failed error="too many open files"26612026/11/06 06:53:01 ERROR Accept failed error="too many open files"2662--- PASS: TestServerBacksOffOnAcceptErrors (0.65s)26632026/11/06 06:53:01 INFO Uploading batch count=126642026/11/06 06:53:01 INFO Uploading batch count=126652026/11/06 06:53:01 INFO Uploading batch count=126662026/11/06 06:53:01 ERROR Upload failed error="upload failed" count=126672026/11/06 06:53:01 INFO Uploading batch count=126682026/11/06 06:53:01 ERROR Upload failed error="upload failed" count=126692026/11/06 06:53:01 INFO Uploading batch count=126702026/11/06 06:53:01 ERROR Upload failed error="upload failed" count=126712026/11/06 06:53:01 INFO Uploading batch count=126722026/11/06 06:53:01 ERROR Upload failed error="upload failed" count=126732026/11/06 06:53:01 ERROR Drain finished with paths left in queue remaining=12674--- PASS: TestRunNotBlockedByPoisonHead (1.04s)2675PASS2676Running signing tests...2677=== RUN TestExternalSigner2678=== PAUSE TestExternalSigner2679=== RUN TestExternalSignerWrongPublicKey2680=== PAUSE TestExternalSignerWrongPublicKey2681=== RUN TestExternalSignerErrors2682=== PAUSE TestExternalSignerErrors2683=== RUN TestExternalSignerRestartsAfterCrash2684=== PAUSE TestExternalSignerRestartsAfterCrash2685=== RUN TestExternalSignerProgramErrorKeepsProcess2686=== PAUSE TestExternalSignerProgramErrorKeepsProcess2687=== RUN TestExternalSignerClose2688=== PAUSE TestExternalSignerClose2689=== RUN TestExternalSignerRejectsInvalidPublicKey2690=== PAUSE TestExternalSignerRejectsInvalidPublicKey2691=== RUN TestExternalSignerCancellation2692=== PAUSE TestExternalSignerCancellation2693=== RUN TestGenerateFingerprint2694=== PAUSE TestGenerateFingerprint2695=== RUN TestParseSigningKey2696=== PAUSE TestParseSigningKey2697=== RUN TestSign2698=== PAUSE TestSign2699=== RUN TestSignBatch2700=== PAUSE TestSignBatch2701=== RUN TestNilKeyPublicKey2702=== PAUSE TestNilKeyPublicKey2703=== RUN TestSignErrors2704=== PAUSE TestSignErrors2705=== CONT TestExternalSigner2706=== CONT TestExternalSignerCancellation2707=== CONT TestParseSigningKey2708=== RUN TestParseSigningKey/valid_32-byte_key2709=== PAUSE TestParseSigningKey/valid_32-byte_key2710=== RUN TestParseSigningKey/valid_32-byte_key_with_different_name2711=== PAUSE TestParseSigningKey/valid_32-byte_key_with_different_name2712=== RUN TestParseSigningKey/no_colon2713=== PAUSE TestParseSigningKey/no_colon2714=== RUN TestParseSigningKey/empty_name2715=== PAUSE TestParseSigningKey/empty_name2716=== RUN TestParseSigningKey/invalid_base642717=== PAUSE TestParseSigningKey/invalid_base642718=== RUN TestParseSigningKey/wrong_length2719=== PAUSE TestParseSigningKey/wrong_length2720=== CONT TestParseSigningKey/valid_32-byte_key2721=== CONT TestParseSigningKey/invalid_base642722=== CONT TestParseSigningKey/wrong_length2723=== CONT TestExternalSignerProgramErrorKeepsProcess2724=== CONT TestSign2725=== CONT TestExternalSignerErrors2726=== RUN TestExternalSignerErrors/wrong_id2727=== PAUSE TestExternalSignerErrors/wrong_id2728=== RUN TestExternalSignerErrors/missing_signatures2729=== PAUSE TestExternalSignerErrors/missing_signatures2730=== CONT TestGenerateFingerprint2731=== CONT TestExternalSignerRestartsAfterCrash2732=== CONT TestExternalSignerRejectsInvalidPublicKey2733=== CONT TestSignErrors2734=== CONT TestNilKeyPublicKey2735--- PASS: TestNilKeyPublicKey (0.00s)2736=== CONT TestExternalSignerClose2737=== RUN TestExternalSignerErrors/null_signatures2738=== PAUSE TestExternalSignerErrors/null_signatures2739=== RUN TestExternalSignerErrors/missing_signature_name2740=== PAUSE TestExternalSignerErrors/missing_signature_name2741=== RUN TestExternalSignerErrors/invalid_signature_base642742=== PAUSE TestExternalSignerErrors/invalid_signature_base642743=== RUN TestExternalSignerErrors/program_error2744=== PAUSE TestExternalSignerErrors/program_error2745=== RUN TestExternalSignerErrors/exit_at_startup2746=== PAUSE TestExternalSignerErrors/exit_at_startup2747=== RUN TestExternalSignerErrors/null2748=== PAUSE TestExternalSignerErrors/null2749=== RUN TestExternalSignerErrors/wrong_signature_length2750=== PAUSE TestExternalSignerErrors/wrong_signature_length2751=== RUN TestExternalSignerErrors/exit_on_request2752=== PAUSE TestExternalSignerErrors/exit_on_request2753=== RUN TestExternalSignerErrors/wrong_shape2754=== PAUSE TestExternalSignerErrors/wrong_shape2755=== RUN TestExternalSignerErrors/wrong_signatures_shape2756=== RUN TestExternalSignerRejectsInvalidPublicKey/#002757=== CONT TestSignBatch2758=== RUN TestGenerateFingerprint/basic_with_references2759=== PAUSE TestGenerateFingerprint/basic_with_references2760=== PAUSE TestExternalSignerErrors/wrong_signatures_shape2761=== RUN TestExternalSignerErrors/too_few_signatures2762=== PAUSE TestExternalSignerErrors/too_few_signatures2763=== RUN TestExternalSignerErrors/wrong_signature_name2764=== PAUSE TestExternalSignerErrors/wrong_signature_name2765=== RUN TestExternalSignerErrors/invalid_JSON2766=== PAUSE TestExternalSignerErrors/invalid_JSON2767=== RUN TestExternalSignerErrors/unrequested_key2768=== PAUSE TestExternalSignerErrors/unrequested_key2769=== CONT TestExternalSignerErrors/wrong_id2770--- PASS: TestSign (0.00s)2771=== RUN TestSignErrors/nil_key2772=== PAUSE TestSignErrors/nil_key2773=== RUN TestSignErrors/nil_narinfo2774=== PAUSE TestSignErrors/nil_narinfo2775=== RUN TestSignErrors/invalid_narinfo2776=== PAUSE TestSignErrors/invalid_narinfo2777=== RUN TestSignErrors/canceled2778=== PAUSE TestSignErrors/canceled2779=== CONT TestSignErrors/nil_key2780=== CONT TestSignErrors/canceled2781=== CONT TestSignErrors/invalid_narinfo2782=== CONT TestSignErrors/nil_narinfo2783--- PASS: TestSignErrors (0.00s)2784 --- PASS: TestSignErrors/nil_key (0.00s)2785 --- PASS: TestSignErrors/canceled (0.00s)2786 --- PASS: TestSignErrors/invalid_narinfo (0.00s)2787 --- PASS: TestSignErrors/nil_narinfo (0.00s)2788=== CONT TestExternalSignerErrors/exit_on_request2789=== RUN TestGenerateFingerprint/no_references2790=== PAUSE TestGenerateFingerprint/no_references2791--- PASS: TestSignBatch (0.00s)2792=== CONT TestExternalSignerErrors/too_few_signatures2793=== RUN TestGenerateFingerprint/unsorted_references_get_sorted2794=== PAUSE TestGenerateFingerprint/unsorted_references_get_sorted2795=== RUN TestGenerateFingerprint/invalid_nar_hash_prefix2796=== CONT TestExternalSignerErrors/wrong_shape2797=== CONT TestParseSigningKey/no_colon2798=== CONT TestParseSigningKey/empty_name2799=== CONT TestParseSigningKey/valid_32-byte_key_with_different_name2800=== CONT TestExternalSignerErrors/program_error2801=== CONT TestExternalSignerErrors/null2802--- PASS: TestParseSigningKey (0.00s)2803 --- PASS: TestParseSigningKey/invalid_base64 (0.00s)2804 --- PASS: TestParseSigningKey/wrong_length (0.00s)2805 --- PASS: TestParseSigningKey/valid_32-byte_key (0.00s)2806 --- PASS: TestParseSigningKey/no_colon (0.00s)2807 --- PASS: TestParseSigningKey/empty_name (0.00s)2808 --- PASS: TestParseSigningKey/valid_32-byte_key_with_different_name (0.00s)2809=== PAUSE TestExternalSignerRejectsInvalidPublicKey/#002810=== RUN TestExternalSignerRejectsInvalidPublicKey/no-colon2811=== PAUSE TestExternalSignerRejectsInvalidPublicKey/no-colon2812=== RUN TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2813=== PAUSE TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2814=== RUN TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2815=== PAUSE TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2816=== RUN TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2817=== PAUSE TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2818=== CONT TestExternalSignerErrors/null_signatures2819=== CONT TestExternalSignerErrors/missing_signatures2820=== CONT TestExternalSignerErrors/exit_at_startup2821=== CONT TestExternalSignerRejectsInvalidPublicKey/#002822=== CONT TestExternalSignerErrors/missing_signature_name2823=== PAUSE TestGenerateFingerprint/invalid_nar_hash_prefix2824=== RUN TestGenerateFingerprint/invalid_nar_hash_length2825=== PAUSE TestGenerateFingerprint/invalid_nar_hash_length2826=== RUN TestGenerateFingerprint/invalid_store_path_prefix2827=== PAUSE TestGenerateFingerprint/invalid_store_path_prefix2828=== RUN TestGenerateFingerprint/invalid_reference_prefix2829=== PAUSE TestGenerateFingerprint/invalid_reference_prefix2830=== CONT TestExternalSignerWrongPublicKey2831=== CONT TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2832=== CONT TestExternalSignerErrors/invalid_JSON2833=== CONT TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2834=== CONT TestExternalSignerErrors/wrong_signature_name2835=== CONT TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2836=== CONT TestGenerateFingerprint/basic_with_references2837=== CONT TestExternalSignerRejectsInvalidPublicKey/no-colon2838--- PASS: TestExternalSignerRejectsInvalidPublicKey (0.00s)2839 --- PASS: TestExternalSignerRejectsInvalidPublicKey/#00 (0.00s)2840 --- PASS: TestExternalSignerRejectsInvalidPublicKey/test-key:YQ== (0.00s)2841 --- PASS: TestExternalSignerRejectsInvalidPublicKey/test-key:invalid! (0.00s)2842 --- PASS: TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA= (0.00s)2843 --- PASS: TestExternalSignerRejectsInvalidPublicKey/no-colon (0.00s)2844=== CONT TestGenerateFingerprint/invalid_nar_hash_length2845=== CONT TestGenerateFingerprint/invalid_store_path_prefix2846=== CONT TestGenerateFingerprint/unsorted_references_get_sorted2847=== CONT TestExternalSignerErrors/unrequested_key2848=== CONT TestExternalSignerErrors/wrong_signature_length2849=== CONT TestExternalSignerErrors/invalid_signature_base642850=== CONT TestGenerateFingerprint/invalid_nar_hash_prefix2851=== CONT TestGenerateFingerprint/no_references2852=== CONT TestExternalSignerErrors/wrong_signatures_shape2853=== CONT TestGenerateFingerprint/invalid_reference_prefix2854--- PASS: TestGenerateFingerprint (0.00s)2855 --- PASS: TestGenerateFingerprint/basic_with_references (0.00s)2856 --- PASS: TestGenerateFingerprint/invalid_nar_hash_length (0.00s)2857 --- PASS: TestGenerateFingerprint/invalid_store_path_prefix (0.00s)2858 --- PASS: TestGenerateFingerprint/unsorted_references_get_sorted (0.00s)2859 --- PASS: TestGenerateFingerprint/invalid_nar_hash_prefix (0.00s)2860 --- PASS: TestGenerateFingerprint/no_references (0.00s)2861 --- PASS: TestGenerateFingerprint/invalid_reference_prefix (0.00s)2862--- PASS: TestExternalSigner (0.23s)2863--- PASS: TestExternalSignerCancellation (0.42s)2864--- PASS: TestExternalSignerClose (0.79s)2865--- PASS: TestExternalSignerWrongPublicKey (1.36s)2866--- PASS: TestExternalSignerRestartsAfterCrash (2.16s)2867/private/var/tb/5/scratch/87d7ae187515016b/build/TestExternalSignerRestartsAfterCrash2837733867/001/sign program: line 7: /private/var/tb/5/scratch/87d7ae187515016b/build/TestExternalSignerRestartsAfterCrash2837733867/001/sign program.starts: No such file or directory2868--- PASS: TestExternalSignerProgramErrorKeepsProcess (2.71s)2869--- PASS: TestExternalSignerErrors (0.00s)2870 --- PASS: TestExternalSignerErrors/unrequested_key (0.59s)2871 --- PASS: TestExternalSignerErrors/program_error (0.98s)2872 --- PASS: TestExternalSignerErrors/missing_signatures (1.17s)2873 --- PASS: TestExternalSignerErrors/missing_signature_name (1.55s)2874 --- PASS: TestExternalSignerErrors/exit_at_startup (1.74s)2875 --- PASS: TestExternalSignerErrors/wrong_signatures_shape (1.93s)2876 --- PASS: TestExternalSignerErrors/wrong_signature_name (2.32s)2877 --- PASS: TestExternalSignerErrors/wrong_signature_length (2.51s)2878 --- PASS: TestExternalSignerErrors/invalid_signature_base64 (2.89s)2879 --- PASS: TestExternalSignerErrors/wrong_shape (3.09s)2880 --- PASS: TestExternalSignerErrors/null (3.28s)2881 --- PASS: TestExternalSignerErrors/invalid_JSON (3.47s)2882 --- PASS: TestExternalSignerErrors/wrong_id (3.67s)2883 --- PASS: TestExternalSignerErrors/null_signatures (3.85s)2884 --- PASS: TestExternalSignerErrors/exit_on_request (4.04s)2885 --- PASS: TestExternalSignerErrors/too_few_signatures (4.23s)2886PASS2887Running OpenBao signer tests...2888=== RUN TestSign2889=== PAUSE TestSign2890=== RUN TestSignErrors2891=== PAUSE TestSignErrors2892=== RUN TestServe2893=== PAUSE TestServe2894=== RUN TestServeRejectsGarbage2895=== PAUSE TestServeRejectsGarbage2896=== CONT TestSign2897=== CONT TestServeRejectsGarbage2898=== CONT TestSignErrors2899=== CONT TestServe2900=== RUN TestSignErrors/http_error2901--- PASS: TestServeRejectsGarbage (0.00s)2902=== PAUSE TestSignErrors/http_error2903=== RUN TestSignErrors/invalid_json2904=== PAUSE TestSignErrors/invalid_json2905=== RUN TestSignErrors/no_prefix2906=== PAUSE TestSignErrors/no_prefix2907=== RUN TestSignErrors/invalid_base642908=== PAUSE TestSignErrors/invalid_base642909=== CONT TestSignErrors/http_error2910=== CONT TestSignErrors/no_prefix2911=== CONT TestSignErrors/invalid_base642912=== CONT TestSignErrors/invalid_json2913--- PASS: TestServe (0.00s)2914--- PASS: TestSign (0.00s)2915--- PASS: TestSignErrors (0.00s)2916 --- PASS: TestSignErrors/http_error (0.00s)2917 --- PASS: TestSignErrors/invalid_base64 (0.00s)2918 --- PASS: TestSignErrors/invalid_json (0.00s)2919 --- PASS: TestSignErrors/no_prefix (0.00s)2920PASS