niks3-go-unit-tests
checks.aarch64-darwin.go-unit-tests
· build #464
· 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.08s)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 TestRegisterUploadedObject_BoundedAgainstSilentServer118=== CONT TestUploadMultipart_PartsInParallel119=== CONT TestUploadMultipart_SupersededByPeer120=== RUN TestUploadMultipart_SupersededByPeer/exists121=== PAUSE TestUploadMultipart_SupersededByPeer/exists122=== CONT TestRateLimiterFeedback_400DoesNotCountAsSuccess123=== CONT TestSetClientTLSDoesNotMutateDefaultTransport124=== RUN TestUploadMultipart_SupersededByPeer/missing125=== PAUSE TestUploadMultipart_SupersededByPeer/missing126=== CONT TestSupersededNARStillUploadsListing127=== CONT TestResolveStorePath1282026/11/06 07:11:29 WARN Rate limiter enabled after throttle name=server-test rate=5129=== CONT TestPartSizeForNAR130=== RUN TestPartSizeForNAR/zero_stays_at_minimum131=== CONT TestUploadMultipart_ReturnsAfterDroppedBody132=== CONT TestDumpPathSingleFile133=== CONT TestSetClientTLS134=== CONT TestScriptTokenEmptyCommand135=== CONT TestScriptTokenScriptFails136=== CONT TestScriptTokenBadJSON137=== CONT TestScriptTokenEmptyToken138=== CONT TestScriptTokenCachesUntilRefresh139=== CONT TestScriptTokenNoExpiryRerunsEveryCall140=== CONT TestFileTokenEmpty141=== CONT TestFileTokenMissing142=== CONT TestFileTokenReadsAndCaches143=== CONT TestStaticToken144=== CONT TestSetClientTLSErrors145=== CONT TestDumpPathWriterError146=== RUN TestSupersededNARStillUploadsListing/small_NAR147--- PASS: TestDoServerRequestAttachesToken (0.01s)148=== CONT TestDumpPathMatchesNix1492026/11/06 07:11:29 WARN Rate limiter enabled after throttle name=server-test rate=51502026/11/06 07:11:29 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:54287151=== CONT TestPathInfoHashCompatibility152=== RUN TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)153=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)154=== RUN TestPathInfoHashCompatibility/old_string_format_with_colon1552026/11/06 07:11:29 WARN Rate limiter backed off name=server-test rate=5156=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_colon157=== PAUSE TestPartSizeForNAR/zero_stays_at_minimum158=== CONT TestRateLimiterFeedback159=== PAUSE TestSupersededNARStillUploadsListing/small_NAR160--- PASS: TestScriptTokenEmptyCommand (0.00s)161=== RUN TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI162--- PASS: TestStaticToken (0.00s)163--- PASS: TestUploadMultipart_ReturnsAfterDroppedBody (0.00s)164=== CONT TestPathInfoCACompatibility165--- PASS: TestSetClientTLSDoesNotMutateDefaultTransport (0.02s)166=== CONT TestParsePathInfoJSONMultiplePaths167=== RUN TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths168=== RUN TestSetClientTLSErrors/missing_cert_file169--- PASS: TestFileTokenMissing (0.02s)170=== CONT TestParsePathInfoJSON171=== RUN TestPartSizeForNAR/small_stays_at_minimum172=== PAUSE TestPartSizeForNAR/small_stays_at_minimum173=== RUN TestPartSizeForNAR/80_GiB_fits_at_minimum174=== PAUSE TestPartSizeForNAR/80_GiB_fits_at_minimum175=== RUN TestPartSizeForNAR/115_GiB_needs_larger_parts176=== PAUSE TestPartSizeForNAR/115_GiB_needs_larger_parts177=== RUN TestPartSizeForNAR/1_TiB178=== PAUSE TestPartSizeForNAR/1_TiB179=== RUN TestPartSizeForNAR/5_TiB_S3_max_object180=== PAUSE TestPartSizeForNAR/5_TiB_S3_max_object181=== RUN TestPartSizeForNAR/capped_at_5_GiB182=== PAUSE TestPartSizeForNAR/capped_at_5_GiB183=== RUN TestSupersededNARStillUploadsListing/dump_cut_short184=== PAUSE TestSupersededNARStillUploadsListing/dump_cut_short185=== RUN TestSupersededNARStillUploadsListing/listing_upload_fails186=== PAUSE TestSupersededNARStillUploadsListing/listing_upload_fails187=== CONT TestEncodeNixBase32WithRealHash188--- PASS: TestEncodeNixBase32WithRealHash (0.00s)189=== CONT TestConvertHashToNix32190=== RUN TestConvertHashToNix32/SRI_format_to_Nix32191=== PAUSE TestConvertHashToNix32/SRI_format_to_Nix32192=== RUN TestConvertHashToNix32/already_Nix32_format193=== PAUSE TestConvertHashToNix32/already_Nix32_format194=== RUN TestConvertHashToNix32/invalid_format195=== PAUSE TestConvertHashToNix32/invalid_format1962026/11/06 07:11:29 WARN Request returned retryable status, retrying attempt=2 backoff=0s status=503 url=http://127.0.0.1:54287197--- PASS: TestScriptTokenScriptFails (0.02s)198--- PASS: TestScriptTokenBadJSON (0.02s)199--- PASS: TestFileTokenReadsAndCaches (0.02s)200=== CONT TestStreamPushReportsSkippedPaths201--- PASS: TestStreamPushReportsSkippedPaths (0.00s)202=== CONT TestStreamPushReportsSignatures203=== CONT TestStreamPushIsolatesFailures204=== RUN TestRateLimiterFeedback/429_enables_limiter205=== PAUSE TestRateLimiterFeedback/429_enables_limiter206=== RUN TestRateLimiterFeedback/503_enables_limiter207=== PAUSE TestRateLimiterFeedback/503_enables_limiter208=== RUN TestRateLimiterFeedback/200_does_not_enable_limiter209=== PAUSE TestRateLimiterFeedback/200_does_not_enable_limiter210=== RUN TestRateLimiterFeedback/400_does_not_enable_limiter211=== PAUSE TestRateLimiterFeedback/400_does_not_enable_limiter2122026/11/06 07:11:29 ERROR Upload failed error="bad path" count=3213--- PASS: TestStreamPushIsolatesFailures (0.00s)214=== CONT TestStreamPushGivesUpOnDeadServer215=== RUN TestPathInfoCACompatibility/null_ca_field216=== PAUSE TestPathInfoCACompatibility/null_ca_field217=== RUN TestPathInfoCACompatibility/old_string_format_-_text218=== PAUSE TestPathInfoCACompatibility/old_string_format_-_text219=== RUN TestPathInfoCACompatibility/old_string_format_-_fixed_recursive220=== PAUSE TestPathInfoCACompatibility/old_string_format_-_fixed_recursive221=== RUN TestPathInfoCACompatibility/new_structured_format_-_text222=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_text223=== RUN TestPathInfoCACompatibility/new_structured_format_-_nar_method224=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_nar_method225=== CONT TestStreamPushRequestLine2262026/11/06 07:11:29 ERROR Upload failed error="connection refused" count=202272026/11/06 07:11:29 ERROR Server seems unavailable, giving up on batch untried=17228--- PASS: TestStreamPushGivesUpOnDeadServer (0.00s)229=== CONT TestFilterOversizedClosures230=== RUN TestFilterOversizedClosures/no_limit_keeps_everything231=== PAUSE TestFilterOversizedClosures/no_limit_keeps_everything232=== RUN TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped233=== PAUSE TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped234=== PAUSE TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI235=== CONT TestRunGarbageCollection_FinishedOnAnotherReplica236=== PAUSE TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths2372026/11/06 07:11:29 ERROR Upload failed error=boom count=1238=== RUN TestPathInfoHashCompatibility/new_structured_format_with_sha512239=== PAUSE TestSetClientTLSErrors/missing_cert_file240=== RUN TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths2412026/11/06 07:11:29 ERROR Upload failed error=boom count=1242=== PAUSE TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths243=== RUN TestSetClientTLSErrors/missing_key_file244=== PAUSE TestSetClientTLSErrors/missing_key_file245=== RUN TestSetClientTLSErrors/missing_ca_file246=== PAUSE TestSetClientTLSErrors/missing_ca_file247=== RUN TestSetClientTLSErrors/invalid_ca_file248=== PAUSE TestSetClientTLSErrors/invalid_ca_file249=== CONT TestShellSplit250=== CONT TestStreamPushReportsEveryPath251=== CONT TestStreamPushBatchesUnderLoad252=== RUN TestStreamPushBatchesUnderLoad/oneAtATime=false253=== PAUSE TestStreamPushBatchesUnderLoad/oneAtATime=false254=== RUN TestStreamPushBatchesUnderLoad/oneAtATime=true255=== PAUSE TestStreamPushBatchesUnderLoad/oneAtATime=true256=== RUN TestParsePathInfoJSON/Nix_format257=== PAUSE TestParsePathInfoJSON/Nix_format258=== RUN TestParsePathInfoJSON/Lix_format259=== PAUSE TestParsePathInfoJSON/Lix_format260=== RUN TestParsePathInfoJSON/empty_input261=== PAUSE TestParsePathInfoJSON/empty_input262=== RUN TestParsePathInfoJSON/whitespace_only263=== PAUSE TestParsePathInfoJSON/whitespace_only264=== RUN TestParsePathInfoJSON/invalid_JSON265=== PAUSE TestParsePathInfoJSON/invalid_JSON266=== CONT TestRetryTimeoutOutlastsMaxRetries267=== CONT TestEncodeNixBase32268=== RUN TestEncodeNixBase32/test_string_hash269=== PAUSE TestEncodeNixBase32/test_string_hash270=== RUN TestEncodeNixBase32/empty_input271=== PAUSE TestEncodeNixBase32/empty_input272=== CONT TestShellSplitErrors273=== CONT TestUploadBuildLog_FileBodyReplayedOnRetry274=== CONT TestRegisterUploadedObjectReusesConnections275=== CONT TestStreamPushStopsWhenCanceled276=== CONT TestUploadMultipart_SupersededByPeer/exists277=== CONT TestClientSignaturesByStorePath278=== CONT TestUploadMultipart_SupersededByPeer/missing279=== CONT TestPartSizeForNAR/zero_stays_at_minimum280=== RUN TestFilterOversizedClosures/all_closures_skipped281=== CONT TestGetStorePathHash282--- PASS: TestDoWithRetry_BodyReplayedViaGetBody (0.03s)283=== CONT TestCaseHackSuffix284=== PAUSE TestPathInfoHashCompatibility/new_structured_format_with_sha512285=== CONT TestRunGarbageCollection_NotFoundAfterLocalRun286=== RUN TestSetClientTLS/rejects_connection_without_client_cert287=== CONT TestDoWithRetry_FinalResponseBodyReadable288=== PAUSE TestSetClientTLS/rejects_connection_without_client_cert289=== RUN TestSetClientTLS/succeeds_with_client_cert_and_CA290=== PAUSE TestSetClientTLS/succeeds_with_client_cert_and_CA291=== RUN TestSetClientTLS/preserves_debug_logging_transport292=== PAUSE TestSetClientTLS/preserves_debug_logging_transport293=== CONT TestSupersededNARStillUploadsListing/small_NAR294=== PAUSE TestFilterOversizedClosures/all_closures_skipped295=== CONT TestPartSizeForNAR/5_TiB_S3_max_object296=== CONT TestPartSizeForNAR/1_TiB297=== CONT TestPartSizeForNAR/115_GiB_needs_larger_parts298=== CONT TestPartSizeForNAR/small_stays_at_minimum299=== CONT TestSupersededNARStillUploadsListing/listing_upload_fails300=== RUN TestGetStorePathHash/valid_store_path301=== PAUSE TestGetStorePathHash/valid_store_path302=== RUN TestGetStorePathHash/basename_without_hyphen_should_error303=== PAUSE TestGetStorePathHash/basename_without_hyphen_should_error304=== RUN TestGetStorePathHash/hash_with_invalid_characters_should_error305=== PAUSE TestGetStorePathHash/hash_with_invalid_characters_should_error306=== RUN TestGetStorePathHash/hash_with_wrong_length_should_error307=== PAUSE TestGetStorePathHash/hash_with_wrong_length_should_error308=== CONT TestSupersededNARStillUploadsListing/dump_cut_short3092026/11/06 07:11:29 INFO Uploading abc-hello (1.0GB)310=== CONT TestPartSizeForNAR/capped_at_5_GiB311--- PASS: TestStreamPushReportsSignatures (0.00s)312--- PASS: TestShellSplit (0.00s)313--- PASS: TestResolveStorePath (0.02s)314--- PASS: TestShellSplitErrors (0.00s)315--- PASS: TestFileTokenEmpty (0.02s)316--- PASS: TestStreamPushStopsWhenCanceled (0.00s)317--- PASS: TestClientSignaturesByStorePath (0.00s)318--- PASS: TestStreamPushReportsEveryPath (0.00s)319--- PASS: TestScriptTokenEmptyToken (0.03s)320=== CONT TestConvertHashToNix32/invalid_format321=== CONT TestConvertHashToNix32/already_Nix32_format322=== CONT TestRateLimiterFeedback/429_enables_limiter3232026/11/06 07:11:29 INFO Uploading abc-hello (1.0GB)324=== CONT TestPartSizeForNAR/80_GiB_fits_at_minimum325--- PASS: TestPartSizeForNAR (0.02s)326 --- PASS: TestPartSizeForNAR/zero_stays_at_minimum (0.00s)327 --- PASS: TestPartSizeForNAR/5_TiB_S3_max_object (0.00s)328 --- PASS: TestPartSizeForNAR/1_TiB (0.00s)329 --- PASS: TestPartSizeForNAR/115_GiB_needs_larger_parts (0.00s)330 --- PASS: TestPartSizeForNAR/small_stays_at_minimum (0.00s)331 --- PASS: TestPartSizeForNAR/capped_at_5_GiB (0.00s)332 --- PASS: TestPartSizeForNAR/80_GiB_fits_at_minimum (0.00s)333=== CONT TestPathInfoCACompatibility/null_ca_field334=== CONT TestRateLimiterFeedback/400_does_not_enable_limiter3352026/11/06 07:11:29 INFO Garbage collection started3362026/11/06 07:11:29 WARN Rate limiter enabled after throttle name=server-test rate=53372026/11/06 07:11:29 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=429 url=http://127.0.0.1:543193382026/11/06 07:11:29 WARN Rate limiter enabled after throttle name=server-test rate=53392026/11/06 07:11:29 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:54311340=== CONT TestRateLimiterFeedback/200_does_not_enable_limiter3412026/11/06 07:11:29 WARN Rate limiter backed off name=server-test rate=53422026/11/06 07:11:29 WARN Rate limiter backed off name=server-test rate=5343=== CONT TestRateLimiterFeedback/503_enables_limiter344=== CONT TestConvertHashToNix32/SRI_format_to_Nix32345=== CONT TestPathInfoCACompatibility/old_string_format_-_fixed_recursive346=== CONT TestPathInfoCACompatibility/old_string_format_-_text347=== CONT TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths348=== CONT TestSetClientTLSErrors/missing_cert_file349=== CONT TestStreamPushBatchesUnderLoad/oneAtATime=false350--- PASS: TestStreamPushRequestLine (0.01s)351=== CONT TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths352=== CONT TestPathInfoCACompatibility/new_structured_format_-_nar_method353=== CONT TestSetClientTLSErrors/missing_ca_file354=== CONT TestSetClientTLSErrors/missing_key_file355=== CONT TestParsePathInfoJSON/Nix_format356--- PASS: TestConvertHashToNix32 (0.00s)357 --- PASS: TestConvertHashToNix32/invalid_format (0.00s)358 --- PASS: TestConvertHashToNix32/already_Nix32_format (0.00s)359 --- PASS: TestConvertHashToNix32/SRI_format_to_Nix32 (0.00s)360=== CONT TestPathInfoCACompatibility/new_structured_format_-_text361=== CONT TestParsePathInfoJSON/whitespace_only362=== CONT TestParsePathInfoJSON/invalid_JSON363=== CONT TestParsePathInfoJSON/empty_input364=== CONT TestParsePathInfoJSON/Lix_format365--- PASS: TestParsePathInfoJSON (0.00s)366 --- PASS: TestParsePathInfoJSON/Nix_format (0.00s)367 --- PASS: TestParsePathInfoJSON/whitespace_only (0.00s)368 --- PASS: TestParsePathInfoJSON/invalid_JSON (0.00s)369 --- PASS: TestParsePathInfoJSON/empty_input (0.00s)370 --- PASS: TestParsePathInfoJSON/Lix_format (0.00s)371=== CONT TestSetClientTLSErrors/invalid_ca_file3722026/11/06 07:11:29 WARN Request returned retryable status, retrying attempt=1 backoff=1ms status=502 url=http://127.0.0.1:54303373=== CONT TestEncodeNixBase32/empty_input374=== CONT TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)375=== CONT TestEncodeNixBase32/test_string_hash376--- PASS: TestEncodeNixBase32 (0.00s)377 --- PASS: TestEncodeNixBase32/empty_input (0.00s)378 --- PASS: TestEncodeNixBase32/test_string_hash (0.00s)379--- PASS: TestDoWithRetry_FinalResponseBodyReadable (0.01s)380--- PASS: TestPathInfoCACompatibility (0.00s)381 --- PASS: TestPathInfoCACompatibility/null_ca_field (0.00s)382 --- PASS: TestPathInfoCACompatibility/old_string_format_-_fixed_recursive (0.00s)383 --- PASS: TestPathInfoCACompatibility/old_string_format_-_text (0.00s)384 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_nar_method (0.00s)385 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_text (0.00s)386=== CONT TestStreamPushBatchesUnderLoad/oneAtATime=true387=== CONT TestGetStorePathHash/valid_store_path388=== CONT TestSetClientTLS/rejects_connection_without_client_cert389=== CONT TestFilterOversizedClosures/no_limit_keeps_everything390--- PASS: TestParsePathInfoJSONMultiplePaths (0.01s)391 --- PASS: TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths (0.00s)392 --- PASS: TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths (0.00s)393=== CONT TestGetStorePathHash/hash_with_wrong_length_should_error394=== CONT TestGetStorePathHash/basename_without_hyphen_should_error395=== CONT TestGetStorePathHash/hash_with_invalid_characters_should_error396--- PASS: TestGetStorePathHash (0.00s)397 --- PASS: TestGetStorePathHash/valid_store_path (0.00s)398 --- PASS: TestGetStorePathHash/hash_with_wrong_length_should_error (0.00s)399 --- PASS: TestGetStorePathHash/basename_without_hyphen_should_error (0.00s)400 --- PASS: TestGetStorePathHash/hash_with_invalid_characters_should_error (0.00s)4012026/11/06 07:11:29 WARN Rate limiter enabled after throttle name=s3-test rate=54022026/11/06 07:11:29 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:54376403--- PASS: TestUploadMultipart_SupersededByPeer (0.00s)404 --- PASS: TestUploadMultipart_SupersededByPeer/missing (0.01s)405 --- PASS: TestUploadMultipart_SupersededByPeer/exists (0.01s)406=== CONT TestSetClientTLS/preserves_debug_logging_transport407=== CONT TestPathInfoHashCompatibility/new_structured_format_with_sha512408=== CONT TestSetClientTLS/succeeds_with_client_cert_and_CA409--- PASS: TestStreamPushBatchesUnderLoad (0.00s)410 --- PASS: TestStreamPushBatchesUnderLoad/oneAtATime=false (0.00s)411 --- PASS: TestStreamPushBatchesUnderLoad/oneAtATime=true (0.00s)412=== CONT TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped4132026/11/06 07:11:29 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=2000414=== CONT TestFilterOversizedClosures/all_closures_skipped4152026/11/06 07:11:29 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=50416--- PASS: TestFilterOversizedClosures (0.00s)417 --- PASS: TestFilterOversizedClosures/no_limit_keeps_everything (0.00s)418 --- PASS: TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped (0.00s)419 --- PASS: TestFilterOversizedClosures/all_closures_skipped (0.00s)420--- PASS: TestRunGarbageCollection_NotFoundAfterLocalRun (0.01s)421=== CONT TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI422=== CONT TestPathInfoHashCompatibility/old_string_format_with_colon423--- PASS: TestPathInfoHashCompatibility (0.03s)424 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) (0.00s)425 --- PASS: TestPathInfoHashCompatibility/new_structured_format_with_sha512 (0.00s)426 --- PASS: TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI (0.00s)427 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_colon (0.00s)4282026/11/06 07:11:29 INFO Garbage collection started4292026/11/06 07:11:29 WARN Request returned retryable status, retrying attempt=2 backoff=1ms status=502 url=http://127.0.0.1:543034302026/11/06 07:11:29 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=04312026/11/06 07:11:29 WARN Request returned retryable status, retrying attempt=1 backoff=1ms status=502 url=http://127.0.0.1:543034322026/11/06 07:11:29 WARN Garbage collection finished on another replica. Its statistics are not available here433--- PASS: TestRunGarbageCollection_FinishedOnAnotherReplica (0.02s)4342026/11/06 07:11:29 WARN Rate limiter enabled after throttle name=server-test rate=54352026/11/06 07:11:29 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:543744362026/11/06 07:11:29 WARN Rate limiter backed off name=server-test rate=5437--- PASS: TestRateLimiterFeedback (0.00s)438 --- PASS: TestRateLimiterFeedback/400_does_not_enable_limiter (0.00s)439 --- PASS: TestRateLimiterFeedback/200_does_not_enable_limiter (0.00s)440 --- PASS: TestRateLimiterFeedback/429_enables_limiter (0.00s)441 --- PASS: TestRateLimiterFeedback/503_enables_limiter (0.01s)442--- PASS: TestSetClientTLSErrors (0.03s)443 --- PASS: TestSetClientTLSErrors/missing_cert_file (0.00s)444 --- PASS: TestSetClientTLSErrors/missing_ca_file (0.00s)445 --- PASS: TestSetClientTLSErrors/missing_key_file (0.00s)446 --- PASS: TestSetClientTLSErrors/invalid_ca_file (0.00s)4472026/11/06 07:11:29 WARN Request returned retryable status, retrying attempt=2 backoff=1ms status=502 url=http://127.0.0.1:543034482026/11/06 07:11:29 WARN Request returned retryable status, retrying attempt=3 backoff=1ms status=502 url=http://127.0.0.1:54303449--- PASS: TestUploadBuildLog_FileBodyReplayedOnRetry (0.03s)4502026/11/06 07:11:29 WARN Request returned retryable status, retrying attempt=4 backoff=1ms status=502 url=http://127.0.0.1:543034512026/11/06 07:11:29 WARN Request returned retryable status, retrying attempt=5 backoff=1ms status=502 url=http://127.0.0.1:543034522026/11/06 07:11:29 WARN Request returned retryable status, retrying attempt=6 backoff=1ms status=502 url=http://127.0.0.1:543034532026/11/06 07:11:29 WARN Request returned retryable status, retrying attempt=7 backoff=1ms status=502 url=http://127.0.0.1:543034542026/11/06 07:11:29 WARN Request returned retryable status, retrying attempt=8 backoff=1ms status=502 url=http://127.0.0.1:543034552026/11/06 07:11:29 WARN Request returned retryable status, retrying attempt=9 backoff=1ms status=502 url=http://127.0.0.1:543034562026/11/06 07:11:29 WARN Request returned retryable status, retrying attempt=10 backoff=1ms status=502 url=http://127.0.0.1:543034572026/11/06 07:11:29 WARN Request returned retryable status, retrying attempt=11 backoff=1ms status=502 url=http://127.0.0.1:543034582026/11/06 07:11:29 WARN Request returned retryable status, retrying attempt=12 backoff=1ms status=502 url=http://127.0.0.1:54303459--- PASS: TestRegisterUploadedObjectReusesConnections (0.05s)4602026/11/06 07:11:29 WARN Request returned retryable status, retrying attempt=13 backoff=1ms status=502 url=http://127.0.0.1:543034612026/11/06 07:11:29 WARN Request returned retryable status, retrying attempt=14 backoff=1ms status=502 url=http://127.0.0.1:543034622026/11/06 07:11:29 WARN Request returned retryable status, retrying attempt=15 backoff=1ms status=502 url=http://127.0.0.1:543034632026/11/06 07:11:29 WARN Request returned retryable status, retrying attempt=16 backoff=1ms status=502 url=http://127.0.0.1:543034642026/11/06 07:11:29 WARN Request returned retryable status, retrying attempt=17 backoff=1ms status=502 url=http://127.0.0.1:54303465--- PASS: TestRetryTimeoutOutlastsMaxRetries (0.06s)466--- PASS: TestScriptTokenCachesUntilRefresh (0.10s)467--- PASS: TestScriptTokenNoExpiryRerunsEveryCall (0.10s)468--- PASS: TestDumpPathSingleFile (0.12s)4692026/11/06 07:11:29 INFO Uploading abc-hello (1.0GB)470--- PASS: TestCaseHackSuffix (0.10s)471--- PASS: TestDumpPathWriterError (0.13s)4722026/11/06 07:11:29 WARN Request failed, retrying attempt=1 backoff=100ms error="Put \"http://127.0.0.1:54318/part/2\": uploading part 1: server returned 404: no such upload\n" url=http://127.0.0.1:54318/part/24732026/11/06 07:11:29 ERROR Failed to close zstd encoder error="io: read/write on closed pipe"4742026/11/06 07:11:29 http: TLS handshake error from 127.0.0.1:54394: remote error: tls: bad certificate475--- PASS: TestSetClientTLS (0.03s)476 --- PASS: TestSetClientTLS/preserves_debug_logging_transport (0.01s)477 --- PASS: TestSetClientTLS/succeeds_with_client_cert_and_CA (0.02s)478 --- PASS: TestSetClientTLS/rejects_connection_without_client_cert (0.11s)479--- PASS: TestDumpPathMatchesNix (0.17s)480--- PASS: TestUploadMultipart_PartsInParallel (0.62s)481--- PASS: TestSupersededNARStillUploadsListing (0.03s)482 --- PASS: TestSupersededNARStillUploadsListing/small_NAR (0.02s)483 --- PASS: TestSupersededNARStillUploadsListing/listing_upload_fails (0.02s)484 --- PASS: TestSupersededNARStillUploadsListing/dump_cut_short (0.61s)4852026/11/06 07:11:30 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:54289/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:54289/api/uploads/complete4862026/11/06 07:11:30 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"4872026/11/06 07:11:30 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:54289/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:54289/api/uploads/complete4882026/11/06 07:11:30 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"4892026/11/06 07:11:30 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:54289/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:54289/api/uploads/complete4902026/11/06 07:11:30 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"491--- PASS: TestRegisterUploadedObject_BoundedAgainstSilentServer (1.01s)492--- PASS: TestRateLimiterFeedback_400DoesNotCountAsSuccess (1.01s)493PASS494Running server tests...495The files belonging to this database system will be owned by user "_tribuchetbld4".496This user must also own the server process.497498The database cluster will be initialized with locale "C".499The default database encoding has accordingly been set to "SQL_ASCII".500The default text search configuration will be set to "english".501502Data page checksums are enabled.503504creating directory /private/var/tb/4/scratch/520ebb830df639a2/build/postgres1269923138/data ... ok505creating subdirectories ... ok506selecting dynamic shared memory implementation ... posix507selecting default "max_connections" ... 100508selecting default "shared_buffers" ... 128MB509selecting default time zone ... UTC510creating configuration files ... ok511running bootstrap script ... ok512performing post-bootstrap initialization ... ok513syncing data to disk ... ok514515initdb: warning: enabling "trust" authentication for local connections516initdb: 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.517518Success. You can now start the database server using:519520 pg_ctl -D /private/var/tb/4/scratch/520ebb830df639a2/build/postgres1269923138/data -l logfile start521522/private/var/tb/4/scratch/520ebb830df639a2/build/postgres1269923138:5432 - no response5232026-11-06 07:11:30.814 UTC [84905] LOG: starting PostgreSQL 18.6 on aarch64-apple-darwin25.6.0, compiled by clang version 21.1.8, 64-bit5242026-11-06 07:11:30.815 UTC [84905] LOG: listening on Unix socket "/private/var/tb/4/scratch/520ebb830df639a2/build/postgres1269923138/.s.PGSQL.5432"5252026-11-06 07:11:30.818 UTC [84912] LOG: database system was shut down at 2026-11-06 07:11:30 UTC5262026-11-06 07:11:30.819 UTC [84905] LOG: database system is ready to accept connections527/private/var/tb/4/scratch/520ebb830df639a2/build/postgres1269923138:5432 - accepting connections528{"timestamp":"2026-11-06T07:11:31.053493Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"d679a292-d64b-42dd-9fed-89d615cc8719","trace_id":"unknown","span_id":"unknown","peer_addr":"127.0.0.1","method":"GET","uri":"/health/ready","status_code":503,"suppressed_errors":0,"duration_ms":12,"result":"server_error","target":"rustfs::server::http","filename":"rustfs/src/server/layer.rs","line_number":502,"threadName":"rustfs-worker","threadId":"ThreadId(8)"}529{"timestamp":"2026-11-06T07:11:31.162638Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"6cbb71b4-90d6-4c70-b3d7-3173a38936d0","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(2)"}530{"timestamp":"2026-11-06T07:11:31.266277Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"5f4b018d-7bed-43a0-befa-9d297e4700b3","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(4)"}531=== RUN TestService_AuthMiddleware532=== PAUSE TestService_AuthMiddleware533=== RUN TestService_AuthMiddleware_MTLSProxyHeader534=== PAUSE TestService_AuthMiddleware_MTLSProxyHeader535=== RUN TestService_AuthMiddleware_MTLSBoundSubjects536=== PAUSE TestService_AuthMiddleware_MTLSBoundSubjects537=== RUN TestService_ReadAuthMiddleware538=== PAUSE TestService_ReadAuthMiddleware539=== RUN TestService_AuthMiddleware_OIDC540=== PAUSE TestService_AuthMiddleware_OIDC541=== RUN TestService_RequireScope_OIDC542=== PAUSE TestService_RequireScope_OIDC543=== RUN TestService_ReadScope_PublicByDefault544=== PAUSE TestService_ReadScope_PublicByDefault545=== RUN TestCacheConfigHandler546=== PAUSE TestCacheConfigHandler547=== RUN TestCacheStatsHandler548=== PAUSE TestCacheStatsHandler549=== RUN TestClientCADerivations550=== PAUSE TestClientCADerivations551=== RUN TestClientErrorHandling552=== PAUSE TestClientErrorHandling553=== RUN TestClientIntegration554=== PAUSE TestClientIntegration555=== RUN TestClientMultipleUploads556=== PAUSE TestClientMultipleUploads557=== RUN TestClientWithDependencies558=== PAUSE TestClientWithDependencies559=== RUN TestClientSharedPathCommittedMidPush560=== PAUSE TestClientSharedPathCommittedMidPush561=== RUN TestPinProtectsFromGC562=== PAUSE TestPinProtectsFromGC563=== RUN TestClientPushesUseOnePush564=== PAUSE TestClientPushesUseOnePush565=== RUN TestClientFallsBackToClosures566=== PAUSE TestClientFallsBackToClosures567=== RUN TestDeleteClosuresRacingPins568=== PAUSE TestDeleteClosuresRacingPins569=== RUN TestConcurrentCommitsSharingObjectsDoNotDeadlock570=== PAUSE TestConcurrentCommitsSharingObjectsDoNotDeadlock571=== RUN TestResolveDBConnectionString572=== PAUSE TestResolveDBConnectionString573=== RUN TestConnectWaitsForAPeerMigration574=== PAUSE TestConnectWaitsForAPeerMigration575=== RUN TestLeadElectsOneAndHandsOver576=== PAUSE TestLeadElectsOneAndHandsOver577=== RUN TestLeadIncumbentWinsAfterRestart5782026/11/06 07:11:31 INFO lead: acquired remote=192.0.2.1:12345792026/11/06 07:11:32 INFO lead: released remote=192.0.2.1:12345802026/11/06 07:11:32 INFO lead: acquired remote=192.0.2.1:12345812026/11/06 07:11:33 INFO lead: released remote=192.0.2.1:1234582--- PASS: TestLeadIncumbentWinsAfterRestart (1.90s)583=== RUN TestLeadIncumbentAnnouncesAtOnce584=== PAUSE TestLeadIncumbentAnnouncesAtOnce585=== RUN TestLeadEndsOnShutdown586=== PAUSE TestLeadEndsOnShutdown587=== RUN TestLeadEndsWhenItsConnectionHangs5882026/11/06 07:11:33 INFO lead: acquired remote=192.0.2.1:12345892026-11-06 07:11:34.825 UTC [84979] FATAL: terminating connection due to administrator command5902026/11/06 07:11:35 INFO lead: acquired remote=192.0.2.1:12345912026/11/06 07:11:36 WARN lead: lock connection lost error="timeout: context deadline exceeded"5922026/11/06 07:11:36 INFO lead: released remote=192.0.2.1:12345932026/11/06 07:11:36 INFO lead: released remote=192.0.2.1:1234594--- PASS: TestLeadEndsWhenItsConnectionHangs (2.95s)595=== RUN TestGCAdvisoryLockBlocksConcurrentRun596=== PAUSE TestGCAdvisoryLockBlocksConcurrentRun597=== RUN TestGCBugBareHashReferences598=== PAUSE TestGCBugBareHashReferences599=== RUN TestGCMetrics600=== PAUSE TestGCMetrics601=== RUN TestPushDedupSurvivesConcurrentGC602=== PAUSE TestPushDedupSurvivesConcurrentGC603=== RUN TestDeduplicatedObjectsRecordedAsPending604=== PAUSE TestDeduplicatedObjectsRecordedAsPending605=== RUN TestGCSweepSkipsPendingObjects606=== PAUSE TestGCSweepSkipsPendingObjects607=== RUN TestTombstonedObjectOfferedWithoutWaiting608=== PAUSE TestTombstonedObjectOfferedWithoutWaiting609=== RUN TestGCSweepDeliversEachKeyOnce610=== PAUSE TestGCSweepDeliversEachKeyOnce611=== RUN TestCreatePendingClosureVerifyS3FailureReleasesConnection612=== PAUSE TestCreatePendingClosureVerifyS3FailureReleasesConnection613=== RUN TestForceGCDuringPushOffersSweptObject614=== PAUSE TestForceGCDuringPushOffersSweptObject615=== RUN TestFailedS3DeleteKeepsTombstone616=== PAUSE TestFailedS3DeleteKeepsTombstone617=== RUN TestSweepSkipsRowsLockedByPush618=== PAUSE TestSweepSkipsRowsLockedByPush619=== RUN TestRegisterCompletedObjectNeedsPendingRow620=== PAUSE TestRegisterCompletedObjectNeedsPendingRow621=== RUN TestGetExistingObjectsLocksRows622=== PAUSE TestGetExistingObjectsLocksRows623=== RUN TestSweepRechecksPendingAfterLocking624=== PAUSE TestSweepRechecksPendingAfterLocking625=== RUN TestPushWaitsForSweepHoldingRow626=== PAUSE TestPushWaitsForSweepHoldingRow627=== RUN TestCommitRacingPendingCleanupKeepsObjects628=== PAUSE TestCommitRacingPendingCleanupKeepsObjects629=== RUN TestGCEndsOnShutdown630=== PAUSE TestGCEndsOnShutdown631=== RUN TestGCTaskStore_StartNew632=== PAUSE TestGCTaskStore_StartNew633=== RUN TestGCTaskStore_DeduplicateSameParams634=== PAUSE TestGCTaskStore_DeduplicateSameParams635=== RUN TestGCTaskStore_ConflictDifferentParams636=== PAUSE TestGCTaskStore_ConflictDifferentParams637=== RUN TestGCTaskStore_GetEmpty638=== PAUSE TestGCTaskStore_GetEmpty639=== RUN TestGCTaskStore_GetReturnsLatest640=== PAUSE TestGCTaskStore_GetReturnsLatest641=== RUN TestGCTaskStore_CompletedAllowsNewTask642=== PAUSE TestGCTaskStore_CompletedAllowsNewTask643=== RUN TestGCTaskStore_PhaseUpdates644=== PAUSE TestGCTaskStore_PhaseUpdates645=== RUN TestGCTaskStore_Fail646=== PAUSE TestGCTaskStore_Fail647=== RUN TestGracefulShutdownDrainsInflight648=== PAUSE TestGracefulShutdownDrainsInflight649=== RUN TestService_healthCheckHandler650=== PAUSE TestService_healthCheckHandler651=== RUN TestService_readinessHandler652=== PAUSE TestService_readinessHandler653=== RUN TestGenerateLandingPage654=== PAUSE TestGenerateLandingPage655=== RUN TestCacheConfigHandlerMaxNarSize656=== PAUSE TestCacheConfigHandlerMaxNarSize657=== RUN TestCreatePendingClosureRejectsOversizedNAR658=== PAUSE TestCreatePendingClosureRejectsOversizedNAR659=== RUN TestNARDeduplicationMetadataUploadBug660=== PAUSE TestNARDeduplicationMetadataUploadBug661=== RUN TestMetricsInventory662=== PAUSE TestMetricsInventory663=== RUN TestMetricsCommit664=== PAUSE TestMetricsCommit665=== RUN TestService_NativeMTLS666=== PAUSE TestService_NativeMTLS667=== RUN TestServerTLSConfig668=== PAUSE TestServerTLSConfig669=== RUN TestMultipartCleanup670=== PAUSE TestMultipartCleanup671=== RUN TestMultipartUploadAbortedWhenCancelledBeforeRecorded672=== PAUSE TestMultipartUploadAbortedWhenCancelledBeforeRecorded673=== RUN TestPendingCleanupUsesOneCutoff674=== PAUSE TestPendingCleanupUsesOneCutoff675=== RUN TestObjectStatsTrigger676=== PAUSE TestObjectStatsTrigger677=== RUN TestObjectStatsUpdatedOncePerCommit678=== PAUSE TestObjectStatsUpdatedOncePerCommit679=== RUN TestOrphanedObjectsGC680=== PAUSE TestOrphanedObjectsGC681=== RUN TestOrphanedObjectsGCStressTest682=== PAUSE TestOrphanedObjectsGCStressTest683=== RUN TestCreatePin_ReservedPins684=== PAUSE TestCreatePin_ReservedPins685=== RUN TestPresentReportsOnlyClosureRoots686=== PAUSE TestPresentReportsOnlyClosureRoots687=== RUN TestPresentRefreshesOnlyStaleClosures688=== PAUSE TestPresentRefreshesOnlyStaleClosures689=== RUN TestPresentNotReportedWhileGCDeletesClosure690=== PAUSE TestPresentNotReportedWhileGCDeletesClosure691=== RUN TestParseSingleRange692=== PAUSE TestParseSingleRange693=== RUN TestProxyHeadersOnlyTrustedOnSocket6942026/11/06 07:11:36 INFO Starting HTTP server address=127.0.0.1:544706952026/11/06 07:11:36 INFO Starting HTTP server address=proxy.sock6962026/11/06 07:11:36 WARN mTLS auth: subject not in bound subjects subject="CN=someone"6972026/11/06 07:11:36 INFO Shutdown signal received, draining in-flight requests timeout=10s698--- PASS: TestProxyHeadersOnlyTrustedOnSocket (0.16s)699=== RUN TestIsValidCachePath700=== PAUSE TestIsValidCachePath701=== RUN TestReadProxyNarinfo702=== PAUSE TestReadProxyNarinfo703=== RUN TestReadProxyNarinfoAlreadyDecompressed704=== PAUSE TestReadProxyNarinfoAlreadyDecompressed705=== RUN TestReadProxyContentNegotiation706=== PAUSE TestReadProxyContentNegotiation707=== RUN TestReadProxyNarStreaming708=== PAUSE TestReadProxyNarStreaming709=== RUN TestReadProxy404710=== PAUSE TestReadProxy404711=== RUN TestReadProxyInvalidPath712=== PAUSE TestReadProxyInvalidPath713=== RUN TestReadProxyHead714=== PAUSE TestReadProxyHead715=== RUN TestReadProxyOutlastsServerWriteTimeout716=== PAUSE TestReadProxyOutlastsServerWriteTimeout717=== RUN TestReadProxyConditionalGet718=== PAUSE TestReadProxyConditionalGet719=== RUN TestReadProxyRootRedirectsToIndexHTML720=== PAUSE TestReadProxyRootRedirectsToIndexHTML721=== RUN TestReadProxyDisabled722=== PAUSE TestReadProxyDisabled723=== RUN TestReadRedirectNar724=== PAUSE TestReadRedirectNar725=== RUN TestReadRedirectKeepsNarinfoProxied726=== PAUSE TestReadRedirectKeepsNarinfoProxied727=== RUN TestReadProxyRangeRequest728=== PAUSE TestReadProxyRangeRequest729=== RUN TestReadRedirectUsesPublicS3URL730=== PAUSE TestReadRedirectUsesPublicS3URL731=== RUN TestPush_OverlappingRootsStoreOneRowPerKey732=== PAUSE TestPush_OverlappingRootsStoreOneRowPerKey733=== RUN TestPush_CompleteCommitsEveryRoot734=== PAUSE TestPush_CompleteCommitsEveryRoot735=== RUN TestPush_RepeatedRootCommitsOnce736=== PAUSE TestPush_RepeatedRootCommitsOnce737=== RUN TestPush_CompleteWaitsForCleanupOfThePush738=== PAUSE TestPush_CompleteWaitsForCleanupOfThePush739=== RUN TestPush_RootsAreLockedInByteOrder740=== PAUSE TestPush_RootsAreLockedInByteOrder741=== RUN TestPush_SkippedKeySurvivesGCBeforeCommit742=== PAUSE TestPush_SkippedKeySurvivesGCBeforeCommit743=== RUN TestPush_RejectsBadRequests744=== PAUSE TestPush_RejectsBadRequests745=== RUN TestPush_SignsNarinfosOfItsPendingObjects746=== PAUSE TestPush_SignsNarinfosOfItsPendingObjects747=== RUN TestRedundantMultipartUpload748=== PAUSE TestRedundantMultipartUpload749=== RUN TestCompleteMultipartUpload_ErrorButObjectExists750=== PAUSE TestCompleteMultipartUpload_ErrorButObjectExists751=== RUN TestCompletedNarNotReofferedAcrossClosures752=== PAUSE TestCompletedNarNotReofferedAcrossClosures753=== RUN TestPresignedUploadRegisteredBeforeCommit754=== PAUSE TestPresignedUploadRegisteredBeforeCommit755=== RUN TestService_Rustfstest756=== PAUSE TestService_Rustfstest757=== RUN TestParseSize758=== PAUSE TestParseSize759=== RUN TestSkippedUploadsHandler760=== PAUSE TestSkippedUploadsHandler761=== RUN TestSystemdListenerNotActivated762--- PASS: TestSystemdListenerNotActivated (0.00s)763=== RUN TestWatchdogBeatsWhenHealthy764--- PASS: TestWatchdogBeatsWhenHealthy (0.03s)765=== RUN TestWatchdogSkipsWhenUnhealthy7662026/11/06 07:11:36 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7672026/11/06 07:11:36 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7682026/11/06 07:11:36 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7692026/11/06 07:11:36 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7702026/11/06 07:11:36 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7712026/11/06 07:11:36 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7722026/11/06 07:11:36 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7732026/11/06 07:11:36 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7742026/11/06 07:11:36 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7752026/11/06 07:11:36 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"776--- PASS: TestWatchdogSkipsWhenUnhealthy (0.20s)777=== RUN TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle778=== PAUSE TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle779=== RUN TestProxyWriteTimeout780=== PAUSE TestProxyWriteTimeout781=== RUN TestPendingClosureWriteTimeout782=== PAUSE TestPendingClosureWriteTimeout783=== RUN TestIsValidUploadKey784=== PAUSE TestIsValidUploadKey785=== RUN TestUploadHandlersRejectInvalidKeys786=== PAUSE TestUploadHandlersRejectInvalidKeys787=== RUN TestUploadHandlersRejectOversizedBody788=== PAUSE TestUploadHandlersRejectOversizedBody789=== RUN TestService_cleanupPendingClosuresHandler790=== PAUSE TestService_cleanupPendingClosuresHandler791=== RUN TestService_createPendingClosureHandler792=== PAUSE TestService_createPendingClosureHandler793=== RUN TestService_verifyS3Integrity794=== PAUSE TestService_verifyS3Integrity795=== RUN TestService_verifyS3ReuploadsStaleNarinfo796=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo797=== RUN TestCompleteMultipartUnregistered798=== PAUSE TestCompleteMultipartUnregistered799=== RUN TestCreatePendingClosure_SmallNARUsesSimplePUT800=== PAUSE TestCreatePendingClosure_SmallNARUsesSimplePUT801=== CONT TestPush_SignsNarinfosOfItsPendingObjects802=== CONT TestGCTaskStore_CompletedAllowsNewTask803=== CONT TestPresentNotReportedWhileGCDeletesClosure804=== CONT TestReadProxyRangeRequest805=== CONT TestService_AuthMiddleware806=== CONT TestParseSingleRange807=== RUN TestParseSingleRange/none808=== CONT TestGCTaskStore_PhaseUpdates809=== PAUSE TestParseSingleRange/none810=== CONT TestCreatePin_ReservedPins811--- PASS: TestGCTaskStore_CompletedAllowsNewTask (0.00s)812--- PASS: TestGCTaskStore_PhaseUpdates (0.00s)813=== RUN TestParseSingleRange/unknown_unit814=== CONT TestPush_SkippedKeySurvivesGCBeforeCommit815=== PAUSE TestParseSingleRange/unknown_unit816=== CONT TestPush_CompleteWaitsForCleanupOfThePush817=== RUN TestParseSingleRange/multi-range_ignored818=== PAUSE TestParseSingleRange/multi-range_ignored819=== RUN TestParseSingleRange/malformed_no_dash820=== PAUSE TestParseSingleRange/malformed_no_dash821=== CONT TestPush_RootsAreLockedInByteOrder822=== CONT TestPush_CompleteCommitsEveryRoot823=== CONT TestPush_OverlappingRootsStoreOneRowPerKey824=== CONT TestReadRedirectUsesPublicS3URL825=== CONT TestGCTaskStore_GetReturnsLatest826--- PASS: TestGCTaskStore_GetReturnsLatest (0.00s)827=== CONT TestOrphanedObjectsGCStressTest828=== CONT TestGCTaskStore_GetEmpty829--- PASS: TestGCTaskStore_GetEmpty (0.00s)830=== CONT TestSweepRechecksPendingAfterLocking831=== CONT TestGCTaskStore_ConflictDifferentParams832--- PASS: TestGCTaskStore_ConflictDifferentParams (0.00s)833=== CONT TestGetExistingObjectsLocksRows834=== CONT TestGCTaskStore_DeduplicateSameParams835=== CONT TestGCTaskStore_StartNew836--- PASS: TestGCTaskStore_DeduplicateSameParams (0.00s)837--- PASS: TestGCTaskStore_StartNew (0.00s)838=== CONT TestGCEndsOnShutdown839=== RUN TestPresentNotReportedWhileGCDeletesClosure/stale840=== CONT TestCommitRacingPendingCleanupKeepsObjects841=== CONT TestPushWaitsForSweepHoldingRow842=== CONT TestPresentRefreshesOnlyStaleClosures843=== CONT TestPresentReportsOnlyClosureRoots844=== CONT TestPush_RejectsBadRequests845=== CONT TestPush_RepeatedRootCommitsOnce846=== RUN TestParseSingleRange/malformed_both_empty847=== PAUSE TestPresentNotReportedWhileGCDeletesClosure/stale848=== RUN TestGCEndsOnShutdown/before_the_run849=== PAUSE TestGCEndsOnShutdown/before_the_run850=== RUN TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete851=== PAUSE TestParseSingleRange/malformed_both_empty852=== RUN TestParseSingleRange/malformed_end_before_start853=== PAUSE TestParseSingleRange/malformed_end_before_start854=== RUN TestParseSingleRange/closed855=== PAUSE TestParseSingleRange/closed856=== RUN TestParseSingleRange/open-ended857=== RUN TestPresentNotReportedWhileGCDeletesClosure/fresh858=== PAUSE TestPresentNotReportedWhileGCDeletesClosure/fresh859=== CONT TestRegisterCompletedObjectNeedsPendingRow860=== CONT TestOrphanedObjectsGC861=== PAUSE TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete862=== RUN TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark863=== PAUSE TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark864=== PAUSE TestParseSingleRange/open-ended865=== CONT TestObjectStatsUpdatedOncePerCommit866=== RUN TestParseSingleRange/end_clamped_to_size867=== PAUSE TestParseSingleRange/end_clamped_to_size868=== RUN TestParseSingleRange/suffix869=== PAUSE TestParseSingleRange/suffix870=== RUN TestParseSingleRange/suffix_exceeds_size871=== PAUSE TestParseSingleRange/suffix_exceeds_size872=== RUN TestParseSingleRange/single_byte873=== PAUSE TestParseSingleRange/single_byte874=== RUN TestParseSingleRange/start_past_EOF875=== PAUSE TestParseSingleRange/start_past_EOF876=== RUN TestParseSingleRange/start_far_past_EOF877=== PAUSE TestParseSingleRange/start_far_past_EOF878=== CONT TestSweepSkipsRowsLockedByPush879=== CONT TestObjectStatsTrigger8802026/11/06 07:11:36 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:54472/oidc881--- PASS: TestReadRedirectUsesPublicS3URL (1.30s)882=== CONT TestPendingCleanupUsesOneCutoff8832026/11/06 07:11:38 INFO Aborted multipart uploads count=0 kept=08842026/11/06 07:11:38 WARN Force mode enabled - objects will be deleted immediately without grace period8852026/11/06 07:11:38 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=08862026/11/06 07:11:38 INFO Vacuumed table table=pending_closures8872026/11/06 07:11:38 INFO Received push request method=POST path=/api/pushes8882026/11/06 07:11:38 INFO Vacuumed table table=pending_objects8892026/11/06 07:11:38 INFO Vacuumed table table=multipart_uploads8902026/11/06 07:11:38 INFO Vacuumed table table=closures8912026/11/06 07:11:38 INFO Vacuumed table table=objects892--- PASS: TestCommitRacingPendingCleanupKeepsObjects (2.11s)893=== CONT TestFailedS3DeleteKeepsTombstone8942026/11/06 07:11:38 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign8952026/11/06 07:11:38 INFO Signed narinfos id=1 count=18962026/11/06 07:11:38 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign8972026/11/06 07:11:38 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign8982026/11/06 07:11:38 ERROR Failed to sign narinfos signer="index 1" error="signing key cannot be nil"8992026/11/06 07:11:38 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign9002026/11/06 07:11:38 ERROR Failed to sign narinfos signer=niks3-test-1 error="signer failed"9012026/11/06 07:11:38 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign9022026/11/06 07:11:38 ERROR Signer returned unexpected signature count signer=niks3-test-1 got=0 want=19032026/11/06 07:11:38 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign9042026/11/06 07:11:38 ERROR Signer returned unexpected object key signer=niks3-test-1 object_key=unexpected.narinfo905--- PASS: TestPush_SignsNarinfosOfItsPendingObjects (2.17s)906=== CONT TestForceGCDuringPushOffersSweptObject907=== RUN TestForceGCDuringPushOffersSweptObject/before_pending_rows908=== PAUSE TestForceGCDuringPushOffersSweptObject/before_pending_rows909=== RUN TestForceGCDuringPushOffersSweptObject/after_presence_check910=== PAUSE TestForceGCDuringPushOffersSweptObject/after_presence_check911=== CONT TestCreatePendingClosureVerifyS3FailureReleasesConnection9122026/11/06 07:11:38 INFO Received push request method=POST path=/api/pushes9132026/11/06 07:11:39 INFO Received complete push request method=POST path=/api/pushes/1/complete9142026/11/06 07:11:39 INFO Completed push id=1 objects=4 duration=36.633459ms915--- PASS: TestPush_RepeatedRootCommitsOnce (2.44s)916=== CONT TestGCSweepDeliversEachKeyOnce9172026/11/06 07:11:39 WARN Authentication failed token_preview=wrongtoken token_length=10 reason="static API token mismatch"918--- PASS: TestService_AuthMiddleware (2.61s)919=== CONT TestTombstonedObjectOfferedWithoutWaiting920--- PASS: TestReadProxyRangeRequest (2.97s)921=== CONT TestMultipartUploadAbortedWhenCancelledBeforeRecorded9222026/11/06 07:11:39 INFO Received push request method=POST path=/api/pushes923=== NAME TestOrphanedObjectsGC924 orphaned_objects_gc_test.go:287: GC Test Summary:925 orphaned_objects_gc_test.go:288: - Kept: 2 objects from closure A926 orphaned_objects_gc_test.go:289: - Deleted: 2 objects from closure B927 orphaned_objects_gc_test.go:290: - Deleted: 6 orphaned chain objects (X1->X2->X3)928 orphaned_objects_gc_test.go:291: - Deleted: 2 orphaned single objects (Y)929 orphaned_objects_gc_test.go:292: - Total deleted: 10 objects930--- PASS: TestOrphanedObjectsGC (3.38s)931=== CONT TestGCSweepSkipsPendingObjects9322026/11/06 07:11:40 INFO Received complete push request method=POST path=/api/pushes/1/complete9332026/11/06 07:11:40 INFO Completed push id=1 objects=6 duration=36.037417ms934--- PASS: TestPush_CompleteCommitsEveryRoot (3.59s)935=== CONT TestMultipartCleanup9362026/11/06 07:11:40 INFO Aborted multipart uploads count=0 kept=09372026/11/06 07:11:40 WARN Force mode enabled - objects will be deleted immediately without grace period9382026/11/06 07:11:40 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=09392026/11/06 07:11:40 INFO Vacuumed table table=pending_closures9402026/11/06 07:11:40 INFO Vacuumed table table=pending_objects9412026/11/06 07:11:40 INFO Vacuumed table table=multipart_uploads9422026/11/06 07:11:40 INFO Vacuumed table table=closures9432026/11/06 07:11:40 INFO Vacuumed table table=objects944--- PASS: TestSweepRechecksPendingAfterLocking (3.86s)945=== CONT TestDeduplicatedObjectsRecordedAsPending9462026/11/06 07:11:40 INFO Received push request method=POST path=/api/pushes9472026-11-06 07:11:40.690 UTC [85089] ERROR: could not obtain lock on row in relation "closures"9482026-11-06 07:11:40.690 UTC [85089] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT9492026-11-06 07:11:40.696 UTC [85089] ERROR: could not obtain lock on row in relation "closures"9502026-11-06 07:11:40.696 UTC [85089] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT9512026-11-06 07:11:40.697 UTC [85089] ERROR: could not obtain lock on row in relation "closures"9522026-11-06 07:11:40.697 UTC [85089] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT9532026-11-06 07:11:40.704 UTC [85089] ERROR: could not obtain lock on row in relation "closures"9542026-11-06 07:11:40.704 UTC [85089] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT9552026-11-06 07:11:40.704 UTC [85089] ERROR: could not obtain lock on row in relation "closures"9562026-11-06 07:11:40.704 UTC [85089] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT957--- PASS: TestPush_RootsAreLockedInByteOrder (4.09s)958=== CONT TestServerTLSConfig959=== RUN TestServerTLSConfig/no_client_CA960=== PAUSE TestServerTLSConfig/no_client_CA961=== RUN TestServerTLSConfig/missing_CA_file962=== PAUSE TestServerTLSConfig/missing_CA_file963=== RUN TestServerTLSConfig/not_a_PEM_file964=== PAUSE TestServerTLSConfig/not_a_PEM_file965=== CONT TestPushDedupSurvivesConcurrentGC966--- PASS: TestRegisterCompletedObjectNeedsPendingRow (4.23s)967=== CONT TestService_NativeMTLS9682026/11/06 07:11:41 INFO Received push request method=POST path=/api/pushes969--- PASS: TestPush_OverlappingRootsStoreOneRowPerKey (4.61s)970=== CONT TestGCMetrics971=== RUN TestPush_RejectsBadRequests/root_not_in_objects972=== PAUSE TestPush_RejectsBadRequests/root_not_in_objects973=== RUN TestPush_RejectsBadRequests/no_roots974=== PAUSE TestPush_RejectsBadRequests/no_roots975=== RUN TestPush_RejectsBadRequests/no_objects976=== PAUSE TestPush_RejectsBadRequests/no_objects977=== RUN TestPush_RejectsBadRequests/bad_root978=== PAUSE TestPush_RejectsBadRequests/bad_root979=== CONT TestGCBugBareHashReferences9802026/11/06 07:11:41 INFO Received push request method=POST path=/api/pushes9812026/11/06 07:11:41 INFO Received complete push request method=POST path=/api/pushes/1/complete9822026/11/06 07:11:41 INFO Completed push id=1 objects=4 duration=41.243625ms9832026/11/06 07:11:41 INFO Received push request method=POST path=/api/pushes9842026/11/06 07:11:41 INFO Aborted multipart uploads count=0 kept=09852026/11/06 07:11:42 WARN Force mode enabled - objects will be deleted immediately without grace period9862026/11/06 07:11:42 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=09872026/11/06 07:11:42 INFO Vacuumed table table=pending_closures9882026/11/06 07:11:42 INFO Vacuumed table table=pending_objects9892026/11/06 07:11:42 INFO Vacuumed table table=multipart_uploads9902026/11/06 07:11:42 INFO Received uploads request method=POST path=/api/pending_closures9912026/11/06 07:11:42 INFO Vacuumed table table=closures9922026/11/06 07:11:42 INFO Vacuumed table table=objects9932026/11/06 07:11:42 INFO Received complete push request method=POST path=/api/pushes/2/complete9942026/11/06 07:11:42 INFO Completed push id=2 objects=4 duration=11.851208ms995--- PASS: TestPush_SkippedKeySurvivesGCBeforeCommit (5.52s)996=== CONT TestGCAdvisoryLockBlocksConcurrentRun997--- PASS: TestObjectStatsUpdatedOncePerCommit (5.91s)998=== CONT TestLeadEndsOnShutdown999--- PASS: TestPushWaitsForSweepHoldingRow (5.97s)1000=== CONT TestMetricsCommit10012026/11/06 07:11:42 INFO Received push request method=POST path=/api/pushes10022026/11/06 07:11:42 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux10032026/11/06 07:11:42 WARN Refused reserved pin name=worker-x86_64-linux10042026/11/06 07:11:42 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux10052026/11/06 07:11:42 INFO Received create pin request method=POST path=/api/pins/my-app10062026/11/06 07:11:42 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux1007--- PASS: TestCreatePin_ReservedPins (6.35s)1008=== CONT TestLeadIncumbentAnnouncesAtOnce10092026-11-06 07:11:43.076 UTC [85121] ERROR: Push does not exist: id=110102026-11-06 07:11:43.076 UTC [85121] CONTEXT: PL/pgSQL function commit_push(bigint) line 11 at RAISE10112026-11-06 07:11:43.076 UTC [85121] STATEMENT: SELECT commit_push($1)1012--- PASS: TestPush_CompleteWaitsForCleanupOfThePush (6.46s)1013=== CONT TestMetricsInventory10142026/11/06 07:11:43 INFO Aborted multipart uploads count=0 kept=010152026/11/06 07:11:43 WARN Force mode enabled - objects will be deleted immediately without grace period10162026/11/06 07:11: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=010172026/11/06 07:11:43 INFO Vacuumed table table=pending_closures10182026/11/06 07:11:43 INFO Vacuumed table table=pending_objects10192026/11/06 07:11:43 INFO Vacuumed table table=multipart_uploads10202026/11/06 07:11:43 INFO Vacuumed table table=closures10212026/11/06 07:11:43 INFO Vacuumed table table=objects10222026/11/06 07:11:43 INFO Aborted multipart uploads count=0 kept=010232026/11/06 07:11:43 WARN Force mode enabled - objects will be deleted immediately without grace period1024--- PASS: TestPresentReportsOnlyClosureRoots (6.92s)1025=== CONT TestLeadElectsOneAndHandsOver10262026/11/06 07:11:43 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=010272026/11/06 07:11:43 INFO Vacuumed table table=pending_closures10282026/11/06 07:11:43 INFO Vacuumed table table=pending_objects10292026/11/06 07:11:43 INFO Vacuumed table table=multipart_uploads10302026/11/06 07:11:43 INFO Vacuumed table table=closures10312026/11/06 07:11:43 INFO Vacuumed table table=objects1032--- PASS: TestSweepSkipsRowsLockedByPush (7.03s)1033=== CONT TestNARDeduplicationMetadataUploadBug1034--- PASS: TestGetExistingObjectsLocksRows (7.20s)1035=== CONT TestConnectWaitsForAPeerMigration1036--- PASS: TestPresentRefreshesOnlyStaleClosures (7.48s)1037=== CONT TestCreatePendingClosureRejectsOversizedNAR10382026/11/06 07:11:44 INFO Received uploads request method=POST path=/api/pending_closures1039--- PASS: TestCreatePendingClosureRejectsOversizedNAR (0.00s)1040=== CONT TestResolveDBConnectionString1041=== RUN TestResolveDBConnectionString/flag_wins1042=== PAUSE TestResolveDBConnectionString/flag_wins1043=== RUN TestResolveDBConnectionString/file_when_flag_empty1044=== PAUSE TestResolveDBConnectionString/file_when_flag_empty1045=== RUN TestResolveDBConnectionString/missing_file_is_an_error1046=== PAUSE TestResolveDBConnectionString/missing_file_is_an_error1047=== RUN TestResolveDBConnectionString/PGHOST_allows_empty1048=== PAUSE TestResolveDBConnectionString/PGHOST_allows_empty1049=== RUN TestResolveDBConnectionString/nothing_configured1050=== PAUSE TestResolveDBConnectionString/nothing_configured1051=== CONT TestCacheConfigHandlerMaxNarSize1052--- PASS: TestCacheConfigHandlerMaxNarSize (0.00s)1053=== CONT TestConcurrentCommitsSharingObjectsDoNotDeadlock1054--- PASS: TestObjectStatsTrigger (7.82s)1055=== CONT TestGenerateLandingPage1056--- PASS: TestGenerateLandingPage (0.00s)1057=== CONT TestDeleteClosuresRacingPins10582026/11/06 07:11:44 INFO Received uploads request method=POST path=/api/pending_closures10592026/11/06 07:11:44 INFO Received uploads request method=POST path=/api/pending_closures10602026/11/06 07:11:44 INFO Received cleanup request method=DELETE path=/api/pending_closures10612026/11/06 07:11:45 INFO Received uploads request method=POST path=/api/pending_closures10622026/11/06 07:11:45 INFO Aborted multipart uploads count=0 kept=010632026/11/06 07:11:45 WARN Force mode enabled - objects will be deleted immediately without grace period10642026/11/06 07:11:45 ERROR failed to remove object object=nar/dddddddddddddddddddddddddddddddddddddddddddddddddddd.nar.zst error="Access Denied."10652026/11/06 07:11:45 ERROR failed to remove object object=dddddddddddddddddddddddddddddddd.narinfo error="Access Denied."1066--- PASS: TestFailedS3DeleteKeepsTombstone (6.63s)1067=== CONT TestService_readinessHandler10682026/11/06 07:11:45 INFO Received uploads request method=POST path=/api/pending_closures1069--- PASS: TestCreatePendingClosureVerifyS3FailureReleasesConnection (6.83s)1070=== CONT TestService_healthCheckHandler10712026/11/06 07:11:45 INFO Aborted multipart uploads count=0 kept=010722026/11/06 07:11:45 WARN Force mode enabled - objects will be deleted immediately without grace period10732026/11/06 07:11:46 INFO Received uploads request method=POST path=/api/pending_closures1074--- PASS: TestTombstonedObjectOfferedWithoutWaiting (6.85s)1075=== CONT TestGracefulShutdownDrainsInflight10762026/11/06 07:11:46 INFO Starting HTTP server address=127.0.0.1:5456810772026/11/06 07:11:46 INFO Shutdown signal received, draining in-flight requests timeout=10s1078--- PASS: TestGracefulShutdownDrainsInflight (0.08s)1079=== CONT TestGCTaskStore_Fail1080--- PASS: TestGCTaskStore_Fail (0.00s)1081=== CONT TestClientCADerivations10822026/11/06 07:11:46 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=010832026/11/06 07:11:46 INFO Vacuumed table table=pending_closures10842026/11/06 07:11:46 INFO Received uploads request method=POST path=/api/pending_closures10852026/11/06 07:11:46 INFO Vacuumed table table=pending_objects10862026/11/06 07:11:46 INFO Vacuumed table table=multipart_uploads10872026/11/06 07:11:46 INFO Vacuumed table table=closures10882026/11/06 07:11:46 INFO Vacuumed table table=objects1089--- PASS: TestGCSweepDeliversEachKeyOnce (7.36s)1090=== CONT TestPendingClosureWriteTimeout1091=== RUN TestPendingClosureWriteTimeout/empty1092=== PAUSE TestPendingClosureWriteTimeout/empty1093=== RUN TestPendingClosureWriteTimeout/400_objects1094=== PAUSE TestPendingClosureWriteTimeout/400_objects1095=== RUN TestPendingClosureWriteTimeout/670k_objects1096=== PAUSE TestPendingClosureWriteTimeout/670k_objects1097=== RUN TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline1098=== PAUSE TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline1099=== CONT TestCreatePendingClosure_SmallNARUsesSimplePUT1100--- PASS: TestMultipartUploadAbortedWhenCancelledBeforeRecorded (6.99s)1101=== CONT TestCompleteMultipartUnregistered11022026/11/06 07:11:46 INFO Received uploads request method=POST path=/api/pending_closures11032026/11/06 07:11:46 INFO Aborted multipart uploads count=0 kept=011042026/11/06 07:11:46 WARN Force mode enabled - objects will be deleted immediately without grace period11052026/11/06 07:11: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=011062026/11/06 07:11:46 INFO Vacuumed table table=pending_closures11072026/11/06 07:11:46 INFO Vacuumed table table=pending_objects11082026/11/06 07:11:46 INFO Vacuumed table table=multipart_uploads11092026/11/06 07:11:46 INFO Vacuumed table table=closures11102026/11/06 07:11:47 INFO Vacuumed table table=objects11112026/11/06 07:11:47 INFO Received uploads request method=POST path=/api/pending_closures1112--- PASS: TestGCSweepSkipsPendingObjects (7.04s)1113=== CONT TestService_verifyS3ReuploadsStaleNarinfo1114=== RUN TestService_verifyS3ReuploadsStaleNarinfo/lost,_other_NAR_pushed1115=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo/lost,_other_NAR_pushed1116=== RUN TestService_verifyS3ReuploadsStaleNarinfo/intact,_other_NAR_pushed1117=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo/intact,_other_NAR_pushed1118=== RUN TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost1119=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost1120=== RUN TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost,_second_pushed1121=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost,_second_pushed1122=== RUN TestService_verifyS3ReuploadsStaleNarinfo/lost,_same_NAR_pushed1123=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo/lost,_same_NAR_pushed1124=== CONT TestService_verifyS3Integrity11252026/11/06 07:11:47 INFO Received cleanup request method=DELETE path=/api/pending_closures11262026/11/06 07:11:47 WARN Failed to abort upload, keeping its closure key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst error="Get \"http://127.0.0.1:1/bucket35/?location=\": dial tcp 127.0.0.1:1: connect: connection refused" code=""11272026/11/06 07:11:47 INFO Aborted multipart uploads count=0 kept=111282026/11/06 07:11:47 INFO Received cleanup request method=DELETE path=/api/pending_closures11292026/11/06 07:11:47 INFO Aborted multipart uploads count=1 kept=01130--- PASS: TestMultipartCleanup (7.06s)1131=== CONT TestService_createPendingClosureHandler11322026/11/06 07:11:47 INFO Received uploads request method=POST path=/api/pending_closures1133--- PASS: TestDeduplicatedObjectsRecordedAsPending (6.86s)1134=== CONT TestService_cleanupPendingClosuresHandler11352026/11/06 07:11:47 INFO Received uploads request method=POST path=/api/pending_closures11362026/11/06 07:11:47 INFO Aborted multipart uploads count=0 kept=011372026/11/06 07:11:47 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=1 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=011382026/11/06 07:11:47 INFO Vacuumed table table=pending_closures11392026/11/06 07:11:47 WARN mTLS auth: subject not in bound subjects subject="CN=reader"11402026/11/06 07:11:47 WARN mTLS auth: subject not in bound subjects subject="CN=reader"1141--- PASS: TestService_NativeMTLS (7.03s)1142=== CONT TestUploadHandlersRejectOversizedBody11432026/11/06 07:11:47 INFO Vacuumed table table=pending_objects11442026/11/06 07:11:47 INFO Vacuumed table table=multipart_uploads11452026/11/06 07:11:47 INFO Vacuumed table table=closures11462026/11/06 07:11:47 INFO Vacuumed table table=objects11472026/11/06 07:11:47 INFO Aborted multipart uploads count=0 kept=011482026/11/06 07:11:47 WARN Force mode enabled - objects will be deleted immediately without grace period11492026/11/06 07:11:47 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=011502026/11/06 07:11:47 INFO Vacuumed table table=pending_closures11512026/11/06 07:11:47 INFO Vacuumed table table=pending_objects11522026/11/06 07:11:47 INFO Vacuumed table table=multipart_uploads11532026/11/06 07:11:47 INFO Vacuumed table table=closures11542026/11/06 07:11:47 INFO Vacuumed table table=objects1155--- PASS: TestPushDedupSurvivesConcurrentGC (7.28s)1156=== CONT TestUploadHandlersRejectInvalidKeys1157=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info1158=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info1159=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal1160=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal1161=== RUN TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key1162=== PAUSE TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key1163=== RUN TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key1164=== PAUSE TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key1165=== CONT TestIsValidUploadKey1166=== RUN TestIsValidUploadKey/narinfo1167=== PAUSE TestIsValidUploadKey/narinfo1168=== RUN TestIsValidUploadKey/nar_zst1169=== PAUSE TestIsValidUploadKey/nar_zst1170=== RUN TestIsValidUploadKey/nar_xz1171=== PAUSE TestIsValidUploadKey/nar_xz1172=== RUN TestIsValidUploadKey/nar_plain1173=== PAUSE TestIsValidUploadKey/nar_plain1174=== RUN TestIsValidUploadKey/listing1175=== PAUSE TestIsValidUploadKey/listing1176=== RUN TestIsValidUploadKey/build_log1177=== PAUSE TestIsValidUploadKey/build_log1178=== RUN TestIsValidUploadKey/build_log_home-manager_file1179=== PAUSE TestIsValidUploadKey/build_log_home-manager_file1180=== RUN TestIsValidUploadKey/build_log_plus_in_name1181=== PAUSE TestIsValidUploadKey/build_log_plus_in_name1182=== RUN TestIsValidUploadKey/build_log_question_mark1183=== PAUSE TestIsValidUploadKey/build_log_question_mark1184=== RUN TestIsValidUploadKey/build_log_equals1185=== PAUSE TestIsValidUploadKey/build_log_equals1186=== RUN TestIsValidUploadKey/realisation1187=== PAUSE TestIsValidUploadKey/realisation1188=== RUN TestIsValidUploadKey/realisation_plus_in_output1189=== PAUSE TestIsValidUploadKey/realisation_plus_in_output1190=== RUN TestIsValidUploadKey/nix-cache-info1191=== PAUSE TestIsValidUploadKey/nix-cache-info1192=== RUN TestIsValidUploadKey/index.html1193=== PAUSE TestIsValidUploadKey/index.html1194=== RUN TestIsValidUploadKey/narinfo_key,_nar_type1195=== PAUSE TestIsValidUploadKey/narinfo_key,_nar_type1196=== RUN TestIsValidUploadKey/nar_key,_narinfo_type1197=== PAUSE TestIsValidUploadKey/nar_key,_narinfo_type1198=== RUN TestIsValidUploadKey/listing_key,_narinfo_type1199=== PAUSE TestIsValidUploadKey/listing_key,_narinfo_type1200=== RUN TestIsValidUploadKey/traversal1201=== PAUSE TestIsValidUploadKey/traversal1202=== RUN TestIsValidUploadKey/traversal_nar1203=== PAUSE TestIsValidUploadKey/traversal_nar1204=== RUN TestIsValidUploadKey/absolute1205=== PAUSE TestIsValidUploadKey/absolute1206=== RUN TestIsValidUploadKey/empty_key1207=== PAUSE TestIsValidUploadKey/empty_key1208=== RUN TestIsValidUploadKey/unknown_type1209=== PAUSE TestIsValidUploadKey/unknown_type1210=== CONT TestClientWithDependencies1211=== RUN TestUploadHandlersRejectOversizedBody/complete_multipart1212=== PAUSE TestUploadHandlersRejectOversizedBody/complete_multipart1213=== RUN TestUploadHandlersRejectOversizedBody/request_more_parts1214=== PAUSE TestUploadHandlersRejectOversizedBody/request_more_parts1215=== RUN TestUploadHandlersRejectOversizedBody/create_pending_closure1216=== PAUSE TestUploadHandlersRejectOversizedBody/create_pending_closure1217=== CONT TestClientPushesUseOnePush12182026/11/06 07:11:48 INFO Aborted multipart uploads count=0 kept=012192026/11/06 07:11:48 WARN Force mode enabled - objects will be deleted immediately without grace period12202026/11/06 07:11:48 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=012212026/11/06 07:11:48 INFO Vacuumed table table=pending_closures12222026/11/06 07:11:48 INFO Vacuumed table table=pending_objects12232026/11/06 07:11:48 INFO Vacuumed table table=multipart_uploads12242026/11/06 07:11:48 INFO Vacuumed table table=closures12252026/11/06 07:11:48 INFO Vacuumed table table=objects1226--- PASS: TestGCMetrics (6.96s)1227=== CONT TestClientMultipleUploads1228--- PASS: TestGCBugBareHashReferences (7.19s)1229=== CONT TestClientIntegration12302026/11/06 07:11:48 ERROR failed to check GC advisory lock error="query pg_locks: failed to connect to `user=_tribuchetbld4 database=niks3`: /nonexistent/.s.PGSQL.5432 (/nonexistent): dial error: dial unix /nonexistent/.s.PGSQL.5432: connect: no such file or directory"1231--- PASS: TestGCAdvisoryLockBlocksConcurrentRun (6.49s)1232=== CONT TestClientErrorHandling1233=== RUN TestClientErrorHandling/InvalidStorePath1234=== PAUSE TestClientErrorHandling/InvalidStorePath1235=== RUN TestClientErrorHandling/InvalidAuthToken1236=== PAUSE TestClientErrorHandling/InvalidAuthToken1237=== RUN TestClientErrorHandling/ServerNotAvailable1238=== PAUSE TestClientErrorHandling/ServerNotAvailable1239=== CONT TestPinProtectsFromGC12402026/11/06 07:11:48 INFO lead: acquired remote=192.0.2.1:123412412026/11/06 07:11:49 INFO Received push request method=POST path=/api/pushes12422026/11/06 07:11:49 INFO Received complete push request method=POST path=/api/pushes/1/complete12432026/11/06 07:11:49 INFO Completed push id=1 objects=4 duration=43.227375ms12442026/11/06 07:11:49 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete12452026/11/06 07:11:49 INFO Completed upload id=2 objects=2 duration=2.348916ms1246--- PASS: TestMetricsCommit (6.71s)1247=== CONT TestClientSharedPathCommittedMidPush12482026/11/06 07:11:49 INFO lead: acquired remote=192.0.2.1:123412492026/11/06 07:11:49 INFO lead: released remote=192.0.2.1:12341250--- PASS: TestLeadIncumbentAnnouncesAtOnce (6.42s)1251=== CONT TestService_Rustfstest1252=== NAME TestOrphanedObjectsGCStressTest1253 orphaned_objects_gc_test.go:422: Created 10 active closures, 5 to-delete closures, 20 orphaned chains1254 orphaned_objects_gc_test.go:440: Marked 210 objects for deletion1255--- PASS: TestMetricsInventory (6.59s)1256=== CONT TestReadProxyHead12572026/11/06 07:11:49 INFO lead: released remote=192.0.2.1:12341258--- PASS: TestLeadEndsOnShutdown (7.36s)1259=== CONT TestProxyWriteTimeout1260=== RUN TestProxyWriteTimeout/narinfo1261=== PAUSE TestProxyWriteTimeout/narinfo1262=== RUN TestProxyWriteTimeout/1_GiB_nar1263=== PAUSE TestProxyWriteTimeout/1_GiB_nar1264=== RUN TestProxyWriteTimeout/10_GiB_nar1265=== PAUSE TestProxyWriteTimeout/10_GiB_nar1266=== RUN TestProxyWriteTimeout/unknown_size1267=== PAUSE TestProxyWriteTimeout/unknown_size1268=== CONT TestReadRedirectKeepsNarinfoProxied12692026/11/06 07:11:50 INFO lead: acquired remote=192.0.2.1:12341270=== NAME TestNARDeduplicationMetadataUploadBug1271 metadata_upload_test.go:48: First store path: /private/var/tb/4/scratch/520ebb830df639a2/build/TestNARDeduplicationMetadataUploadBug1306617331/001/store/dd3b7d242xdnpprqfymdzaq82jcp9kba-file1.txt12722026/11/06 07:11:50 INFO Received push request method=POST path=/api/pushes12732026/11/06 07:11:50 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)12742026/11/06 07:11:50 INFO Uploading dd3b7d242xdnpprqfymdzaq82jcp9kba-file1.txt (160B)12752026/11/06 07:11:50 WARN Failed to register uploaded object key=dd3b7d242xdnpprqfymdzaq82jcp9kba.ls error="server returned 404: 404 page not found\n"12762026/11/06 07:11:50 WARN Failed to register uploaded object key=nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst error="server returned 404: 404 page not found\n"12772026/11/06 07:11:50 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign12782026/11/06 07:11:50 INFO Signed narinfos id=1 count=112792026/11/06 07:11:50 INFO Uploading 1 narinfos12802026/11/06 07:11:50 INFO Received complete push request method=POST path=/api/pushes/1/complete12812026/11/06 07:11:50 WARN Failed to register uploaded object key=dd3b7d242xdnpprqfymdzaq82jcp9kba.narinfo error="server returned 404: 404 page not found\n"12822026/11/06 07:11:50 INFO Completed push id=1 objects=3 duration=23.639ms12832026/11/06 07:11:50 INFO Upload complete. (307ms)1284 metadata_upload_test.go:54: Retrieved narinfo from S3:1285 StorePath: /private/var/tb/4/scratch/520ebb830df639a2/build/TestNARDeduplicationMetadataUploadBug1306617331/001/store/dd3b7d242xdnpprqfymdzaq82jcp9kba-file1.txt1286 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1287 Compression: zstd1288 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1289 NarSize: 1601290 References: 1291 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1292 metadata_upload_test.go:55: Retrieved .ls file from S3 (compressed size: 77 bytes)1293 metadata_upload_test.go:55: Decompressed .ls content (64 bytes):1294 {"version":1,"root":{"type":"regular","size":44,"narOffset":96}}1295 metadata_upload_test.go:64: Second store path (same content): /private/var/tb/4/scratch/520ebb830df639a2/build/TestNARDeduplicationMetadataUploadBug1306617331/001/store/75ib44z4wfysc60qyrfgdir1avf0473l-file2.txt12962026/11/06 07:11:50 INFO Received push request method=POST path=/api/pushes12972026/11/06 07:11:50 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)12982026/11/06 07:11:50 INFO Aborted multipart uploads count=1 kept=012992026/11/06 07:11:50 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign13002026/11/06 07:11:50 WARN Failed to register uploaded object key=75ib44z4wfysc60qyrfgdir1avf0473l.ls error="server returned 404: 404 page not found\n"13012026/11/06 07:11:50 INFO Signed narinfos id=2 count=113022026/11/06 07:11:50 INFO Uploading 1 narinfos13032026/11/06 07:11:50 INFO Received cleanup request method=DELETE path=/api/pending_closures13042026/11/06 07:11:50 INFO Aborted multipart uploads count=1 kept=01305--- PASS: TestPendingCleanupUsesOneCutoff (13.05s)1306=== CONT TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle13072026/11/06 07:11:50 INFO Received complete push request method=POST path=/api/pushes/2/complete13082026/11/06 07:11:50 WARN Failed to register uploaded object key=75ib44z4wfysc60qyrfgdir1avf0473l.narinfo error="server returned 404: 404 page not found\n"13092026/11/06 07:11:50 INFO Completed push id=2 objects=3 duration=1.38825ms13102026/11/06 07:11:51 INFO Upload complete. (172ms)1311=== NAME TestNARDeduplicationMetadataUploadBug1312 metadata_upload_test.go:76: Retrieved narinfo from S3:1313 StorePath: /private/var/tb/4/scratch/520ebb830df639a2/build/TestNARDeduplicationMetadataUploadBug1306617331/001/store/75ib44z4wfysc60qyrfgdir1avf0473l-file2.txt1314 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1315 Compression: zstd1316 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1317 NarSize: 1601318 References: 1319 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1320 metadata_upload_test.go:77: Retrieved .ls file from S3 (compressed size: 62 bytes)1321 metadata_upload_test.go:77: Decompressed .ls content (49 bytes):1322 {"version":1,"root":{"type":"regular","size":44}}1323--- PASS: TestNARDeduplicationMetadataUploadBug (7.38s)1324=== CONT TestReadRedirectNar13252026/11/06 07:11:51 WARN readiness check failed error="closed pool"1326--- PASS: TestService_readinessHandler (5.72s)1327=== CONT TestSkippedUploadsHandler13282026/11/06 07:11:51 INFO Client skipped oversized paths paths=3 nar_bytes=50000000001329--- PASS: TestSkippedUploadsHandler (0.00s)1330=== CONT TestReadProxyDisabled1331--- PASS: TestConnectWaitsForAPeerMigration (7.58s)1332=== CONT TestParseSize1333--- PASS: TestParseSize (0.00s)1334=== CONT TestReadProxyRootRedirectsToIndexHTML13352026/11/06 07:11:51 INFO lead: released remote=192.0.2.1:12341336--- PASS: TestService_healthCheckHandler (5.82s)1337=== CONT TestReadProxyContentNegotiation13382026/11/06 07:11:51 INFO lead: acquired remote=192.0.2.1:12341339--- PASS: TestConcurrentCommitsSharingObjectsDoNotDeadlock (7.66s)1340=== CONT TestReadProxyInvalidPath13412026/11/06 07:11:52 INFO Received uploads request method=POST path=/api/pending_closures1342--- PASS: TestCreatePendingClosure_SmallNARUsesSimplePUT (5.75s)1343=== CONT TestReadProxyConditionalGet1344=== NAME TestClientCADerivations1345 client_ca_test.go:136: Built CA derivation: /private/var/tb/4/scratch/520ebb830df639a2/build/TestClientCADerivations2862094404/001/store/hwcbhvbxpgl1dnx345xyclm82r7vlib7-ca-test13462026/11/06 07:11:52 INFO Received complete multipart upload request method=POST path=/api/multipart/complete13472026/11/06 07:11:52 ERROR Failed to get multipart upload error="no rows in result set" upload_id=does-not-exist object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst1348--- PASS: TestCompleteMultipartUnregistered (5.81s)1349=== CONT TestReadProxy4041350=== NAME TestClientCADerivations1351 client_ca_test.go:139: Found 1 dependencies (including self)13522026/11/06 07:11:52 INFO lead: released remote=192.0.2.1:12341353--- PASS: TestLeadElectsOneAndHandsOver (8.99s)1354=== CONT TestReadProxyOutlastsServerWriteTimeout13552026/11/06 07:11:52 INFO Received push request method=POST path=/api/pushes13562026/11/06 07:11:52 INFO Received uploads request method=POST path=/api/pending_closures13572026/11/06 07:11:52 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)13582026/11/06 07:11:52 INFO Uploading hwcbhvbxpgl1dnx345xyclm82r7vlib7-ca-test (144B)13592026/11/06 07:11:52 WARN Failed to register uploaded object key=nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst error="server returned 404: 404 page not found\n"13602026/11/06 07:11:52 WARN Failed to register uploaded object key=hwcbhvbxpgl1dnx345xyclm82r7vlib7.ls error="server returned 404: 404 page not found\n"13612026/11/06 07:11:52 WARN Failed to register uploaded object key=log/rg3c9936rn06m5fw0qg7c6929iik9zp0-ca-test.drv error="server returned 404: 404 page not found\n"13622026/11/06 07:11:52 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign13632026/11/06 07:11:52 INFO Signed narinfos id=1 count=113642026/11/06 07:11:52 INFO Uploading 1 narinfos13652026/11/06 07:11:52 INFO Received complete push request method=POST path=/api/pushes/1/complete13662026/11/06 07:11:52 WARN Failed to register uploaded object key=hwcbhvbxpgl1dnx345xyclm82r7vlib7.narinfo error="server returned 404: 404 page not found\n"13672026/11/06 07:11:52 INFO Completed push id=1 objects=4 duration=34.535ms13682026/11/06 07:11:52 INFO Upload complete. (418ms)1369=== NAME TestClientCADerivations1370 client_ca_test.go:180: Narinfo contains CA field: StorePath: /private/var/tb/4/scratch/520ebb830df639a2/build/TestClientCADerivations2862094404/001/store/hwcbhvbxpgl1dnx345xyclm82r7vlib7-ca-test1371 URL: nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst1372 Compression: zstd1373 NarHash: sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1374 NarSize: 1441375 References: 1376 Deriver: /private/var/tb/4/scratch/520ebb830df639a2/build/TestClientCADerivations2862094404/001/store/rg3c9936rn06m5fw0qg7c6929iik9zp0-ca-test.drv1377 CA: fixed:r:sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1378 client_ca_test.go:185: Checking for realisation files in S3...1379 client_ca_test.go:207: No realisation files uploaded - this is expected for locally built CA derivations1380 client_ca_test.go:208: Locally built CA derivations don't have DrvOutput IDs until they're substituted from a cache13812026/11/06 07:11:53 INFO Received uploads request method=POST path=/api/pending_closures1382 client_ca_test.go:258: nix copy output: error: binary cache 's3://bucket52?endpoint=http://localhost:54435®ion=eu-west-1' is for Nix stores with prefix '/nix/store', not '/private/var/tb/4/scratch/520ebb830df639a2/build/TestClientCADerivations2862094404/001/store'1383 client_ca_test.go:259: nix copy failed (might be expected with isolated stores): exit status 113842026/11/06 07:11:53 INFO Received uploads request method=POST path=/api/pending_closures13852026/11/06 07:11:53 INFO Received uploads request method=POST path=/api/pending_closures1386--- PASS: TestClientCADerivations (6.98s)1387=== CONT TestCompletedNarNotReofferedAcrossClosures13882026/11/06 07:11:53 INFO Received cleanup request method=DELETE path=/api/pending_closures13892026/11/06 07:11:53 INFO Aborted multipart uploads count=0 kept=013902026/11/06 07:11:53 INFO Received uploads request method=POST path=/api/pending_closures13912026/11/06 07:11:53 INFO Received cleanup request method=DELETE path=/api/pending_closures13922026/11/06 07:11:53 INFO Aborted multipart uploads count=1 kept=013932026/11/06 07:11:53 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete13942026-11-06 07:11:53.663 UTC [85192] ERROR: Closure does not exist: id=113952026-11-06 07:11:53.663 UTC [85192] CONTEXT: PL/pgSQL function commit_pending_closure(bigint) line 13 at RAISE13962026-11-06 07:11:53.663 UTC [85192] STATEMENT: -- name: CommitPendingClosure :one1397 SELECT commit_pending_closure($1::bigint)::bigint1398 1399--- PASS: TestService_cleanupPendingClosuresHandler (6.31s)1400=== CONT TestReadProxyNarStreaming1401=== NAME TestClientWithDependencies1402 client_integration_test.go:660: Built derivation: /private/var/tb/4/scratch/520ebb830df639a2/build/TestClientWithDependencies1602418402/001/store/xqwljx8a8m1jbnyvgbc97m77rj9nsz9p-test-script1403 client_integration_test.go:662: Found 1 dependencies (including self)14042026/11/06 07:11:54 INFO Received complete multipart upload request method=POST path=/api/multipart/complete14052026/11/06 07:11:54 INFO Received push request method=POST path=/api/pushes14062026/11/06 07:11:54 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)14072026/11/06 07:11:54 INFO Uploading xqwljx8a8m1jbnyvgbc97m77rj9nsz9p-test-script (136B)14082026/11/06 07:11:54 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst upload_id=ZmU1YTU2N2ItYWZhNS00YzBlLTk1ZWEtN2VjYjM0N2E0OWRlLjA5ODdiYThjLTc3YzQtNDRhOS1hY2FlLTljMjkwYTRlZmFhMHgxNzkzOTQ5MTEyNzY1ODQwMDAw parts=1014092026/11/06 07:11:54 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete14102026/11/06 07:11:55 WARN Failed to register uploaded object key=log/6mrrqjxy803vwxcd7b14hk1cqfb52zmk-test-script.drv error="server returned 404: 404 page not found\n"14112026/11/06 07:11:55 WARN Failed to register uploaded object key=xqwljx8a8m1jbnyvgbc97m77rj9nsz9p.ls error="server returned 404: 404 page not found\n"14122026/11/06 07:11:55 INFO Completed upload id=1 objects=2 duration=86.401625ms14132026/11/06 07:11:55 INFO Received uploads request method=POST path=/api/pending_closures14142026/11/06 07:11:55 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign14152026/11/06 07:11:55 WARN Failed to register uploaded object key=nar/1s7yghixzpinyqm7g59kyn3sav81pmnsdi5v63m6x4r2vacy907j.nar.zst error="server returned 404: 404 page not found\n"14162026/11/06 07:11:55 INFO Received uploads request method=POST path=/api/pending_closures14172026/11/06 07:11:55 INFO Signed narinfos id=1 count=114182026/11/06 07:11:55 INFO Object in database but missing from S3 key=dadb44fdadb44fdadb44fdadb44f0000.narinfo14192026/11/06 07:11:55 WARN Found objects in DB but missing from S3, will re-upload count=114202026/11/06 07:11:55 INFO Uploading 1 narinfos1421--- PASS: TestService_verifyS3Integrity (8.00s)1422=== CONT TestReadProxyNarinfo14232026/11/06 07:11:55 INFO Received complete push request method=POST path=/api/pushes/1/complete14242026/11/06 07:11:55 WARN Failed to register uploaded object key=xqwljx8a8m1jbnyvgbc97m77rj9nsz9p.narinfo error="server returned 404: 404 page not found\n"14252026/11/06 07:11:55 INFO Completed push id=1 objects=4 duration=43.688042ms14262026/11/06 07:11:55 INFO Upload complete. (473ms)1427=== NAME TestClientWithDependencies1428 client_integration_test.go:664: Skipping nix copy test - isolated store (/private/var/tb/4/scratch/520ebb830df639a2/build/TestClientWithDependencies1602418402/001/store) requires matching store prefix14292026/11/06 07:11:55 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1430=== NAME TestClientMultipleUploads1431 client_integration_test.go:405: Created store path 0: /private/var/tb/4/scratch/520ebb830df639a2/build/TestClientMultipleUploads1851833113/001/store/ycmfffix29jyj68vxs5a0k41ryanfxvk-test-file-0.txt1432--- PASS: TestClientWithDependencies (7.26s)14332026/11/06 07:11:55 INFO Received push request method=POST path=/api/pushes1434=== CONT TestPresignedUploadRegisteredBeforeCommit14352026/11/06 07:11:55 INFO Completed multipart upload object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst upload_id=ZmU1YTU2N2ItYWZhNS00YzBlLTk1ZWEtN2VjYjM0N2E0OWRlLjg3NTZiNzJmLTg0YTItNGFmOC04YWVlLTFhMjE3YWYwY2UxYXgxNzkzOTQ5MTEzMTEyNzYyMDAw parts=1014362026/11/06 07:11:55 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete14372026/11/06 07:11:55 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)14382026/11/06 07:11:55 INFO Uploading 8m31m3alsyiv1ixyb8pfv65w89r07hfg-b (256B)14392026/11/06 07:11:55 INFO Uploading j4ixbkdisgqfdb22dm0dn0726ydshgv7-shared-dep (136B)1440=== NAME TestClientMultipleUploads1441 client_integration_test.go:405: Created store path 1: /private/var/tb/4/scratch/520ebb830df639a2/build/TestClientMultipleUploads1851833113/001/store/gjf9p9a29bbr5vcp34fja0d1s52wri1d-test-file-1.txt14422026/11/06 07:11:55 WARN Failed to register uploaded object key=07glj0kiz01rfqmymbwkblffj7q6vqfw.ls error="server returned 404: 404 page not found\n"14432026/11/06 07:11:55 WARN Failed to register uploaded object key=8m31m3alsyiv1ixyb8pfv65w89r07hfg.ls error="server returned 404: 404 page not found\n"14442026/11/06 07:11:55 WARN Failed to register uploaded object key=nar/0g3sxlsbjn6yfny3g7jqngzd4mdpag1kwdam17jm19ynajzg7dhj.nar.zst error="server returned 404: 404 page not found\n"14452026/11/06 07:11:55 WARN Failed to register uploaded object key=j4ixbkdisgqfdb22dm0dn0726ydshgv7.ls error="server returned 404: 404 page not found\n"14462026/11/06 07:11:55 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign14472026/11/06 07:11:55 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"14482026/11/06 07:11:55 INFO Signed narinfos id=1 count=314492026/11/06 07:11:55 INFO Uploading 3 narinfos14502026/11/06 07:11:55 INFO Completed upload id=1 objects=2 duration=150.442541ms14512026/11/06 07:11:55 INFO Received get closure request method=GET path=/api/closures/0000000000000000000000000000000014522026/11/06 07:11:55 INFO Received uploads request method=POST path=/api/pending_closures14532026/11/06 07:11:55 INFO Starting cleanup of old closures method=DELETE path=/api/closures14542026/11/06 07:11:55 INFO Aborted multipart uploads count=0 kept=014552026/11/06 07:11:55 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=014562026/11/06 07:11:55 WARN Failed to register uploaded object key=07glj0kiz01rfqmymbwkblffj7q6vqfw.narinfo error="server returned 404: 404 page not found\n"14572026/11/06 07:11:55 WARN Failed to register uploaded object key=8m31m3alsyiv1ixyb8pfv65w89r07hfg.narinfo error="server returned 404: 404 page not found\n"14582026/11/06 07:11:55 INFO Received complete push request method=POST path=/api/pushes/1/complete14592026/11/06 07:11:55 WARN Failed to register uploaded object key=j4ixbkdisgqfdb22dm0dn0726ydshgv7.narinfo error="server returned 404: 404 page not found\n"14602026/11/06 07:11:55 INFO Vacuumed table table=pending_closures14612026/11/06 07:11:55 INFO Completed push id=1 objects=8 duration=34.86975ms14622026/11/06 07:11:55 INFO Upload complete. (483ms)1463=== NAME TestClientPushesUseOnePush1464 client_pushes_test.go:97: Retrieved narinfo from S3:1465 StorePath: /private/var/tb/4/scratch/520ebb830df639a2/build/TestClientPushesUseOnePush1445777879/001/store/j4ixbkdisgqfdb22dm0dn0726ydshgv7-shared-dep1466 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1467 Compression: zstd1468 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821469 NarSize: 1361470 References: 1471 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1472 client_pushes_test.go:97: Retrieved narinfo from S3:1473 StorePath: /private/var/tb/4/scratch/520ebb830df639a2/build/TestClientPushesUseOnePush1445777879/001/store/07glj0kiz01rfqmymbwkblffj7q6vqfw-a1474 URL: nar/0g3sxlsbjn6yfny3g7jqngzd4mdpag1kwdam17jm19ynajzg7dhj.nar.zst1475 Compression: zstd1476 NarHash: sha256:0g3sxlsbjn6yfny3g7jqngzd4mdpag1kwdam17jm19ynajzg7dhj1477 NarSize: 2561478 References: /private/var/tb/4/scratch/520ebb830df639a2/build/TestClientPushesUseOnePush1445777879/001/store/j4ixbkdisgqfdb22dm0dn0726ydshgv7-shared-dep1479 CA: text:sha256:04rgl2p05d1nmga5vvqbq75yr46d0bj9ra1q24q00kxmdy6laq1f1480 client_pushes_test.go:97: Retrieved narinfo from S3:1481 StorePath: /private/var/tb/4/scratch/520ebb830df639a2/build/TestClientPushesUseOnePush1445777879/001/store/8m31m3alsyiv1ixyb8pfv65w89r07hfg-b1482 URL: nar/0g3sxlsbjn6yfny3g7jqngzd4mdpag1kwdam17jm19ynajzg7dhj.nar.zst1483 Compression: zstd1484 NarHash: sha256:0g3sxlsbjn6yfny3g7jqngzd4mdpag1kwdam17jm19ynajzg7dhj1485 NarSize: 2561486 References: /private/var/tb/4/scratch/520ebb830df639a2/build/TestClientPushesUseOnePush1445777879/001/store/j4ixbkdisgqfdb22dm0dn0726ydshgv7-shared-dep1487 CA: text:sha256:04rgl2p05d1nmga5vvqbq75yr46d0bj9ra1q24q00kxmdy6laq1f1488=== NAME TestClientMultipleUploads1489 client_integration_test.go:405: Created store path 2: /private/var/tb/4/scratch/520ebb830df639a2/build/TestClientMultipleUploads1851833113/001/store/031gfy4kdsshf02p8k952di0l3srd9c1-test-file-2.txt14902026/11/06 07:11:55 INFO Vacuumed table table=pending_objects14912026/11/06 07:11:55 INFO Vacuumed table table=multipart_uploads14922026/11/06 07:11:55 INFO Vacuumed table table=closures1493--- PASS: TestClientPushesUseOnePush (7.74s)14942026/11/06 07:11:55 INFO Received push request method=POST path=/api/pushes1495=== CONT TestReadProxyNarinfoAlreadyDecompressed14962026/11/06 07:11:55 INFO Vacuumed table table=objects14972026/11/06 07:11:55 INFO Received get closure request method=GET path=/api/closures/0000000000000000000000000000000014982026/11/06 07:11:55 INFO Uploading 3 paths to 127.0.0.1 (0 already cached)14992026/11/06 07:11:55 INFO Uploading ycmfffix29jyj68vxs5a0k41ryanfxvk-test-file-0.txt (160B)15002026/11/06 07:11:55 INFO Uploading gjf9p9a29bbr5vcp34fja0d1s52wri1d-test-file-1.txt (160B)15012026/11/06 07:11:55 INFO Uploading 031gfy4kdsshf02p8k952di0l3srd9c1-test-file-2.txt (160B)1502--- PASS: TestService_createPendingClosureHandler (8.56s)1503=== CONT TestIsValidCachePath1504=== RUN TestIsValidCachePath/narinfo1505=== PAUSE TestIsValidCachePath/narinfo1506=== RUN TestIsValidCachePath/narinfo_all_nix_base32_chars1507=== PAUSE TestIsValidCachePath/narinfo_all_nix_base32_chars1508=== RUN TestIsValidCachePath/nar_zst1509=== PAUSE TestIsValidCachePath/nar_zst1510=== RUN TestIsValidCachePath/nar_xz1511=== PAUSE TestIsValidCachePath/nar_xz1512=== RUN TestIsValidCachePath/nar_bz21513=== PAUSE TestIsValidCachePath/nar_bz21514=== RUN TestIsValidCachePath/nar_uncompressed1515=== PAUSE TestIsValidCachePath/nar_uncompressed1516=== RUN TestIsValidCachePath/ls1517=== PAUSE TestIsValidCachePath/ls1518=== RUN TestIsValidCachePath/log1519=== PAUSE TestIsValidCachePath/log1520=== RUN TestIsValidCachePath/realisation1521=== PAUSE TestIsValidCachePath/realisation1522=== RUN TestIsValidCachePath/nix-cache-info1523=== PAUSE TestIsValidCachePath/nix-cache-info1524=== RUN TestIsValidCachePath/index.html1525=== PAUSE TestIsValidCachePath/index.html1526=== RUN TestIsValidCachePath/traversal_parent1527=== PAUSE TestIsValidCachePath/traversal_parent1528=== RUN TestIsValidCachePath/traversal_in_middle1529=== PAUSE TestIsValidCachePath/traversal_in_middle1530=== RUN TestIsValidCachePath/invalid_char_e1531=== PAUSE TestIsValidCachePath/invalid_char_e1532=== RUN TestIsValidCachePath/invalid_char_u1533=== PAUSE TestIsValidCachePath/invalid_char_u1534=== RUN TestIsValidCachePath/random_path1535=== PAUSE TestIsValidCachePath/random_path1536=== RUN TestIsValidCachePath/empty1537=== PAUSE TestIsValidCachePath/empty1538=== RUN TestIsValidCachePath/leading_slash1539=== PAUSE TestIsValidCachePath/leading_slash1540=== RUN TestIsValidCachePath/wrong_extension1541=== PAUSE TestIsValidCachePath/wrong_extension15422026/11/06 07:11:55 WARN Failed to register uploaded object key=ycmfffix29jyj68vxs5a0k41ryanfxvk.ls error="server returned 404: 404 page not found\n"1543=== NAME TestClientIntegration1544 client_integration_test.go:291: Created store path: /private/var/tb/4/scratch/520ebb830df639a2/build/TestClientIntegration3810632103/002/store/13707a1ilhj1l2hg3bjywhh6ib2jrzaz-test-file.txt1545=== RUN TestIsValidCachePath/short_hash1546=== PAUSE TestIsValidCachePath/short_hash15472026/11/06 07:11:55 WARN Failed to register uploaded object key=nar/0ahq3izw3h0b0c08p3xdfclh758fwxnp85ccvflasb4vnfsv50ri.nar.zst error="server returned 404: 404 page not found\n"1548=== CONT TestService_ReadAuthMiddleware15492026/11/06 07:11:55 WARN Failed to register uploaded object key=nar/13p9pqi0ga6fx2apcwls9hjnv7nmf740ggpn5zvfzdsp5vz2bbg4.nar.zst error="server returned 404: 404 page not found\n"15502026/11/06 07:11:55 WARN Failed to register uploaded object key=gjf9p9a29bbr5vcp34fja0d1s52wri1d.ls error="server returned 404: 404 page not found\n"15512026/11/06 07:11:55 WARN Failed to register uploaded object key=nar/1823g6vx4q5zqvr73m7lkq1wpk40fin7bsc792di430yk7sg4lka.nar.zst error="server returned 404: 404 page not found\n"15522026/11/06 07:11:55 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign15532026/11/06 07:11:55 WARN Failed to register uploaded object key=031gfy4kdsshf02p8k952di0l3srd9c1.ls error="server returned 404: 404 page not found\n"15542026/11/06 07:11:55 INFO Signed narinfos id=1 count=315552026/11/06 07:11:55 INFO Uploading 3 narinfos15562026/11/06 07:11:56 WARN Failed to register uploaded object key=031gfy4kdsshf02p8k952di0l3srd9c1.narinfo error="server returned 404: 404 page not found\n"15572026/11/06 07:11:56 WARN Failed to register uploaded object key=ycmfffix29jyj68vxs5a0k41ryanfxvk.narinfo error="server returned 404: 404 page not found\n"15582026/11/06 07:11:56 INFO Received complete push request method=POST path=/api/pushes/1/complete15592026/11/06 07:11:56 WARN Failed to register uploaded object key=gjf9p9a29bbr5vcp34fja0d1s52wri1d.narinfo error="server returned 404: 404 page not found\n"15602026/11/06 07:11:56 INFO Received push request method=POST path=/api/pushes15612026/11/06 07:11:56 INFO Completed push id=1 objects=9 duration=35.499292ms15622026/11/06 07:11:56 INFO Upload complete. (363ms)1563=== NAME TestClientMultipleUploads1564 client_integration_test.go:416: Uploaded 3 paths in 410.009084ms15652026/11/06 07:11:56 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)15662026/11/06 07:11:56 INFO Uploading 13707a1ilhj1l2hg3bjywhh6ib2jrzaz-test-file.txt (152B)15672026/11/06 07:11:56 WARN Failed to register uploaded object key=13707a1ilhj1l2hg3bjywhh6ib2jrzaz.ls error="server returned 404: 404 page not found\n"15682026/11/06 07:11:56 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign15692026/11/06 07:11:56 WARN Failed to register uploaded object key=nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst error="server returned 404: 404 page not found\n"15702026/11/06 07:11:56 INFO Signed narinfos id=1 count=115712026/11/06 07:11:56 INFO Uploading 1 narinfos1572--- PASS: TestClientMultipleUploads (8.02s)1573=== CONT TestService_RequireScope_OIDC15742026/11/06 07:11:56 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:54713/oidc15752026/11/06 07:11:56 INFO Received complete push request method=POST path=/api/pushes/1/complete15762026/11/06 07:11:56 WARN Failed to register uploaded object key=13707a1ilhj1l2hg3bjywhh6ib2jrzaz.narinfo error="server returned 404: 404 page not found\n"15772026/11/06 07:11:56 INFO Completed push id=1 objects=3 duration=12.434625ms15782026/11/06 07:11:56 INFO Upload complete. (321ms)15792026/11/06 07:11:56 INFO All 1 paths already cached1580=== NAME TestClientIntegration1581 client_integration_test.go:317: Retrieved narinfo from S3:1582 StorePath: /private/var/tb/4/scratch/520ebb830df639a2/build/TestClientIntegration3810632103/002/store/13707a1ilhj1l2hg3bjywhh6ib2jrzaz-test-file.txt1583 URL: nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst1584 Compression: zstd1585 NarHash: sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11586 NarSize: 1521587 References: 1588 CA: fixed:r:sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11589 client_integration_test.go:318: Retrieved .ls file from S3 (compressed size: 77 bytes)1590=== NAME TestPinProtectsFromGC1591 client_integration_test.go:778: Pinned store path: /private/var/tb/4/scratch/520ebb830df639a2/build/TestPinProtectsFromGC3004725465/001/store/4xq1ms815g2ks30pszidgia4b5ml6bqc-pinned-file.txt1592 client_integration_test.go:779: Unpinned store path: /private/var/tb/4/scratch/520ebb830df639a2/build/TestPinProtectsFromGC3004725465/001/store/csyhlnyplcvvzpn94vkaiwyjkb52z5ks-unpinned-file.txt1593=== NAME TestClientIntegration1594 client_integration_test.go:318: Decompressed .ls content (64 bytes):1595 {"version":1,"root":{"type":"regular","size":39,"narOffset":96}}15962026/11/06 07:11:56 INFO Received push request method=POST path=/api/pushes15972026/11/06 07:11:56 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)15982026/11/06 07:11:56 INFO Uploading 4xq1ms815g2ks30pszidgia4b5ml6bqc-pinned-file.txt (128B)1599--- PASS: TestService_Rustfstest (7.17s)1600=== CONT TestService_AuthMiddleware_OIDC16012026/11/06 07:11:56 WARN Failed to register uploaded object key=4xq1ms815g2ks30pszidgia4b5ml6bqc.ls error="server returned 404: 404 page not found\n"16022026/11/06 07:11:56 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign16032026/11/06 07:11:56 WARN Failed to register uploaded object key=nar/0qmhsg42pqsz7x6hh02j8gznnac3yi3qpjhrqbwvz88i194jbb5s.nar.zst error="server returned 404: 404 page not found\n"16042026/11/06 07:11:56 INFO Signed narinfos id=1 count=116052026/11/06 07:11:56 INFO Uploading 1 narinfos16062026/11/06 07:11:56 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:54723/oidc16072026/11/06 07:11:56 INFO Received complete push request method=POST path=/api/pushes/1/complete16082026/11/06 07:11:56 WARN Failed to register uploaded object key=4xq1ms815g2ks30pszidgia4b5ml6bqc.narinfo error="server returned 404: 404 page not found\n"1609--- PASS: TestDeleteClosuresRacingPins (12.23s)1610=== CONT TestCacheStatsHandler16112026/11/06 07:11:56 INFO Received push request method=POST path=/api/pushes16122026/11/06 07:11:56 INFO Completed push id=1 objects=3 duration=120.610709ms16132026/11/06 07:11:56 INFO Object in database but missing from S3 key=13707a1ilhj1l2hg3bjywhh6ib2jrzaz.ls16142026/11/06 07:11:56 WARN Found objects in DB but missing from S3, will re-upload count=116152026/11/06 07:11:56 INFO Upload complete. (442ms)16162026/11/06 07:11:56 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)16172026/11/06 07:11:56 INFO Received complete push request method=POST path=/api/pushes/2/complete16182026/11/06 07:11:56 WARN Failed to register uploaded object key=13707a1ilhj1l2hg3bjywhh6ib2jrzaz.ls error="server returned 404: 404 page not found\n"16192026/11/06 07:11:56 INFO Completed push id=2 objects=3 duration=1.718083ms16202026/11/06 07:11:56 INFO Upload complete. (209ms)1621=== NAME TestClientIntegration1622 client_integration_test.go:335: Retrieved .ls file from S3 (compressed size: 62 bytes)1623 client_integration_test.go:335: Decompressed .ls content (49 bytes):1624 {"version":1,"root":{"type":"regular","size":39}}16252026/11/06 07:11:56 INFO Received push request method=POST path=/api/pushes16262026/11/06 07:11:56 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)16272026/11/06 07:11:56 INFO Uploading csyhlnyplcvvzpn94vkaiwyjkb52z5ks-unpinned-file.txt (128B)16282026/11/06 07:11:56 INFO Received push request method=POST path=/api/pushes16292026/11/06 07:11:56 WARN Failed to register uploaded object key=csyhlnyplcvvzpn94vkaiwyjkb52z5ks.ls error="server returned 404: 404 page not found\n"16302026/11/06 07:11:57 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign16312026/11/06 07:11:57 WARN Failed to register uploaded object key=nar/0gh0wdnr6gmk4r5sfzzh12isnl14rgmkrwy1ws41hpsrlndclg5h.nar.zst error="server returned 404: 404 page not found\n"16322026/11/06 07:11:57 INFO Signed narinfos id=2 count=116332026/11/06 07:11:57 INFO Uploading 1 narinfos16342026/11/06 07:11:57 INFO Uploading 2 paths to 127.0.0.1 (0 already cached)1635--- PASS: TestReadProxyHead (7.36s)1636=== CONT TestService_ReadScope_PublicByDefault16372026/11/06 07:11:57 INFO Uploading xr545nc4zxp6xd7474m27nwdsbfp10dp-top (264B)16382026/11/06 07:11:57 INFO Uploading r8gsh0mj84qs1y3r1868rj8zjxbziicb-shared-dep (136B)16392026/11/06 07:11:57 INFO Received complete push request method=POST path=/api/pushes/2/complete16402026/11/06 07:11:57 WARN Failed to register uploaded object key=csyhlnyplcvvzpn94vkaiwyjkb52z5ks.narinfo error="server returned 404: 404 page not found\n"16412026/11/06 07:11:57 INFO Completed push id=2 objects=3 duration=768.666µs16422026/11/06 07:11:57 INFO Upload complete. (253ms)16432026/11/06 07:11:57 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"16442026/11/06 07:11:57 WARN Failed to register uploaded object key=r8gsh0mj84qs1y3r1868rj8zjxbziicb.ls error="server returned 404: 404 page not found\n"16452026/11/06 07:11:57 WARN Failed to register uploaded object key=nar/1yx7h1n45ym389rcflynbq63a6vw2wm30vk8zpj1c4pwq981sw57.nar.zst error="server returned 404: 404 page not found\n"16462026/11/06 07:11:57 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign16472026/11/06 07:11:57 WARN Failed to register uploaded object key=xr545nc4zxp6xd7474m27nwdsbfp10dp.ls error="server returned 404: 404 page not found\n"16482026/11/06 07:11:57 INFO Signed narinfos id=1 count=216492026/11/06 07:11:57 INFO Uploading 2 narinfos16502026/11/06 07:11:57 INFO Starting cleanup of old closures method=DELETE path=/api/closures16512026/11/06 07:11:57 INFO Garbage collection started16522026/11/06 07:11:57 INFO Aborted multipart uploads count=0 kept=016532026/11/06 07:11:57 WARN Failed to register uploaded object key=xr545nc4zxp6xd7474m27nwdsbfp10dp.narinfo error="server returned 404: 404 page not found\n"16542026/11/06 07:11:57 INFO Received complete push request method=POST path=/api/pushes/1/complete16552026/11/06 07:11:57 WARN Failed to register uploaded object key=r8gsh0mj84qs1y3r1868rj8zjxbziicb.narinfo error="server returned 404: 404 page not found\n"16562026/11/06 07:11:57 WARN Force mode enabled - objects will be deleted immediately without grace period16572026/11/06 07:11:57 INFO Completed push id=1 objects=6 duration=50.433667ms16582026/11/06 07:11:57 INFO Upload complete. (440ms)1659=== NAME TestClientSharedPathCommittedMidPush1660 client_integration_test.go:727: Retrieved narinfo from S3:1661 StorePath: /private/var/tb/4/scratch/520ebb830df639a2/build/TestClientSharedPathCommittedMidPush3888502545/001/store/r8gsh0mj84qs1y3r1868rj8zjxbziicb-shared-dep1662 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1663 Compression: zstd1664 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821665 NarSize: 1361666 References: 1667 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1668 client_integration_test.go:727: Retrieved narinfo from S3:1669 StorePath: /private/var/tb/4/scratch/520ebb830df639a2/build/TestClientSharedPathCommittedMidPush3888502545/001/store/xr545nc4zxp6xd7474m27nwdsbfp10dp-top1670 URL: nar/1yx7h1n45ym389rcflynbq63a6vw2wm30vk8zpj1c4pwq981sw57.nar.zst1671 Compression: zstd1672 NarHash: sha256:1yx7h1n45ym389rcflynbq63a6vw2wm30vk8zpj1c4pwq981sw571673 NarSize: 2641674 References: /private/var/tb/4/scratch/520ebb830df639a2/build/TestClientSharedPathCommittedMidPush3888502545/001/store/r8gsh0mj84qs1y3r1868rj8zjxbziicb-shared-dep1675 CA: text:sha256:0hl8gjkfy40fqrp6b67nvxai5nlw21pxjgk4vk7zhivx5yqq83ns16762026/11/06 07:11:57 INFO Received push request method=POST path=/api/pushes16772026/11/06 07:11:57 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)16782026/11/06 07:11:57 INFO Received complete push request method=POST path=/api/pushes/3/complete16792026/11/06 07:11:57 WARN Failed to register uploaded object key=13707a1ilhj1l2hg3bjywhh6ib2jrzaz.ls error="server returned 404: 404 page not found\n"16802026/11/06 07:11:57 INFO Completed push id=3 objects=3 duration=1.556458ms16812026/11/06 07:11:57 INFO Upload complete. (153ms)1682=== NAME TestClientIntegration1683 client_integration_test.go:352: Retrieved .ls file from S3 (compressed size: 62 bytes)1684 client_integration_test.go:352: Decompressed .ls content (49 bytes):1685 {"version":1,"root":{"type":"regular","size":39}}1686 client_integration_test.go:363: Testing garbage collection...1687--- PASS: TestReadRedirectKeepsNarinfoProxied (7.55s)1688=== CONT TestService_AuthMiddleware_MTLSBoundSubjects1689--- PASS: TestClientSharedPathCommittedMidPush (8.17s)1690=== CONT TestClientFallsBackToClosures16912026/11/06 07:11:57 INFO Starting cleanup of old closures method=DELETE path=/api/closures16922026/11/06 07:11:57 INFO Garbage collection started16932026/11/06 07:11:57 INFO Aborted multipart uploads count=0 kept=016942026/11/06 07:11:57 WARN Force mode enabled - objects will be deleted immediately without grace period16952026/11/06 07:11:57 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=016962026/11/06 07:11:57 INFO Vacuumed table table=pending_closures1697--- PASS: TestReadProxyDisabled (6.83s)1698=== CONT TestService_AuthMiddleware_MTLSProxyHeader16992026/11/06 07:11:58 INFO Vacuumed table table=pending_objects17002026/11/06 07:11:58 INFO Vacuumed table table=multipart_uploads17012026/11/06 07:11:58 INFO Vacuumed table table=closures17022026/11/06 07:11:58 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=017032026/11/06 07:11:58 INFO Vacuumed table table=pending_closures17042026/11/06 07:11:58 INFO Vacuumed table table=objects17052026/11/06 07:11:58 INFO Vacuumed table table=pending_objects17062026/11/06 07:11:58 INFO Vacuumed table table=multipart_uploads17072026/11/06 07:11:58 INFO Vacuumed table table=closures17082026/11/06 07:11:58 INFO Vacuumed table table=objects17092026/11/06 07:11:58 INFO Received uploads request method=POST path=/api/pending_closures17102026/11/06 07:11:58 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1711--- PASS: TestReadRedirectNar (7.95s)1712=== CONT TestCompleteMultipartUpload_ErrorButObjectExists17132026/11/06 07:11:59 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=017142026/11/06 07:11:59 INFO Received create pin request method=POST path=/api/pins/myapp17152026/11/06 07:11:59 INFO Created/updated pin name=myapp store_path=/private/var/tb/4/scratch/520ebb830df639a2/build/TestPinProtectsFromGC3004725465/001/store/4xq1ms815g2ks30pszidgia4b5ml6bqc-pinned-file.txt narinfo_key=4xq1ms815g2ks30pszidgia4b5ml6bqc.narinfo17162026/11/06 07:11:59 INFO Starting cleanup of old closures method=DELETE path=/api/closures17172026/11/06 07:11:59 INFO Garbage collection started17182026/11/06 07:11:59 INFO Aborted multipart uploads count=0 kept=017192026/11/06 07:11:59 WARN Force mode enabled - objects will be deleted immediately without grace period17202026/11/06 07:11:59 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=01721--- PASS: TestReadProxyRootRedirectsToIndexHTML (7.97s)1722=== CONT TestRedundantMultipartUpload17232026/11/06 07:11:59 INFO Vacuumed table table=pending_closures17242026/11/06 07:11:59 INFO Vacuumed table table=pending_objects17252026/11/06 07:11:59 INFO Vacuumed table table=multipart_uploads17262026/11/06 07:11:59 INFO Vacuumed table table=closures17272026/11/06 07:11:59 INFO Vacuumed table table=objects17282026/11/06 07:11:59 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=01729=== NAME TestClientIntegration1730 client_integration_test.go:370: Objects in database after GC:1731 client_integration_test.go:370: Successfully deleted all objects with GC --force1732--- PASS: TestClientIntegration (11.00s)1733=== CONT TestCacheConfigHandler1734=== RUN TestCacheConfigHandler/full_config,_no_issuer1735=== PAUSE TestCacheConfigHandler/full_config,_no_issuer1736=== RUN TestCacheConfigHandler/no_cache_url_configured1737=== PAUSE TestCacheConfigHandler/no_cache_url_configured1738=== RUN TestCacheConfigHandler/no_signing_keys1739=== PAUSE TestCacheConfigHandler/no_signing_keys1740=== RUN TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1741=== PAUSE TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1742=== CONT TestPresentNotReportedWhileGCDeletesClosure/stale1743--- PASS: TestReadProxyContentNegotiation (8.51s)1744=== CONT TestPresentNotReportedWhileGCDeletesClosure/fresh1745--- PASS: TestReadProxyInvalidPath (8.43s)1746=== CONT TestGCEndsOnShutdown/before_the_run1747--- PASS: TestReadProxyConditionalGet (8.50s)1748=== CONT TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark1749=== NAME TestPinProtectsFromGC1750 client_integration_test.go:887: Pin successfully protected closure from garbage collection1751--- PASS: TestPinProtectsFromGC (12.88s)1752=== CONT TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete1753--- PASS: TestReadProxy404 (9.41s)1754=== CONT TestParseSingleRange/none1755=== CONT TestParseSingleRange/start_far_past_EOF1756=== CONT TestParseSingleRange/start_past_EOF1757=== CONT TestParseSingleRange/single_byte1758=== CONT TestParseSingleRange/suffix_exceeds_size1759=== CONT TestParseSingleRange/suffix1760=== CONT TestParseSingleRange/end_clamped_to_size1761=== CONT TestParseSingleRange/open-ended1762=== CONT TestParseSingleRange/closed1763=== CONT TestParseSingleRange/malformed_end_before_start1764=== CONT TestParseSingleRange/malformed_both_empty1765=== CONT TestParseSingleRange/malformed_no_dash1766=== CONT TestParseSingleRange/multi-range_ignored1767=== CONT TestParseSingleRange/unknown_unit1768--- PASS: TestParseSingleRange (0.00s)1769 --- PASS: TestParseSingleRange/none (0.00s)1770 --- PASS: TestParseSingleRange/start_far_past_EOF (0.00s)1771 --- PASS: TestParseSingleRange/start_past_EOF (0.00s)1772 --- PASS: TestParseSingleRange/single_byte (0.00s)1773 --- PASS: TestParseSingleRange/suffix_exceeds_size (0.00s)1774 --- PASS: TestParseSingleRange/suffix (0.00s)1775 --- PASS: TestParseSingleRange/end_clamped_to_size (0.00s)1776 --- PASS: TestParseSingleRange/open-ended (0.00s)1777 --- PASS: TestParseSingleRange/closed (0.00s)1778 --- PASS: TestParseSingleRange/malformed_end_before_start (0.00s)1779 --- PASS: TestParseSingleRange/malformed_both_empty (0.00s)1780 --- PASS: TestParseSingleRange/malformed_no_dash (0.00s)1781 --- PASS: TestParseSingleRange/multi-range_ignored (0.00s)1782 --- PASS: TestParseSingleRange/unknown_unit (0.00s)1783=== CONT TestForceGCDuringPushOffersSweptObject/before_pending_rows17842026/11/06 07:12:01 INFO Received uploads request method=POST path=/api/pending_closures17852026/11/06 07:12:02 WARN Rate limiter enabled after throttle name=s3-test rate=517862026/11/06 07:12:02 WARN S3 rate limit hit operation="complete multipart upload" error="Please reduce your request rate."1787--- PASS: TestReadProxyNarStreaming (8.66s)1788=== CONT TestForceGCDuringPushOffersSweptObject/after_presence_check1789=== NAME TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle1790 throttle_test.go:213: Proxy stats: total=13, throttled=10, completeMultipart=101791 throttle_test.go:215: Rate limiter: enabled=true, rate=5.001792--- PASS: TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle (11.35s)1793=== CONT TestServerTLSConfig/no_client_CA1794=== CONT TestServerTLSConfig/not_a_PEM_file1795=== CONT TestServerTLSConfig/missing_CA_file1796--- PASS: TestServerTLSConfig (0.00s)1797 --- PASS: TestServerTLSConfig/no_client_CA (0.00s)1798 --- PASS: TestServerTLSConfig/not_a_PEM_file (0.03s)1799 --- PASS: TestServerTLSConfig/missing_CA_file (0.00s)1800=== CONT TestPush_RejectsBadRequests/root_not_in_objects18012026/11/06 07:12:02 INFO Received push request method=POST path=/api/pushes1802=== CONT TestPush_RejectsBadRequests/no_objects18032026/11/06 07:12:02 INFO Received push request method=POST path=/api/pushes1804=== CONT TestPush_RejectsBadRequests/bad_root18052026/11/06 07:12:02 INFO Received push request method=POST path=/api/pushes1806=== CONT TestPush_RejectsBadRequests/no_roots18072026/11/06 07:12:02 INFO Received push request method=POST path=/api/pushes1808=== CONT TestResolveDBConnectionString/flag_wins1809--- PASS: TestPush_RejectsBadRequests (4.81s)1810 --- PASS: TestPush_RejectsBadRequests/root_not_in_objects (0.01s)1811 --- PASS: TestPush_RejectsBadRequests/no_objects (0.00s)1812 --- PASS: TestPush_RejectsBadRequests/bad_root (0.00s)1813 --- PASS: TestPush_RejectsBadRequests/no_roots (0.00s)1814=== CONT TestResolveDBConnectionString/PGHOST_allows_empty1815=== CONT TestResolveDBConnectionString/nothing_configured1816=== CONT TestResolveDBConnectionString/missing_file_is_an_error1817=== CONT TestResolveDBConnectionString/file_when_flag_empty1818=== CONT TestPendingClosureWriteTimeout/empty1819=== CONT TestPendingClosureWriteTimeout/670k_objects1820=== CONT TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline1821--- PASS: TestResolveDBConnectionString (0.02s)1822 --- PASS: TestResolveDBConnectionString/flag_wins (0.00s)1823 --- PASS: TestResolveDBConnectionString/PGHOST_allows_empty (0.00s)1824 --- PASS: TestResolveDBConnectionString/nothing_configured (0.00s)1825 --- PASS: TestResolveDBConnectionString/missing_file_is_an_error (0.00s)1826 --- PASS: TestResolveDBConnectionString/file_when_flag_empty (0.00s)18272026/11/06 07:12:02 ERROR Failed to decode narinfo key=3hcdxyjf9yiq7qf3i4548drb6sjmwa1v.narinfo limit=16777216 error=<nil>1828--- PASS: TestReadProxyNarinfo (7.79s)1829=== CONT TestPendingClosureWriteTimeout/400_objects1830=== CONT TestService_verifyS3ReuploadsStaleNarinfo/lost,_other_NAR_pushed18312026/11/06 07:12:03 INFO Received uploads request method=POST path=/api/pending_closures18322026/11/06 07:12:03 INFO Registered completed upload object_key=nar/jjjjjjjjjjjjjjjjjjjjjjjjjjjjjj0100000000000000000000.nar.zst18332026/11/06 07:12:03 INFO Received uploads request method=POST path=/api/pending_closures1834--- PASS: TestPresignedUploadRegisteredBeforeCommit (7.99s)1835=== CONT TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost,_second_pushed1836--- PASS: TestReadProxyNarinfoAlreadyDecompressed (7.74s)1837=== CONT TestService_verifyS3ReuploadsStaleNarinfo/lost,_same_NAR_pushed1838--- PASS: TestService_ReadAuthMiddleware (7.98s)1839=== CONT TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost18402026/11/06 07:12:04 INFO Received complete multipart upload request method=POST path=/api/multipart/complete18412026/11/06 07:12:04 INFO Completed multipart upload object_key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhh0100000000000000000000.nar.zst upload_id=ZmU1YTU2N2ItYWZhNS00YzBlLTk1ZWEtN2VjYjM0N2E0OWRlLmFiNjljMWQ3LWE0YWItNGUyYi05MzlhLWMyOTg3MjhhZTVlNngxNzkzOTQ5MTIxOTQ3MTc2MDAw parts=1218422026/11/06 07:12:04 INFO Received uploads request method=POST path=/api/pending_closures1843--- PASS: TestCompletedNarNotReofferedAcrossClosures (11.12s)1844=== CONT TestService_verifyS3ReuploadsStaleNarinfo/intact,_other_NAR_pushed1845=== RUN TestService_RequireScope_OIDC/builder_may_write1846=== PAUSE TestService_RequireScope_OIDC/builder_may_write1847=== RUN TestService_RequireScope_OIDC/builder_may_not_admin1848=== PAUSE TestService_RequireScope_OIDC/builder_may_not_admin1849=== RUN TestService_RequireScope_OIDC/ops_may_admin1850=== PAUSE TestService_RequireScope_OIDC/ops_may_admin1851=== RUN TestService_RequireScope_OIDC/ops_may_not_write1852=== PAUSE TestService_RequireScope_OIDC/ops_may_not_write1853=== RUN TestService_RequireScope_OIDC/reader_may_not_write1854=== PAUSE TestService_RequireScope_OIDC/reader_may_not_write1855=== RUN TestService_RequireScope_OIDC/static_token_may_admin1856=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin1857=== RUN TestService_RequireScope_OIDC/static_token_may_write1858=== PAUSE TestService_RequireScope_OIDC/static_token_may_write1859=== RUN TestService_RequireScope_OIDC/reader_may_read1860=== PAUSE TestService_RequireScope_OIDC/reader_may_read1861=== RUN TestService_RequireScope_OIDC/writer_implies_read1862=== PAUSE TestService_RequireScope_OIDC/writer_implies_read1863=== RUN TestService_RequireScope_OIDC/anonymous_may_not_read1864=== PAUSE TestService_RequireScope_OIDC/anonymous_may_not_read1865=== RUN TestService_RequireScope_OIDC/reader_may_read_with_netrc1866=== PAUSE TestService_RequireScope_OIDC/reader_may_read_with_netrc1867=== RUN TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1868=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1869=== RUN TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read1870=== PAUSE TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read1871=== RUN TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1872=== PAUSE TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1873=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info18742026/11/06 07:12:04 INFO Received uploads request method=POST path=/1875=== CONT TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key18762026/11/06 07:12:04 INFO Received complete multipart upload request method=POST path=/1877=== CONT TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key18782026/11/06 07:12:04 INFO Received request for more parts method=POST path=/1879=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal18802026/11/06 07:12:04 INFO Received uploads request method=POST path=/1881--- PASS: TestUploadHandlersRejectInvalidKeys (0.00s)1882 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info (0.00s)1883 --- PASS: TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key (0.00s)1884 --- PASS: TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key (0.01s)1885 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal (0.01s)1886=== CONT TestIsValidUploadKey/narinfo1887=== CONT TestIsValidUploadKey/realisation_plus_in_output1888=== CONT TestIsValidUploadKey/unknown_type1889=== CONT TestIsValidUploadKey/empty_key1890=== CONT TestIsValidUploadKey/absolute1891=== CONT TestIsValidUploadKey/traversal_nar1892=== CONT TestIsValidUploadKey/traversal1893=== CONT TestIsValidUploadKey/listing_key,_narinfo_type1894=== CONT TestIsValidUploadKey/nar_key,_narinfo_type1895=== CONT TestIsValidUploadKey/narinfo_key,_nar_type1896=== CONT TestIsValidUploadKey/index.html1897=== CONT TestIsValidUploadKey/nix-cache-info1898=== CONT TestIsValidUploadKey/build_log_home-manager_file1899=== CONT TestIsValidUploadKey/realisation1900=== CONT TestIsValidUploadKey/build_log_equals1901=== CONT TestIsValidUploadKey/build_log_question_mark1902=== CONT TestIsValidUploadKey/build_log_plus_in_name1903=== CONT TestIsValidUploadKey/nar_plain1904=== CONT TestIsValidUploadKey/build_log1905=== CONT TestIsValidUploadKey/listing1906=== CONT TestIsValidUploadKey/nar_xz1907=== CONT TestIsValidUploadKey/nar_zst1908=== CONT TestUploadHandlersRejectOversizedBody/complete_multipart19092026/11/06 07:12:04 INFO Received complete multipart upload request method=POST path=/1910--- PASS: TestIsValidUploadKey (0.04s)1911 --- PASS: TestIsValidUploadKey/narinfo (0.00s)1912 --- PASS: TestIsValidUploadKey/realisation_plus_in_output (0.00s)1913 --- PASS: TestIsValidUploadKey/unknown_type (0.00s)1914 --- PASS: TestIsValidUploadKey/empty_key (0.00s)1915 --- PASS: TestIsValidUploadKey/absolute (0.00s)1916 --- PASS: TestIsValidUploadKey/traversal_nar (0.00s)1917 --- PASS: TestIsValidUploadKey/traversal (0.00s)1918 --- PASS: TestIsValidUploadKey/listing_key,_narinfo_type (0.00s)1919 --- PASS: TestIsValidUploadKey/nar_key,_narinfo_type (0.00s)1920 --- PASS: TestIsValidUploadKey/narinfo_key,_nar_type (0.00s)1921 --- PASS: TestIsValidUploadKey/index.html (0.00s)1922 --- PASS: TestIsValidUploadKey/nix-cache-info (0.00s)1923 --- PASS: TestIsValidUploadKey/build_log_home-manager_file (0.00s)1924 --- PASS: TestIsValidUploadKey/realisation (0.00s)1925 --- PASS: TestIsValidUploadKey/build_log_equals (0.00s)1926 --- PASS: TestIsValidUploadKey/build_log_question_mark (0.00s)1927 --- PASS: TestIsValidUploadKey/build_log_plus_in_name (0.00s)1928 --- PASS: TestIsValidUploadKey/nar_plain (0.00s)1929 --- PASS: TestIsValidUploadKey/build_log (0.00s)1930 --- PASS: TestIsValidUploadKey/listing (0.00s)1931 --- PASS: TestIsValidUploadKey/nar_xz (0.00s)1932 --- PASS: TestIsValidUploadKey/nar_zst (0.00s)1933=== CONT TestUploadHandlersRejectOversizedBody/create_pending_closure19342026/11/06 07:12:04 INFO Received uploads request method=POST path=/1935--- PASS: TestService_ReadScope_PublicByDefault (7.62s)1936=== CONT TestUploadHandlersRejectOversizedBody/request_more_parts19372026/11/06 07:12:04 INFO Received request for more parts method=POST path=/1938=== CONT TestClientErrorHandling/InvalidStorePath1939--- PASS: TestUploadHandlersRejectOversizedBody (0.18s)1940 --- PASS: TestUploadHandlersRejectOversizedBody/complete_multipart (0.04s)1941 --- PASS: TestUploadHandlersRejectOversizedBody/request_more_parts (0.02s)1942 --- PASS: TestUploadHandlersRejectOversizedBody/create_pending_closure (0.45s)1943=== CONT TestClientErrorHandling/ServerNotAvailable1944=== RUN TestService_AuthMiddleware_OIDC/valid_OIDC_token1945=== PAUSE TestService_AuthMiddleware_OIDC/valid_OIDC_token1946=== RUN TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1947=== PAUSE TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1948=== RUN TestService_AuthMiddleware_OIDC/malformed_token_rejected1949=== PAUSE TestService_AuthMiddleware_OIDC/malformed_token_rejected1950=== RUN TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1951=== PAUSE TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1952=== CONT TestClientErrorHandling/InvalidAuthToken19532026/11/06 07:12:05 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/present1954--- PASS: TestCacheStatsHandler (8.63s)1955=== CONT TestProxyWriteTimeout/narinfo1956=== CONT TestProxyWriteTimeout/10_GiB_nar1957=== CONT TestProxyWriteTimeout/unknown_size1958=== CONT TestProxyWriteTimeout/1_GiB_nar1959--- PASS: TestProxyWriteTimeout (0.01s)1960 --- PASS: TestProxyWriteTimeout/narinfo (0.00s)1961 --- PASS: TestProxyWriteTimeout/10_GiB_nar (0.00s)1962 --- PASS: TestProxyWriteTimeout/unknown_size (0.00s)1963 --- PASS: TestProxyWriteTimeout/1_GiB_nar (0.00s)1964=== CONT TestIsValidCachePath/narinfo1965=== CONT TestIsValidCachePath/index.html1966=== CONT TestIsValidCachePath/short_hash1967=== CONT TestIsValidCachePath/wrong_extension1968=== CONT TestIsValidCachePath/leading_slash1969=== CONT TestIsValidCachePath/empty1970=== CONT TestIsValidCachePath/random_path1971=== CONT TestIsValidCachePath/invalid_char_u1972=== CONT TestIsValidCachePath/invalid_char_e1973=== CONT TestIsValidCachePath/traversal_in_middle1974=== CONT TestIsValidCachePath/traversal_parent1975=== CONT TestIsValidCachePath/nar_uncompressed1976=== CONT TestIsValidCachePath/nix-cache-info1977=== CONT TestIsValidCachePath/realisation1978=== CONT TestIsValidCachePath/log1979=== CONT TestIsValidCachePath/ls1980=== CONT TestIsValidCachePath/nar_xz1981=== CONT TestIsValidCachePath/nar_bz21982=== CONT TestIsValidCachePath/nar_zst1983=== CONT TestIsValidCachePath/narinfo_all_nix_base32_chars1984=== CONT TestCacheConfigHandler/full_config,_no_issuer1985=== CONT TestCacheConfigHandler/no_signing_keys1986=== CONT TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1987--- PASS: TestIsValidCachePath (0.08s)1988 --- PASS: TestIsValidCachePath/narinfo (0.00s)1989 --- PASS: TestIsValidCachePath/index.html (0.00s)1990 --- PASS: TestIsValidCachePath/short_hash (0.00s)1991 --- PASS: TestIsValidCachePath/wrong_extension (0.00s)1992 --- PASS: TestIsValidCachePath/leading_slash (0.00s)1993 --- PASS: TestIsValidCachePath/empty (0.00s)1994 --- PASS: TestIsValidCachePath/random_path (0.00s)1995 --- PASS: TestIsValidCachePath/invalid_char_u (0.00s)1996 --- PASS: TestIsValidCachePath/invalid_char_e (0.00s)1997 --- PASS: TestIsValidCachePath/traversal_in_middle (0.00s)1998 --- PASS: TestIsValidCachePath/traversal_parent (0.00s)1999 --- PASS: TestIsValidCachePath/nar_uncompressed (0.00s)2000 --- PASS: TestIsValidCachePath/nix-cache-info (0.00s)2001 --- PASS: TestIsValidCachePath/realisation (0.00s)2002 --- PASS: TestIsValidCachePath/log (0.00s)2003 --- PASS: TestIsValidCachePath/ls (0.00s)2004 --- PASS: TestIsValidCachePath/nar_bz2 (0.00s)2005 --- PASS: TestIsValidCachePath/nar_zst (0.00s)2006 --- PASS: TestIsValidCachePath/narinfo_all_nix_base32_chars (0.00s)2007 --- PASS: TestIsValidCachePath/nar_xz (0.00s)2008=== CONT TestCacheConfigHandler/no_cache_url_configured2009--- PASS: TestCacheConfigHandler (0.00s)2010 --- PASS: TestCacheConfigHandler/full_config,_no_issuer (0.00s)2011 --- PASS: TestCacheConfigHandler/no_signing_keys (0.00s)2012 --- PASS: TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator (0.00s)2013 --- PASS: TestCacheConfigHandler/no_cache_url_configured (0.00s)2014=== CONT TestService_RequireScope_OIDC/builder_may_write2015=== CONT TestService_RequireScope_OIDC/reader_may_read2016=== CONT TestService_RequireScope_OIDC/empty_netrc_password_may_not_read2017=== CONT TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read20182026/11/06 07:12:05 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]2019=== CONT TestService_RequireScope_OIDC/static_token_may_admin_with_netrc2020=== CONT TestService_RequireScope_OIDC/reader_may_read_with_netrc2021=== CONT TestService_RequireScope_OIDC/anonymous_may_not_read2022=== CONT TestService_RequireScope_OIDC/writer_implies_read2023=== CONT TestService_RequireScope_OIDC/reader_may_not_write2024=== CONT TestService_RequireScope_OIDC/static_token_may_write2025=== CONT TestService_RequireScope_OIDC/static_token_may_admin2026=== CONT TestService_RequireScope_OIDC/ops_may_admin2027=== CONT TestService_RequireScope_OIDC/ops_may_not_write2028=== CONT TestService_RequireScope_OIDC/builder_may_not_admin2029=== CONT TestService_AuthMiddleware_OIDC/valid_OIDC_token2030=== CONT TestService_AuthMiddleware_OIDC/malformed_token_rejected20312026/11/06 07:12:05 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]2032=== CONT TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected20332026/11/06 07:12:05 WARN Request failed, retrying attempt=2 backoff=197.54927ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present2034--- PASS: TestService_RequireScope_OIDC (8.13s)2035 --- PASS: TestService_RequireScope_OIDC/builder_may_write (0.00s)2036 --- PASS: TestService_RequireScope_OIDC/reader_may_read (0.00s)2037 --- PASS: TestService_RequireScope_OIDC/empty_netrc_password_may_not_read (0.00s)2038 --- PASS: TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read (0.00s)2039 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin_with_netrc (0.00s)2040 --- PASS: TestService_RequireScope_OIDC/reader_may_read_with_netrc (0.00s)2041 --- PASS: TestService_RequireScope_OIDC/anonymous_may_not_read (0.00s)2042 --- PASS: TestService_RequireScope_OIDC/writer_implies_read (0.00s)2043 --- PASS: TestService_RequireScope_OIDC/reader_may_not_write (0.00s)2044 --- PASS: TestService_RequireScope_OIDC/static_token_may_write (0.00s)2045 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin (0.00s)2046 --- PASS: TestService_RequireScope_OIDC/ops_may_admin (0.00s)2047 --- PASS: TestService_RequireScope_OIDC/ops_may_not_write (0.00s)2048 --- PASS: TestService_RequireScope_OIDC/builder_may_not_admin (0.00s)20492026/11/06 07:12:05 WARN Authentication failed token_preview=eyJhbGciOi...mZUHjMlz1g token_length=701 oidc_error="no rule matched: claim \"repository_owner\" value [otherorg] not in allowed patterns [myorg]" oidc_provider=test tried_providers=[test]2050=== CONT TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2051--- PASS: TestService_AuthMiddleware_OIDC (8.41s)2052 --- PASS: TestService_AuthMiddleware_OIDC/valid_OIDC_token (0.00s)2053 --- PASS: TestService_AuthMiddleware_OIDC/malformed_token_rejected (0.01s)2054 --- PASS: TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected (0.00s)2055 --- PASS: TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured (0.00s)20562026/11/06 07:12:05 WARN Request failed, retrying attempt=3 backoff=425.87717ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present20572026/11/06 07:12:05 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted,O=Other"20582026/11/06 07:12:05 WARN mTLS auth: bound subjects configured but subject DN unavailable20592026/11/06 07:12:05 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted"2060--- PASS: TestService_AuthMiddleware_MTLSBoundSubjects (8.15s)2061--- PASS: TestReadProxyOutlastsServerWriteTimeout (13.24s)20622026/11/06 07:12:06 WARN Request failed, retrying attempt=4 backoff=765.096625ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present2063--- PASS: TestService_AuthMiddleware_MTLSProxyHeader (8.39s)20642026/11/06 07:12:06 WARN Request failed, retrying attempt=5 backoff=1.57421456s error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present20652026/11/06 07:12:07 INFO Received uploads request method=POST path=/api/pending_closures20662026/11/06 07:12:07 INFO Received uploads request method=POST path=/api/pending_closures20672026/11/06 07:12:07 INFO Received uploads request method=POST path=/api/pending_closures20682026/11/06 07:12:07 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)20692026/11/06 07:12:07 INFO Uploading 2q63hma3x0a3l24bn00hjn0fmqlyzhvq-shared-dep (136B)20702026/11/06 07:12:07 INFO Uploading 8s25a74bwsns8886y65z3pdnsh2yfhph-b (256B)20712026/11/06 07:12:07 WARN Failed to register uploaded object key=2q63hma3x0a3l24bn00hjn0fmqlyzhvq.ls error="server returned 404: 404 page not found\n"20722026/11/06 07:12:07 WARN Failed to register uploaded object key=nar/0990sb35cja2hx25205zdk0mixpcaj17nfymby3g9gja2l5zz6zm.nar.zst error="server returned 404: 404 page not found\n"20732026/11/06 07:12:07 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"20742026/11/06 07:12:07 WARN Failed to register uploaded object key=8s25a74bwsns8886y65z3pdnsh2yfhph.ls error="server returned 404: 404 page not found\n"20752026/11/06 07:12:07 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign20762026/11/06 07:12:07 WARN Failed to register uploaded object key=3mbj0b2md0b3s7lp8xadf2r14g91rcmh.ls error="server returned 404: 404 page not found\n"20772026/11/06 07:12:07 INFO Signed narinfos id=1 count=220782026/11/06 07:12:07 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign20792026/11/06 07:12:07 INFO Signed narinfos id=2 count=220802026/11/06 07:12:07 INFO Uploading 4 narinfos20812026/11/06 07:12:08 WARN Failed to register uploaded object key=2q63hma3x0a3l24bn00hjn0fmqlyzhvq.narinfo error="server returned 404: 404 page not found\n"20822026/11/06 07:12:08 WARN Failed to register uploaded object key=3mbj0b2md0b3s7lp8xadf2r14g91rcmh.narinfo error="server returned 404: 404 page not found\n"20832026/11/06 07:12:08 WARN Failed to register uploaded object key=8s25a74bwsns8886y65z3pdnsh2yfhph.narinfo error="server returned 404: 404 page not found\n"20842026/11/06 07:12:08 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete20852026/11/06 07:12:08 WARN Failed to register uploaded object key=2q63hma3x0a3l24bn00hjn0fmqlyzhvq.narinfo error="server returned 404: 404 page not found\n"20862026/11/06 07:12:08 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-config20872026/11/06 07:12:08 INFO Completed upload id=1 objects=6 duration=36.887458ms20882026/11/06 07:12:08 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete20892026/11/06 07:12:08 INFO Completed upload id=2 objects=6 duration=490.917µs20902026/11/06 07:12:08 INFO Upload complete. (1.151s)2091=== NAME TestClientFallsBackToClosures2092 client_pushes_test.go:112: Retrieved narinfo from S3:2093 StorePath: /private/var/tb/4/scratch/520ebb830df639a2/build/TestClientFallsBackToClosures1048588302/001/store/2q63hma3x0a3l24bn00hjn0fmqlyzhvq-shared-dep2094 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst2095 Compression: zstd2096 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y822097 NarSize: 1362098 References: 2099 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n2100 client_pushes_test.go:112: Retrieved narinfo from S3:2101 StorePath: /private/var/tb/4/scratch/520ebb830df639a2/build/TestClientFallsBackToClosures1048588302/001/store/3mbj0b2md0b3s7lp8xadf2r14g91rcmh-a21022026/11/06 07:12:08 WARN Request failed, retrying attempt=2 backoff=211.188118ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config2103 URL: nar/0990sb35cja2hx25205zdk0mixpcaj17nfymby3g9gja2l5zz6zm.nar.zst2104 Compression: zstd2105 NarHash: sha256:0990sb35cja2hx25205zdk0mixpcaj17nfymby3g9gja2l5zz6zm2106 NarSize: 25621072026/11/06 07:12:08 INFO Received uploads request method=POST path=/api/pending_closures2108 References: /private/var/tb/4/scratch/520ebb830df639a2/build/TestClientFallsBackToClosures1048588302/001/store/2q63hma3x0a3l24bn00hjn0fmqlyzhvq-shared-dep2109 CA: text:sha256:12mhv2j0z51vs0i0rqivr9cf2gfv1lqzk18pgy8mww91wncy7q2d2110 client_pushes_test.go:112: Retrieved narinfo from S3:2111 StorePath: /private/var/tb/4/scratch/520ebb830df639a2/build/TestClientFallsBackToClosures1048588302/001/store/8s25a74bwsns8886y65z3pdnsh2yfhph-b2112 URL: nar/0990sb35cja2hx25205zdk0mixpcaj17nfymby3g9gja2l5zz6zm.nar.zst2113 Compression: zstd2114 NarHash: sha256:0990sb35cja2hx25205zdk0mixpcaj17nfymby3g9gja2l5zz6zm21152026/11/06 07:12:08 INFO Received complete multipart upload request method=POST path=/api/multipart/complete2116 NarSize: 2562117 References: /private/var/tb/4/scratch/520ebb830df639a2/build/TestClientFallsBackToClosures1048588302/001/store/2q63hma3x0a3l24bn00hjn0fmqlyzhvq-shared-dep2118 CA: text:sha256:12mhv2j0z51vs0i0rqivr9cf2gfv1lqzk18pgy8mww91wncy7q2d21192026/11/06 07:12:08 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified key does not exist." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=ZmU1YTU2N2ItYWZhNS00YzBlLTk1ZWEtN2VjYjM0N2E0OWRlLmM2OGE2MjUzLWJjNTAtNDNiNC05ZGUzLTRkYzM0NmExZjI0NHgxNzkzOTQ5MTI3NTU5Mzg2MDAw21202026/11/06 07:12:08 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=ZmU1YTU2N2ItYWZhNS00YzBlLTk1ZWEtN2VjYjM0N2E0OWRlLmM2OGE2MjUzLWJjNTAtNDNiNC05ZGUzLTRkYzM0NmExZjI0NHgxNzkzOTQ5MTI3NTU5Mzg2MDAw parts=12121--- PASS: TestCompleteMultipartUpload_ErrorButObjectExists (9.82s)21222026/11/06 07:12:08 WARN Request failed, retrying attempt=3 backoff=410.110142ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21232026/11/06 07:12:08 INFO Received uploads request method=POST path=/api/pending_closures2124--- PASS: TestClientFallsBackToClosures (11.52s)21252026/11/06 07:12:09 WARN Request failed, retrying attempt=4 backoff=809.7529ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21262026/11/06 07:12:10 WARN Request failed, retrying attempt=5 backoff=1.617669721s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config2127--- PASS: TestPresentNotReportedWhileGCDeletesClosure (0.00s)2128 --- PASS: TestPresentNotReportedWhileGCDeletesClosure/stale (10.78s)2129 --- PASS: TestPresentNotReportedWhileGCDeletesClosure/fresh (11.47s)21302026/11/06 07:12:11 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"21312026/11/06 07:12:11 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-config21322026/11/06 07:12:11 WARN Request failed, retrying attempt=2 backoff=219.413749ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21332026/11/06 07:12:12 WARN Request failed, retrying attempt=3 backoff=397.114094ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21342026/11/06 07:12:12 WARN Request failed, retrying attempt=4 backoff=865.729055ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config2135=== NAME TestOrphanedObjectsGCStressTest2136 orphaned_objects_gc_test.go:503: Stress test completed successfully:2137 orphaned_objects_gc_test.go:504: - Active objects preserved: 202138 orphaned_objects_gc_test.go:505: - Objects deleted: 2102139 orphaned_objects_gc_test.go:506: - Total GC'd: 2102140--- PASS: TestOrphanedObjectsGCStressTest (35.98s)21412026/11/06 07:12:12 INFO Aborted multipart uploads count=0 kept=021422026/11/06 07:12:12 WARN Force mode enabled - objects will be deleted immediately without grace period21432026-11-06 07:12:12.693 UTC [85413] ERROR: canceling statement due to user request21442026-11-06 07:12:12.693 UTC [85413] STATEMENT: -- name: MarkStaleObjects :execrows2145 WITH RECURSIVE ct AS (2146 SELECT timezone('UTC', now()) AS now2147 ),2148 closure_reach AS (2149 -- Start with all closure keys2150 SELECT o.key, o.refs2151 FROM objects o2152 INNER JOIN closures c ON o.key = c.key2153 UNION2154 -- Recursively add all referenced objects2155 SELECT o.key, o.refs2156 FROM objects o2157 INNER JOIN closure_reach cr ON o.key = ANY(cr.refs)2158 ),2159 reachable_objects AS (2160 SELECT DISTINCT key FROM closure_reach2161 ),2162 stale_objects AS (2163 SELECT o.key2164 FROM objects AS o, ct2165 WHERE2166 NOT EXISTS (2167 SELECT 12168 FROM reachable_objects ro2169 WHERE ro.key = o.key2170 )2171 AND NOT EXISTS (2172 SELECT 12173 FROM pending_objects AS po2174 WHERE po.key = o.key2175 )2176 AND o.deleted_at IS NULL -- Only mark fresh objects2177 ORDER BY o.key COLLATE "C" -- lock in key order, like commit_pending_closure2178 FOR UPDATE2179 )2180 UPDATE objects2181 SET2182 deleted_at = ct.now,2183 first_deleted_at = COALESCE(first_deleted_at, ct.now)2184 FROM stale_objects, ct2185 WHERE objects.key = stale_objects.key2186 21872026/11/06 07:12:12 INFO Aborted multipart uploads count=0 kept=021882026/11/06 07:12:12 WARN Force mode enabled - objects will be deleted immediately without grace period21892026/11/06 07:12:12 ERROR failed to remove object object=nar/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa.nar.zst error="Post \"http://localhost:54435/bucket95/?delete=\": context canceled"2190--- PASS: TestGCEndsOnShutdown (0.00s)2191 --- PASS: TestGCEndsOnShutdown/before_the_run (11.95s)2192 --- PASS: TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark (11.97s)2193 --- PASS: TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete (11.32s)21942026/11/06 07:12:12 INFO Received complete multipart upload request method=POST path=/api/multipart/complete21952026/11/06 07:12:12 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=ZmU1YTU2N2ItYWZhNS00YzBlLTk1ZWEtN2VjYjM0N2E0OWRlLjA1ZWI3Y2JhLWI2YmEtNGJhNS1hNDJjLTdlM2EwMWQ4NDU3OXgxNzkzOTQ5MTI4NzI3NDQwMDAw parts=1221962026/11/06 07:12:12 INFO Received uploads request method=POST path=/api/pending_closures21972026/11/06 07:12:12 INFO Received uploads request method=POST path=/api/pending_closures21982026/11/06 07:12:13 INFO Received uploads request method=POST path=/api/pending_closures21992026/11/06 07:12:13 INFO Aborted multipart uploads count=0 kept=022002026/11/06 07:12:13 WARN Force mode enabled - objects will be deleted immediately without grace period22012026/11/06 07:12:13 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=022022026/11/06 07:12:13 INFO Vacuumed table table=pending_closures22032026/11/06 07:12:13 INFO Vacuumed table table=pending_objects22042026/11/06 07:12:13 INFO Vacuumed table table=multipart_uploads22052026/11/06 07:12:13 INFO Vacuumed table table=closures22062026/11/06 07:12:13 INFO Received uploads request method=POST path=/api/pending_closures22072026/11/06 07:12:13 WARN Request failed, retrying attempt=5 backoff=1.682250494s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22082026/11/06 07:12:13 INFO Vacuumed table table=objects22092026/11/06 07:12:13 INFO Aborted multipart uploads count=0 kept=022102026/11/06 07:12:13 WARN Force mode enabled - objects will be deleted immediately without grace period22112026/11/06 07:12:13 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=022122026/11/06 07:12:13 INFO Vacuumed table table=pending_closures22132026/11/06 07:12:13 INFO Vacuumed table table=pending_objects22142026/11/06 07:12:13 INFO Vacuumed table table=multipart_uploads22152026/11/06 07:12:13 INFO Vacuumed table table=closures22162026/11/06 07:12:13 INFO Vacuumed table table=objects2217--- PASS: TestForceGCDuringPushOffersSweptObject (0.00s)2218 --- PASS: TestForceGCDuringPushOffersSweptObject/before_pending_rows (11.66s)2219 --- PASS: TestForceGCDuringPushOffersSweptObject/after_presence_check (11.21s)22202026/11/06 07:12:13 INFO Received uploads request method=POST path=/api/pending_closures22212026/11/06 07:12:13 INFO Received uploads request method=POST path=/api/pending_closures22222026/11/06 07:12:14 INFO Received uploads request method=POST path=/api/pending_closures22232026/11/06 07:12:14 INFO Received uploads request method=POST path=/api/pending_closures2224--- PASS: TestPendingClosureWriteTimeout (0.01s)2225 --- PASS: TestPendingClosureWriteTimeout/empty (0.00s)2226 --- PASS: TestPendingClosureWriteTimeout/670k_objects (0.00s)2227 --- PASS: TestPendingClosureWriteTimeout/400_objects (0.00s)2228 --- PASS: TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline (12.00s)22292026/11/06 07:12:14 INFO Received complete multipart upload request method=POST path=/api/multipart/complete22302026/11/06 07:12:14 WARN Failed to abort redundant multipart upload, keeping its row object_key=nar/gggggggggggggggggggggggggggggg0200000000000000000000.nar.zst upload_id=ZmU1YTU2N2ItYWZhNS00YzBlLTk1ZWEtN2VjYjM0N2E0OWRlLjNjNWUwZWNhLTU0ZWUtNDBmNy05MjlhLTE4MDVhNTViMzgwZHgxNzkzOTQ5MTMyOTkyNjgwMDAw error="Get \"http://127.0.0.1:1/bucket90/?location=\": dial tcp 127.0.0.1:1: connect: connection refused"22312026/11/06 07:12:14 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0200000000000000000000.nar.zst upload_id=ZmU1YTU2N2ItYWZhNS00YzBlLTk1ZWEtN2VjYjM0N2E0OWRlLmJmODhjZjI0LWY4MGMtNDVhZS04ODIwLWNlYTQxNzgxZjg4ZngxNzkzOTQ5MTMyOTY0MzMwMDAw parts=1222322026/11/06 07:12:14 INFO Received cleanup request method=DELETE path=/api/pending_closures22332026/11/06 07:12:14 INFO Aborted multipart uploads count=1 kept=02234--- PASS: TestRedundantMultipartUpload (15.19s)22352026/11/06 07:12:14 INFO Received uploads request method=POST path=/api/pending_closures22362026/11/06 07:12:14 INFO Received uploads request method=POST path=/api/pending_closures22372026/11/06 07:12:15 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_closures22382026/11/06 07:12:15 WARN Request failed, retrying attempt=2 backoff=186.931729ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures22392026/11/06 07:12:15 INFO Received complete multipart upload request method=POST path=/api/multipart/complete22402026/11/06 07:12:15 WARN Request failed, retrying attempt=3 backoff=370.31787ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures22412026/11/06 07:12:15 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000100000000000000000000.nar.zst upload_id=ZmU1YTU2N2ItYWZhNS00YzBlLTk1ZWEtN2VjYjM0N2E0OWRlLmRmZmUxNDA2LTQ4NDEtNGZhZi05OGIyLTExYjU3MjVjNDU3YngxNzkzOTQ5MTMzODA0NTQwMDAw parts=1022422026/11/06 07:12:15 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete22432026/11/06 07:12:15 INFO Completed upload id=1 objects=3 duration=9.178542ms22442026/11/06 07:12:15 INFO Received complete multipart upload request method=POST path=/api/multipart/complete22452026/11/06 07:12:15 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000400000000000000000000.nar.zst upload_id=ZmU1YTU2N2ItYWZhNS00YzBlLTk1ZWEtN2VjYjM0N2E0OWRlLjA3YjViNjRmLWY5ZTYtNDQ5MC04ZDY5LWFmYWFlZWJiZDI4YXgxNzkzOTQ5MTM0MDQ3NTg0MDAw parts=1022462026/11/06 07:12:15 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete22472026/11/06 07:12:15 WARN Request failed, retrying attempt=4 backoff=864.175768ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures22482026/11/06 07:12:15 INFO Completed upload id=1 objects=3 duration=8.733334ms22492026/11/06 07:12:15 INFO Received uploads request method=POST path=/api/pending_closures22502026/11/06 07:12:15 INFO Received uploads request method=POST path=/api/pending_closures22512026/11/06 07:12:15 INFO Object in database but missing from S3 key=nar/dadb44fdadb44fdadb44fdadb44f000100000000000000000000.nar.zst22522026/11/06 07:12:15 WARN Narinfo references a NAR missing from S3, will re-upload narinfo=dadb44fdadb44fdadb44fdadb44f0001.narinfo22532026/11/06 07:12:15 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"22542026/11/06 07:12:15 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"22552026/11/06 07:12:15 INFO Received complete multipart upload request method=POST path=/api/multipart/complete22562026/11/06 07:12:16 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000500000000000000000000.nar.zst upload_id=ZmU1YTU2N2ItYWZhNS00YzBlLTk1ZWEtN2VjYjM0N2E0OWRlLjllMjdlNzI4LTAzMmMtNGRiYy04ZmYxLWNlMDM4NjI1OWU2MXgxNzkzOTQ5MTM0MzM1MDkzMDAw parts=1022572026/11/06 07:12:16 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete22582026/11/06 07:12:16 INFO Completed upload id=1 objects=3 duration=11.857416ms22592026/11/06 07:12:16 INFO Received complete multipart upload request method=POST path=/api/multipart/complete22602026/11/06 07:12:16 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000300000000000000000000.nar.zst upload_id=ZmU1YTU2N2ItYWZhNS00YzBlLTk1ZWEtN2VjYjM0N2E0OWRlLmI5Njk4ZjZkLTdjYTEtNDVmNC04ZWNhLWUzYzdmOTk0MGUwMHgxNzkzOTQ5MTM0NjQzMzY0MDAw parts=1022612026/11/06 07:12:16 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete22622026/11/06 07:12:16 INFO Completed upload id=1 objects=3 duration=10.385ms22632026/11/06 07:12:16 INFO Received uploads request method=POST path=/api/pending_closures22642026/11/06 07:12:16 INFO Received uploads request method=POST path=/api/pending_closures22652026/11/06 07:12:16 INFO Received complete multipart upload request method=POST path=/api/multipart/complete22662026/11/06 07:12:16 INFO Object in database but missing from S3 key=nar/dadb44fdadb44fdadb44fdadb44f000500000000000000000000.nar.zst22672026/11/06 07:12:16 WARN Found objects in DB but missing from S3, will re-upload count=122682026/11/06 07:12:16 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000200000000000000000000.nar.zst upload_id=ZmU1YTU2N2ItYWZhNS00YzBlLTk1ZWEtN2VjYjM0N2E0OWRlLjM5NTVhMDE1LTc4ZjMtNGVlMi05NDU4LTg5ODUxOWJjZTZjNHgxNzkzOTQ5MTM0OTMyOTE2MDAw parts=1022692026/11/06 07:12:16 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete22702026/11/06 07:12:16 INFO Completed upload id=1 objects=3 duration=13.53975ms22712026/11/06 07:12:16 INFO Received uploads request method=POST path=/api/pending_closures22722026/11/06 07:12:16 WARN Request failed, retrying attempt=5 backoff=1.448518223s error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures22732026/11/06 07:12:16 INFO Received complete multipart upload request method=POST path=/api/multipart/complete22742026/11/06 07:12:16 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f100400000000000000000000.nar.zst upload_id=ZmU1YTU2N2ItYWZhNS00YzBlLTk1ZWEtN2VjYjM0N2E0OWRlLjc0NGYwMDY0LWEzZjgtNDQwNy05NTc3LWJiNDQzZDdjMWEzZHgxNzkzOTQ5MTM1NzM2NjIxMDAw parts=1022752026/11/06 07:12:16 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete22762026/11/06 07:12:16 INFO Completed upload id=2 objects=3 duration=1.213166ms22772026/11/06 07:12:17 INFO Received uploads request method=POST path=/api/pending_closures22782026/11/06 07:12:17 INFO Object in database but missing from S3 key=nar/dadb44fdadb44fdadb44fdadb44f000400000000000000000000.nar.zst22792026/11/06 07:12:17 WARN Narinfo references a NAR missing from S3, will re-upload narinfo=dadb44fdadb44fdadb44fdadb44f0004.narinfo22802026/11/06 07:12:17 INFO Received complete multipart upload request method=POST path=/api/multipart/complete22812026/11/06 07:12:17 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f100300000000000000000000.nar.zst upload_id=ZmU1YTU2N2ItYWZhNS00YzBlLTk1ZWEtN2VjYjM0N2E0OWRlLjUwNzYyNjAzLWE3ODEtNDEyMy1iMWM1LTM4N2Y1NTczNWNmZngxNzkzOTQ5MTM2MjY0NjY2MDAw parts=1022822026/11/06 07:12:17 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete22832026/11/06 07:12:17 INFO Completed upload id=2 objects=3 duration=562.083µs22842026/11/06 07:12:17 INFO Received uploads request method=POST path=/api/pending_closures22852026/11/06 07:12:17 INFO Object in database but missing from S3 key=nar/dadb44fdadb44fdadb44fdadb44f000300000000000000000000.nar.zst22862026/11/06 07:12:17 WARN Narinfo references a NAR missing from S3, will re-upload narinfo=dadb44fdadb44fdadb44fdadb44f0003.narinfo2287--- PASS: TestService_verifyS3ReuploadsStaleNarinfo (0.01s)2288 --- PASS: TestService_verifyS3ReuploadsStaleNarinfo/lost,_other_NAR_pushed (12.93s)2289 --- PASS: TestService_verifyS3ReuploadsStaleNarinfo/lost,_same_NAR_pushed (12.86s)2290 --- PASS: TestService_verifyS3ReuploadsStaleNarinfo/intact,_other_NAR_pushed (12.26s)2291 --- PASS: TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost,_second_pushed (13.81s)2292 --- PASS: TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost (13.42s)2293--- PASS: TestClientErrorHandling (0.00s)2294 --- PASS: TestClientErrorHandling/InvalidStorePath (10.62s)2295 --- PASS: TestClientErrorHandling/InvalidAuthToken (10.96s)2296 --- PASS: TestClientErrorHandling/ServerNotAvailable (13.15s)2297PASS2298{"timestamp":"2026-11-06T07:12:18.043228Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:54729","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)"}2299{"timestamp":"2026-11-06T07:12:18.042921Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:54672","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)"}2300{"timestamp":"2026-11-06T07:12:18.042919Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:54967","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(3)"}2301{"timestamp":"2026-11-06T07:12:18.04377Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:54730","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(8)"}2302{"timestamp":"2026-11-06T07:12:18.043897Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:54981","error_kind":"io_error","error":"Cancelled","result":"transport_error","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":2561,"threadName":"rustfs-worker","threadId":"ThreadId(10)"}2303{"timestamp":"2026-11-06T07:12:18.044021Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:54973","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(9)"}23042026-11-06 07:12:18.174 UTC [84905] LOG: received smart shutdown request23052026-11-06 07:12:18.175 UTC [84905] LOG: background worker "logical replication launcher" (PID 84915) exited with exit code 123062026-11-06 07:12:18.189 UTC [84910] LOG: shutting down23072026-11-06 07:12:18.190 UTC [84910] LOG: checkpoint starting: shutdown immediate23082026-11-06 07:12:19.895 UTC [84910] LOG: checkpoint complete: wrote 12803 buffers (78.1%), wrote 5 SLRU buffers; 0 WAL file(s) added, 0 removed, 32 recycled; write=0.954 s, sync=0.687 s, total=1.706 s; sync files=35725, longest=0.001 s, average=0.001 s; distance=525221 kB, estimate=525221 kB; lsn=0/21876398, redo lsn=0/2187639823092026-11-06 07:12:19.904 UTC [84905] LOG: database system is shut down2310Running OIDC tests...2311=== RUN TestAudienceForIssuer2312=== PAUSE TestAudienceForIssuer2313=== RUN TestGlobMatch2314=== PAUSE TestGlobMatch2315=== RUN TestValidateToken_ValidToken2316=== PAUSE TestValidateToken_ValidToken2317=== RUN TestValidateToken_WrongAudience2318=== PAUSE TestValidateToken_WrongAudience2319=== RUN TestValidateToken_Expired2320=== PAUSE TestValidateToken_Expired2321=== RUN TestValidateToken_BoundClaimsMismatch2322=== PAUSE TestValidateToken_BoundClaimsMismatch2323=== RUN TestValidateToken_BoundSubjectMismatch2324=== PAUSE TestValidateToken_BoundSubjectMismatch2325=== RUN TestValidateToken_MultipleProviders2326=== PAUSE TestValidateToken_MultipleProviders2327=== RUN TestValidateToken_NoMatchingProvider2328=== PAUSE TestValidateToken_NoMatchingProvider2329=== RUN TestValidateToken_KubernetesServiceAccount2330=== PAUSE TestValidateToken_KubernetesServiceAccount2331=== RUN TestNewValidator_KubernetesRequiresCA2332=== PAUSE TestNewValidator_KubernetesRequiresCA2333=== RUN TestValidateToken_KubernetesIssuerFromOwnToken2334=== PAUSE TestValidateToken_KubernetesIssuerFromOwnToken2335=== RUN TestPins_ReservedForMatchingRule2336=== PAUSE TestPins_ReservedForMatchingRule2337=== RUN TestPins_TopLevelShorthand2338=== PAUSE TestPins_TopLevelShorthand2339=== RUN TestPins_ConfigValidation2340=== PAUSE TestPins_ConfigValidation2341=== RUN TestScopes_LegacyProviderDefaultsToWrite2342=== PAUSE TestScopes_LegacyProviderDefaultsToWrite2343=== RUN TestScopes_Rules2344=== PAUSE TestScopes_Rules2345=== RUN TestScopes_ConfigValidation2346=== PAUSE TestScopes_ConfigValidation2347=== CONT TestAudienceForIssuer2348--- PASS: TestAudienceForIssuer (0.00s)2349=== CONT TestValidateToken_Expired2350=== CONT TestValidateToken_BoundClaimsMismatch2351=== CONT TestValidateToken_NoMatchingProvider2352=== CONT TestValidateToken_ValidToken2353=== CONT TestValidateToken_WrongAudience2354=== CONT TestValidateToken_BoundSubjectMismatch2355=== CONT TestGlobMatch2356=== RUN TestGlobMatch/foo_foo2357=== PAUSE TestGlobMatch/foo_foo2358=== RUN TestGlobMatch/foo_bar2359=== PAUSE TestGlobMatch/foo_bar2360=== RUN TestGlobMatch/*_2361=== PAUSE TestGlobMatch/*_2362=== RUN TestGlobMatch/*_anything2363=== PAUSE TestGlobMatch/*_anything2364=== RUN TestGlobMatch/foo*_foo2365=== PAUSE TestGlobMatch/foo*_foo2366=== RUN TestGlobMatch/foo*_foobar2367=== PAUSE TestGlobMatch/foo*_foobar2368=== RUN TestGlobMatch/foo*_bar2369=== PAUSE TestGlobMatch/foo*_bar2370=== RUN TestGlobMatch/*bar_bar2371=== PAUSE TestGlobMatch/*bar_bar2372=== RUN TestGlobMatch/*bar_foobar2373=== PAUSE TestGlobMatch/*bar_foobar2374=== RUN TestGlobMatch/*bar_foo2375=== PAUSE TestGlobMatch/*bar_foo2376=== RUN TestGlobMatch/foo*bar_foobar2377=== PAUSE TestGlobMatch/foo*bar_foobar2378=== RUN TestGlobMatch/foo*bar_foo123bar2379=== PAUSE TestGlobMatch/foo*bar_foo123bar2380=== RUN TestGlobMatch/foo*bar_foobarbaz2381=== PAUSE TestGlobMatch/foo*bar_foobarbaz2382=== RUN TestGlobMatch/*/*_foo/bar2383=== PAUSE TestGlobMatch/*/*_foo/bar2384=== RUN TestGlobMatch/*/*_foo2385=== PAUSE TestGlobMatch/*/*_foo2386=== RUN TestGlobMatch/refs/heads/*_refs/heads/main2387=== PAUSE TestGlobMatch/refs/heads/*_refs/heads/main2388=== RUN TestGlobMatch/refs/heads/*_refs/tags/v1.02389=== PAUSE TestGlobMatch/refs/heads/*_refs/tags/v1.02390=== RUN TestGlobMatch/refs/*/main_refs/heads/main2391=== PAUSE TestGlobMatch/refs/*/main_refs/heads/main2392=== RUN TestGlobMatch/fo?_foo2393=== PAUSE TestGlobMatch/fo?_foo2394=== RUN TestGlobMatch/fo?_fo2395=== PAUSE TestGlobMatch/fo?_fo2396=== RUN TestGlobMatch/fo?_fooo2397=== PAUSE TestGlobMatch/fo?_fooo2398=== RUN TestGlobMatch/?oo_foo2399=== PAUSE TestGlobMatch/?oo_foo2400=== RUN TestGlobMatch/?oo_boo2401=== PAUSE TestGlobMatch/?oo_boo2402=== RUN TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2403=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2404=== RUN TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2405=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2406=== CONT TestGlobMatch/foo_foo2407=== CONT TestValidateToken_KubernetesServiceAccount2408=== CONT TestGlobMatch/*/*_foo/bar2409=== CONT TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2410=== CONT TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2411=== CONT TestGlobMatch/?oo_boo2412=== CONT TestGlobMatch/?oo_foo2413=== CONT TestGlobMatch/fo?_fooo2414=== CONT TestGlobMatch/fo?_fo2415=== CONT TestGlobMatch/fo?_foo2416=== CONT TestGlobMatch/foo*bar_foobarbaz2417=== CONT TestGlobMatch/foo*_foo2418=== CONT TestGlobMatch/foo*_bar2419=== CONT TestGlobMatch/foo*_foobar2420=== CONT TestGlobMatch/*bar_foo2421=== CONT TestGlobMatch/*_2422=== CONT TestGlobMatch/*_anything2423=== CONT TestGlobMatch/foo_bar2424=== CONT TestGlobMatch/*bar_bar2425=== CONT TestGlobMatch/*bar_foobar2426=== CONT TestScopes_Rules2427=== CONT TestScopes_ConfigValidation2428--- PASS: TestScopes_ConfigValidation (0.00s)2429=== CONT TestPins_ConfigValidation2430=== CONT TestScopes_LegacyProviderDefaultsToWrite2431=== CONT TestPins_ReservedForMatchingRule2432=== CONT TestValidateToken_KubernetesIssuerFromOwnToken2433--- PASS: TestPins_ConfigValidation (0.00s)2434=== CONT TestPins_TopLevelShorthand2435=== CONT TestNewValidator_KubernetesRequiresCA2436=== CONT TestValidateToken_MultipleProviders2437=== CONT TestGlobMatch/refs/heads/*_refs/tags/v1.02438=== CONT TestGlobMatch/refs/heads/*_refs/heads/main2439=== CONT TestGlobMatch/*/*_foo2440=== CONT TestGlobMatch/foo*bar_foobar2441=== CONT TestGlobMatch/foo*bar_foo123bar2442=== CONT TestGlobMatch/refs/*/main_refs/heads/main2443--- 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/foo*bar_foobarbaz (0.00s)2454 --- PASS: TestGlobMatch/foo*_foo (0.00s)2455 --- PASS: TestGlobMatch/foo*_bar (0.00s)2456 --- PASS: TestGlobMatch/foo*_foobar (0.00s)2457 --- PASS: TestGlobMatch/*bar_foo (0.00s)2458 --- PASS: TestGlobMatch/*_ (0.00s)2459 --- PASS: TestGlobMatch/*_anything (0.00s)2460 --- PASS: TestGlobMatch/foo_bar (0.00s)2461 --- PASS: TestGlobMatch/*bar_bar (0.00s)2462 --- PASS: TestGlobMatch/*bar_foobar (0.00s)2463 --- PASS: TestGlobMatch/refs/heads/*_refs/tags/v1.0 (0.00s)2464 --- PASS: TestGlobMatch/refs/heads/*_refs/heads/main (0.00s)2465 --- PASS: TestGlobMatch/*/*_foo (0.00s)2466 --- PASS: TestGlobMatch/foo*bar_foobar (0.00s)2467 --- PASS: TestGlobMatch/foo*bar_foo123bar (0.00s)2468 --- PASS: TestGlobMatch/refs/*/main_refs/heads/main (0.00s)24692026/11/06 07:12:21 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:54987/oidc2470--- PASS: TestValidateToken_BoundSubjectMismatch (0.04s)24712026/11/06 07:12:21 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:54989/oidc2472--- PASS: TestValidateToken_BoundClaimsMismatch (0.07s)24732026/11/06 07:12:21 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:54992/oidc2474--- PASS: TestValidateToken_Expired (0.09s)24752026/11/06 07:12:21 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:54996/oidc24762026/11/06 07:12:21 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:54990/oidc2477--- PASS: TestValidateToken_NoMatchingProvider (0.10s)2478--- PASS: TestValidateToken_ValidToken (0.10s)24792026/11/06 07:12:21 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:55000/oidc24802026/11/06 07:12:21 INFO OIDC provider initialized name=kubernetes issuer=https://127.0.0.1:549942481--- PASS: TestValidateToken_WrongAudience (0.11s)2482--- PASS: TestValidateToken_KubernetesServiceAccount (0.11s)24832026/11/06 07:12:21 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:55003/oidc2484--- PASS: TestScopes_LegacyProviderDefaultsToWrite (0.10s)24852026/11/06 07:12:21 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:55005/oidc24862026/11/06 07:12:21 INFO OIDC provider initialized name=kubernetes issuer=https://oidc.eks.invalid/id/ABC1232487--- PASS: TestPins_ReservedForMatchingRule (0.12s)2488--- PASS: TestValidateToken_KubernetesIssuerFromOwnToken (0.12s)24892026/11/06 07:12:21 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:55009/oidc2490--- PASS: TestScopes_Rules (0.13s)24912026/11/06 07:12:21 http: TLS handshake error from 127.0.0.1:55012: read tcp 127.0.0.1:55011->127.0.0.1:55012: use of closed network connection2492--- PASS: TestNewValidator_KubernetesRequiresCA (0.15s)24932026/11/06 07:12:21 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:55002/oidc24942026/11/06 07:12:21 INFO OIDC provider initialized name=provider2 issuer=http://127.0.0.1:55013/oidc2495--- PASS: TestValidateToken_MultipleProviders (0.16s)24962026/11/06 07:12:21 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:55016/oidc2497--- PASS: TestPins_TopLevelShorthand (0.18s)2498PASS2499Running hook tests...2500=== RUN TestSendPathsEmpty2501=== PAUSE TestSendPathsEmpty2502=== RUN TestQueueEnqueueAndFetch2503=== PAUSE TestQueueEnqueueAndFetch2504=== RUN TestQueueDeduplication2505=== PAUSE TestQueueDeduplication2506=== RUN TestQueueRemove2507=== PAUSE TestQueueRemove2508=== RUN TestQueueFetchBatchLimit2509=== PAUSE TestQueueFetchBatchLimit2510=== RUN TestQueueRetryMovesToBack2511=== PAUSE TestQueueRetryMovesToBack2512=== RUN TestQueueFetchRemoveLifecycle2513=== PAUSE TestQueueFetchRemoveLifecycle2514=== RUN TestQueueConcurrentWriters2515=== PAUSE TestQueueConcurrentWriters2516=== RUN TestQueueRemoveLargeClosure2517=== PAUSE TestQueueRemoveLargeClosure2518=== RUN TestServerClientIntegration2519--- PASS: TestServerClientIntegration (0.00s)2520=== RUN TestServerQueueError25212026/11/06 07:12:22 ERROR Failed to queue paths error="permission denied" count=12522--- PASS: TestServerQueueError (0.00s)2523=== RUN TestGetListenerSocketActivation2524 server_test.go:145: systemd socket activation does not exist on darwin2525--- SKIP: TestGetListenerSocketActivation (0.00s)2526=== RUN TestServerStalledClientDoesNotBlockShutdown2527=== PAUSE TestServerStalledClientDoesNotBlockShutdown2528=== RUN TestServerBacksOffOnAcceptErrors2529=== PAUSE TestServerBacksOffOnAcceptErrors2530=== RUN TestDrainIsolatesPoisonPath2531=== PAUSE TestDrainIsolatesPoisonPath2532=== RUN TestRunNotBlockedByPoisonHead2533=== PAUSE TestRunNotBlockedByPoisonHead2534=== RUN TestDrainGivesUpWhenServerDown2535=== PAUSE TestDrainGivesUpWhenServerDown2536=== RUN TestFailedPathPrunedByLaterClosure2537=== PAUSE TestFailedPathPrunedByLaterClosure2538=== RUN TestWorkerUploadsAndRemoves2539=== PAUSE TestWorkerUploadsAndRemoves2540=== RUN TestWorkerSkipsGCdPaths2541=== PAUSE TestWorkerSkipsGCdPaths2542=== RUN TestWorkerPrunesClosureDeps2543=== PAUSE TestWorkerPrunesClosureDeps2544=== RUN TestDrainTimeout2545=== PAUSE TestDrainTimeout2546=== RUN TestWorkerRemoveFailureIsNotProgress2547=== PAUSE TestWorkerRemoveFailureIsNotProgress2548=== RUN TestWorkerKeepsPathItCannotStat2549=== PAUSE TestWorkerKeepsPathItCannotStat2550=== CONT TestSendPathsEmpty2551--- PASS: TestSendPathsEmpty (0.00s)2552=== CONT TestDrainGivesUpWhenServerDown2553=== CONT TestDrainIsolatesPoisonPath2554=== CONT TestQueueFetchRemoveLifecycle2555=== CONT TestWorkerKeepsPathItCannotStat2556=== CONT TestWorkerRemoveFailureIsNotProgress2557=== CONT TestDrainTimeout2558=== CONT TestWorkerPrunesClosureDeps2559=== CONT TestWorkerSkipsGCdPaths2560=== CONT TestWorkerUploadsAndRemoves2561=== CONT TestFailedPathPrunedByLaterClosure2562=== CONT TestServerBacksOffOnAcceptErrors2563=== CONT TestServerStalledClientDoesNotBlockShutdown25642026/11/06 07:12:22 ERROR Accept failed error="too many open files"2565=== CONT TestQueueRetryMovesToBack2566=== CONT TestQueueRemoveLargeClosure2567=== CONT TestQueueFetchBatchLimit2568=== CONT TestQueueConcurrentWriters2569=== CONT TestQueueRemove2570=== CONT TestQueueEnqueueAndFetch2571=== CONT TestRunNotBlockedByPoisonHead2572=== CONT TestQueueDeduplication25732026/11/06 07:12:22 ERROR Accept failed error="too many open files"25742026/11/06 07:12:22 INFO Upload queue status pending=225752026/11/06 07:12:22 INFO Uploading batch count=125762026/11/06 07:12:22 WARN Store path no longer exists (garbage collected?), removing from queue path=/private/var/tb/4/scratch/520ebb830df639a2/build/TestWorkerRemoveFailureIsNotProgress702719270/002/nonexistent25772026/11/06 07:12:22 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=125782026/11/06 07:12:22 INFO Uploading batch count=225792026/11/06 07:12:22 ERROR Upload failed error="upload failed" count=225802026/11/06 07:12:22 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/4/scratch/520ebb830df639a2/build/TestDrainGivesUpWhenServerDown980859217/002/a25812026/11/06 07:12:22 WARN Store path no longer exists (garbage collected?), removing from queue path=/private/var/tb/4/scratch/520ebb830df639a2/build/TestWorkerRemoveFailureIsNotProgress702719270/002/nonexistent25822026/11/06 07:12:22 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=125832026/11/06 07:12:22 INFO Upload queue status pending=225842026/11/06 07:12:22 WARN Store path no longer exists (garbage collected?), removing from queue path=/private/var/tb/4/scratch/520ebb830df639a2/build/TestWorkerRemoveFailureIsNotProgress702719270/002/nonexistent25852026/11/06 07:12:22 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=125862026/11/06 07:12:22 INFO Upload queue status pending=225872026/11/06 07:12:22 ERROR Drain finished with paths left in queue remaining=125882026/11/06 07:12:22 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/4/scratch/520ebb830df639a2/build/TestDrainGivesUpWhenServerDown980859217/002/b25892026/11/06 07:12:22 INFO Uploading batch count=225902026/11/06 07:12:22 WARN Store path no longer exists (garbage collected?), removing from queue path=/private/var/tb/4/scratch/520ebb830df639a2/build/TestWorkerSkipsGCdPaths2996629232/002/nonexistent25912026/11/06 07:12:22 ERROR Accept failed error="too many open files"25922026/11/06 07:12:22 INFO Uploading batch count=225932026/11/06 07:12:22 INFO Uploading batch count=42594--- PASS: TestQueueRetryMovesToBack (0.02s)25952026/11/06 07:12:22 ERROR Upload failed error="upload failed" count=425962026/11/06 07:12:22 INFO Uploading batch count=125972026/11/06 07:12:22 INFO Uploading batch count=125982026/11/06 07:12:22 ERROR Upload failed error="upload failed" count=125992026/11/06 07:12:22 INFO Upload queue status pending=326002026/11/06 07:12:22 WARN Cannot stat store path, will retry later path=/private/var/tb/4/scratch/520ebb830df639a2/build/TestWorkerKeepsPathItCannotStat1035479832/002/locked/aaa error="stat /private/var/tb/4/scratch/520ebb830df639a2/build/TestWorkerKeepsPathItCannotStat1035479832/002/locked/aaa: permission denied"2601--- PASS: TestQueueEnqueueAndFetch (0.01s)26022026/11/06 07:12:22 WARN Cannot stat store path, will retry later path=/private/var/tb/4/scratch/520ebb830df639a2/build/TestWorkerKeepsPathItCannotStat1035479832/002/locked/aaa error="stat /private/var/tb/4/scratch/520ebb830df639a2/build/TestWorkerKeepsPathItCannotStat1035479832/002/locked/aaa: permission denied"26032026/11/06 07:12:22 INFO Uploading batch count=126042026/11/06 07:12:22 ERROR Upload failed error="upload failed" count=12605--- PASS: TestWorkerRemoveFailureIsNotProgress (0.02s)26062026/11/06 07:12:22 WARN Cannot stat store path, will retry later path=/private/var/tb/4/scratch/520ebb830df639a2/build/TestWorkerKeepsPathItCannotStat1035479832/002/locked/aaa error="stat /private/var/tb/4/scratch/520ebb830df639a2/build/TestWorkerKeepsPathItCannotStat1035479832/002/locked/aaa: permission denied"2607--- PASS: TestQueueFetchBatchLimit (0.02s)2608--- PASS: TestQueueRemove (0.02s)26092026/11/06 07:12:22 INFO Uploading batch count=226102026/11/06 07:12:22 ERROR Upload failed error="upload failed" count=226112026/11/06 07:12:22 ERROR Drain finished with paths left in queue remaining=126122026/11/06 07:12:22 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/4/scratch/520ebb830df639a2/build/TestDrainGivesUpWhenServerDown980859217/002/c26132026/11/06 07:12:22 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/4/scratch/520ebb830df639a2/build/TestDrainIsolatesPoisonPath786713682/002/bbb26142026/11/06 07:12:22 INFO Uploading batch count=12615--- PASS: TestQueueFetchRemoveLifecycle (0.02s)26162026/11/06 07:12:22 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/4/scratch/520ebb830df639a2/build/TestDrainGivesUpWhenServerDown980859217/002/d26172026/11/06 07:12:22 INFO Uploading batch count=126182026/11/06 07:12:22 INFO Uploading batch count=126192026/11/06 07:12:22 ERROR Upload failed error="upload failed" count=126202026/11/06 07:12:22 INFO Uploading batch count=226212026/11/06 07:12:22 ERROR Upload failed error="upload failed" count=226222026/11/06 07:12:22 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/4/scratch/520ebb830df639a2/build/TestDrainGivesUpWhenServerDown980859217/002/e2623--- PASS: TestQueueDeduplication (0.02s)26242026/11/06 07:12:22 INFO Uploading batch count=126252026/11/06 07:12:22 ERROR Upload failed error="upload failed" count=126262026/11/06 07:12:22 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/4/scratch/520ebb830df639a2/build/TestDrainGivesUpWhenServerDown980859217/002/f26272026/11/06 07:12:22 ERROR Drain finished with paths left in queue remaining=102628--- PASS: TestWorkerKeepsPathItCannotStat (0.02s)26292026/11/06 07:12:22 INFO Uploading batch count=126302026/11/06 07:12:22 ERROR Upload failed error="upload failed" count=126312026/11/06 07:12:22 ERROR Drain finished with paths left in queue remaining=12632--- PASS: TestFailedPathPrunedByLaterClosure (0.02s)2633--- PASS: TestDrainGivesUpWhenServerDown (0.02s)2634--- PASS: TestDrainIsolatesPoisonPath (0.02s)2635--- PASS: TestWorkerPrunesClosureDeps (0.04s)26362026/11/06 07:12:22 ERROR Accept failed error="too many open files"2637--- PASS: TestWorkerSkipsGCdPaths (0.04s)2638--- PASS: TestWorkerUploadsAndRemoves (0.04s)2639--- PASS: TestQueueRemoveLargeClosure (0.04s)2640--- PASS: TestQueueConcurrentWriters (0.04s)26412026/11/06 07:12:22 ERROR Accept failed error="too many open files"26422026/11/06 07:12:22 ERROR Accept failed error="too many open files"26432026/11/06 07:12:22 ERROR Failed to decode request error="read unix /private/var/tb/4/scratch/520ebb830df639a2/build/hook1116618794/test.sock->: i/o timeout"26442026/11/06 07:12:22 ERROR Failed to write response error="write unix /private/var/tb/4/scratch/520ebb830df639a2/build/hook1116618794/test.sock->: i/o timeout"2645--- PASS: TestServerStalledClientDoesNotBlockShutdown (0.20s)26462026/11/06 07:12:22 ERROR Upload failed error="context deadline exceeded" count=226472026/11/06 07:12:22 ERROR Drain finished with paths left in queue remaining=42648--- PASS: TestDrainTimeout (0.22s)26492026/11/06 07:12:22 ERROR Accept failed error="too many open files"26502026/11/06 07:12:22 ERROR Accept failed error="too many open files"2651--- PASS: TestServerBacksOffOnAcceptErrors (0.64s)26522026/11/06 07:12:23 INFO Uploading batch count=126532026/11/06 07:12:23 INFO Uploading batch count=126542026/11/06 07:12:23 INFO Uploading batch count=126552026/11/06 07:12:23 ERROR Upload failed error="upload failed" count=126562026/11/06 07:12:23 INFO Uploading batch count=126572026/11/06 07:12:23 ERROR Upload failed error="upload failed" count=126582026/11/06 07:12:23 INFO Uploading batch count=126592026/11/06 07:12:23 ERROR Upload failed error="upload failed" count=126602026/11/06 07:12:23 INFO Uploading batch count=126612026/11/06 07:12:23 ERROR Upload failed error="upload failed" count=126622026/11/06 07:12:23 ERROR Drain finished with paths left in queue remaining=12663--- PASS: TestRunNotBlockedByPoisonHead (1.03s)2664PASS2665Running signing tests...2666=== RUN TestExternalSigner2667=== PAUSE TestExternalSigner2668=== RUN TestExternalSignerWrongPublicKey2669=== PAUSE TestExternalSignerWrongPublicKey2670=== RUN TestExternalSignerErrors2671=== PAUSE TestExternalSignerErrors2672=== RUN TestExternalSignerRestartsAfterCrash2673=== PAUSE TestExternalSignerRestartsAfterCrash2674=== RUN TestExternalSignerProgramErrorKeepsProcess2675=== PAUSE TestExternalSignerProgramErrorKeepsProcess2676=== RUN TestExternalSignerClose2677=== PAUSE TestExternalSignerClose2678=== RUN TestExternalSignerRejectsInvalidPublicKey2679=== PAUSE TestExternalSignerRejectsInvalidPublicKey2680=== RUN TestExternalSignerCancellation2681=== PAUSE TestExternalSignerCancellation2682=== RUN TestGenerateFingerprint2683=== PAUSE TestGenerateFingerprint2684=== RUN TestParseSigningKey2685=== PAUSE TestParseSigningKey2686=== RUN TestSign2687=== PAUSE TestSign2688=== RUN TestSignBatch2689=== PAUSE TestSignBatch2690=== RUN TestNilKeyPublicKey2691=== PAUSE TestNilKeyPublicKey2692=== RUN TestSignErrors2693=== PAUSE TestSignErrors2694=== CONT TestExternalSigner2695=== CONT TestExternalSignerCancellation2696=== CONT TestSignBatch2697=== CONT TestSignErrors2698=== CONT TestExternalSignerProgramErrorKeepsProcess2699=== CONT TestExternalSignerErrors2700=== RUN TestExternalSignerErrors/wrong_id2701=== PAUSE TestExternalSignerErrors/wrong_id2702=== RUN TestExternalSignerErrors/wrong_signatures_shape2703=== PAUSE TestExternalSignerErrors/wrong_signatures_shape2704=== RUN TestExternalSignerErrors/wrong_signature_length2705=== PAUSE TestExternalSignerErrors/wrong_signature_length2706=== RUN TestExternalSignerErrors/program_error2707=== PAUSE TestExternalSignerErrors/program_error2708=== RUN TestExternalSignerErrors/exit_at_startup2709=== PAUSE TestExternalSignerErrors/exit_at_startup2710=== RUN TestExternalSignerErrors/too_few_signatures2711=== PAUSE TestExternalSignerErrors/too_few_signatures2712=== RUN TestExternalSignerErrors/wrong_signature_name2713=== PAUSE TestExternalSignerErrors/wrong_signature_name2714=== RUN TestExternalSignerErrors/invalid_JSON2715=== PAUSE TestExternalSignerErrors/invalid_JSON2716=== RUN TestExternalSignerErrors/wrong_shape2717=== PAUSE TestExternalSignerErrors/wrong_shape2718=== RUN TestExternalSignerErrors/null2719=== PAUSE TestExternalSignerErrors/null2720=== RUN TestExternalSignerErrors/missing_signatures2721=== PAUSE TestExternalSignerErrors/missing_signatures2722=== RUN TestExternalSignerErrors/null_signatures2723=== PAUSE TestExternalSignerErrors/null_signatures2724=== RUN TestExternalSignerErrors/unrequested_key2725=== PAUSE TestExternalSignerErrors/unrequested_key2726=== RUN TestExternalSignerErrors/missing_signature_name2727=== PAUSE TestExternalSignerErrors/missing_signature_name2728=== RUN TestExternalSignerErrors/invalid_signature_base642729=== PAUSE TestExternalSignerErrors/invalid_signature_base642730=== RUN TestExternalSignerErrors/exit_on_request2731=== PAUSE TestExternalSignerErrors/exit_on_request2732=== CONT TestExternalSignerErrors/wrong_id2733=== CONT TestExternalSignerRejectsInvalidPublicKey2734=== RUN TestExternalSignerRejectsInvalidPublicKey/#002735=== PAUSE TestExternalSignerRejectsInvalidPublicKey/#002736=== CONT TestExternalSignerClose2737=== CONT TestExternalSignerErrors/exit_on_request2738=== CONT TestExternalSignerErrors/wrong_shape2739=== CONT TestExternalSignerErrors/invalid_signature_base642740=== CONT TestExternalSignerErrors/invalid_JSON2741=== CONT TestExternalSignerErrors/missing_signature_name2742=== CONT TestExternalSignerWrongPublicKey2743=== CONT TestExternalSignerErrors/program_error2744=== CONT TestNilKeyPublicKey2745--- PASS: TestNilKeyPublicKey (0.00s)2746=== CONT TestExternalSignerErrors/wrong_signature_length2747=== CONT TestExternalSignerErrors/exit_at_startup2748=== CONT TestExternalSignerErrors/wrong_signatures_shape2749=== CONT TestExternalSignerErrors/wrong_signature_name2750=== RUN TestSignErrors/nil_key2751=== PAUSE TestSignErrors/nil_key2752=== RUN TestSignErrors/nil_narinfo2753=== PAUSE TestSignErrors/nil_narinfo2754=== CONT TestExternalSignerErrors/too_few_signatures2755=== CONT TestExternalSignerErrors/null_signatures2756--- PASS: TestSignBatch (0.00s)2757=== CONT TestParseSigningKey2758=== RUN TestParseSigningKey/valid_32-byte_key2759=== PAUSE TestParseSigningKey/valid_32-byte_key2760=== RUN TestParseSigningKey/valid_32-byte_key_with_different_name2761=== PAUSE TestParseSigningKey/valid_32-byte_key_with_different_name2762=== RUN TestParseSigningKey/no_colon2763=== PAUSE TestParseSigningKey/no_colon2764=== CONT TestGenerateFingerprint2765=== CONT TestExternalSignerRestartsAfterCrash2766=== RUN TestGenerateFingerprint/basic_with_references2767=== RUN TestExternalSignerRejectsInvalidPublicKey/no-colon2768=== PAUSE TestGenerateFingerprint/basic_with_references2769=== RUN TestGenerateFingerprint/no_references2770=== PAUSE TestExternalSignerRejectsInvalidPublicKey/no-colon2771=== PAUSE TestGenerateFingerprint/no_references2772=== RUN TestSignErrors/invalid_narinfo2773=== RUN TestGenerateFingerprint/unsorted_references_get_sorted2774=== PAUSE TestGenerateFingerprint/unsorted_references_get_sorted2775=== RUN TestGenerateFingerprint/invalid_nar_hash_prefix2776=== PAUSE TestGenerateFingerprint/invalid_nar_hash_prefix2777=== RUN TestGenerateFingerprint/invalid_nar_hash_length2778=== PAUSE TestGenerateFingerprint/invalid_nar_hash_length2779=== RUN TestGenerateFingerprint/invalid_store_path_prefix2780=== PAUSE TestGenerateFingerprint/invalid_store_path_prefix2781=== RUN TestGenerateFingerprint/invalid_reference_prefix2782=== PAUSE TestGenerateFingerprint/invalid_reference_prefix2783=== CONT TestSign2784=== RUN TestParseSigningKey/empty_name2785=== PAUSE TestParseSigningKey/empty_name2786=== RUN TestParseSigningKey/invalid_base642787=== PAUSE TestParseSigningKey/invalid_base642788--- PASS: TestSign (0.00s)2789=== RUN TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2790=== PAUSE TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2791=== RUN TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2792=== PAUSE TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2793=== RUN TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2794=== PAUSE TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2795=== CONT TestExternalSignerErrors/missing_signatures2796=== PAUSE TestSignErrors/invalid_narinfo2797=== RUN TestSignErrors/canceled2798=== PAUSE TestSignErrors/canceled2799=== CONT TestExternalSignerErrors/unrequested_key2800=== CONT TestExternalSignerErrors/null2801=== CONT TestGenerateFingerprint/basic_with_references2802=== RUN TestParseSigningKey/wrong_length2803=== PAUSE TestParseSigningKey/wrong_length2804=== CONT TestGenerateFingerprint/invalid_reference_prefix2805=== CONT TestGenerateFingerprint/invalid_store_path_prefix2806=== CONT TestGenerateFingerprint/invalid_nar_hash_length2807=== CONT TestGenerateFingerprint/invalid_nar_hash_prefix2808=== CONT TestGenerateFingerprint/no_references2809=== CONT TestGenerateFingerprint/unsorted_references_get_sorted2810=== CONT TestExternalSignerRejectsInvalidPublicKey/#002811--- PASS: TestGenerateFingerprint (0.00s)2812 --- PASS: TestGenerateFingerprint/basic_with_references (0.00s)2813 --- PASS: TestGenerateFingerprint/invalid_reference_prefix (0.00s)2814 --- PASS: TestGenerateFingerprint/invalid_store_path_prefix (0.00s)2815 --- PASS: TestGenerateFingerprint/invalid_nar_hash_length (0.00s)2816 --- PASS: TestGenerateFingerprint/invalid_nar_hash_prefix (0.00s)2817 --- PASS: TestGenerateFingerprint/no_references (0.00s)2818 --- PASS: TestGenerateFingerprint/unsorted_references_get_sorted (0.00s)2819=== CONT TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2820=== CONT TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2821=== CONT TestSignErrors/canceled2822=== CONT TestExternalSignerRejectsInvalidPublicKey/no-colon2823=== CONT TestSignErrors/nil_key2824=== CONT TestSignErrors/nil_narinfo2825=== CONT TestSignErrors/invalid_narinfo2826--- PASS: TestSignErrors (0.00s)2827 --- PASS: TestSignErrors/canceled (0.00s)2828 --- PASS: TestSignErrors/nil_key (0.00s)2829 --- PASS: TestSignErrors/nil_narinfo (0.00s)2830 --- PASS: TestSignErrors/invalid_narinfo (0.00s)2831=== CONT TestParseSigningKey/valid_32-byte_key2832=== CONT TestParseSigningKey/empty_name2833=== CONT TestParseSigningKey/invalid_base642834=== CONT TestParseSigningKey/no_colon2835=== CONT TestParseSigningKey/valid_32-byte_key_with_different_name2836=== CONT TestParseSigningKey/wrong_length2837--- PASS: TestParseSigningKey (0.00s)2838 --- PASS: TestParseSigningKey/valid_32-byte_key (0.00s)2839 --- PASS: TestParseSigningKey/empty_name (0.00s)2840 --- PASS: TestParseSigningKey/invalid_base64 (0.00s)2841 --- PASS: TestParseSigningKey/no_colon (0.00s)2842 --- PASS: TestParseSigningKey/valid_32-byte_key_with_different_name (0.00s)2843 --- PASS: TestParseSigningKey/wrong_length (0.00s)2844=== CONT TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2845--- PASS: TestExternalSignerRejectsInvalidPublicKey (0.00s)2846 --- PASS: TestExternalSignerRejectsInvalidPublicKey/#00 (0.00s)2847 --- PASS: TestExternalSignerRejectsInvalidPublicKey/test-key:YQ== (0.00s)2848 --- PASS: TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA= (0.00s)2849 --- PASS: TestExternalSignerRejectsInvalidPublicKey/no-colon (0.00s)2850 --- PASS: TestExternalSignerRejectsInvalidPublicKey/test-key:invalid! (0.00s)2851--- PASS: TestExternalSignerCancellation (0.12s)2852--- PASS: TestExternalSignerClose (0.49s)2853--- PASS: TestExternalSignerRestartsAfterCrash (1.20s)2854/private/var/tb/4/scratch/520ebb830df639a2/build/TestExternalSignerRestartsAfterCrash3814780792/001/sign program: line 7: /private/var/tb/4/scratch/520ebb830df639a2/build/TestExternalSignerRestartsAfterCrash3814780792/001/sign program.starts: No such file or directory2855--- PASS: TestExternalSignerProgramErrorKeepsProcess (1.26s)2856--- PASS: TestExternalSigner (1.43s)2857--- PASS: TestExternalSignerWrongPublicKey (1.49s)2858--- PASS: TestExternalSignerErrors (0.00s)2859 --- PASS: TestExternalSignerErrors/missing_signature_name (0.17s)2860 --- PASS: TestExternalSignerErrors/wrong_shape (0.25s)2861 --- PASS: TestExternalSignerErrors/invalid_JSON (0.33s)2862 --- PASS: TestExternalSignerErrors/null_signatures (0.41s)2863 --- PASS: TestExternalSignerErrors/too_few_signatures (0.56s)2864 --- PASS: TestExternalSignerErrors/missing_signatures (0.64s)2865 --- PASS: TestExternalSignerErrors/invalid_signature_base64 (0.72s)2866 --- PASS: TestExternalSignerErrors/exit_on_request (0.80s)2867 --- PASS: TestExternalSignerErrors/wrong_signatures_shape (0.87s)2868 --- PASS: TestExternalSignerErrors/unrequested_key (0.95s)2869 --- PASS: TestExternalSignerErrors/program_error (1.03s)2870 --- PASS: TestExternalSignerErrors/wrong_signature_name (1.11s)2871 --- PASS: TestExternalSignerErrors/wrong_signature_length (1.34s)2872 --- PASS: TestExternalSignerErrors/wrong_id (1.57s)2873 --- PASS: TestExternalSignerErrors/exit_at_startup (1.65s)2874 --- PASS: TestExternalSignerErrors/null (1.73s)2875PASS2876Running OpenBao signer tests...2877=== RUN TestSign2878=== PAUSE TestSign2879=== RUN TestSignErrors2880=== PAUSE TestSignErrors2881=== RUN TestServe2882=== PAUSE TestServe2883=== RUN TestServeRejectsGarbage2884=== PAUSE TestServeRejectsGarbage2885=== CONT TestSign2886=== CONT TestSignErrors2887=== CONT TestServe2888=== RUN TestSignErrors/http_error2889=== PAUSE TestSignErrors/http_error2890=== RUN TestSignErrors/invalid_json2891=== PAUSE TestSignErrors/invalid_json2892=== RUN TestSignErrors/no_prefix2893=== PAUSE TestSignErrors/no_prefix2894=== RUN TestSignErrors/invalid_base642895=== PAUSE TestSignErrors/invalid_base642896=== CONT TestSignErrors/http_error2897=== CONT TestSignErrors/invalid_json2898=== CONT TestServeRejectsGarbage2899--- PASS: TestServeRejectsGarbage (0.00s)2900=== CONT TestSignErrors/invalid_base642901=== CONT TestSignErrors/no_prefix2902--- PASS: TestServe (0.00s)2903--- PASS: TestSign (0.00s)2904--- PASS: TestSignErrors (0.00s)2905 --- PASS: TestSignErrors/invalid_base64 (0.00s)2906 --- PASS: TestSignErrors/invalid_json (0.00s)2907 --- PASS: TestSignErrors/no_prefix (0.00s)2908 --- PASS: TestSignErrors/http_error (0.00s)2909PASS