niks3-go-unit-tests
checks.aarch64-darwin.go-unit-tests
· build #465
· 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.07s)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 TestDumpPathWriterError118=== CONT TestGetStorePathHash119=== CONT TestSetClientTLS120=== CONT TestPathInfoHashCompatibility121=== RUN TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)122=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)123=== CONT TestShellSplitErrors124--- PASS: TestShellSplitErrors (0.00s)125=== CONT TestConvertHashToNix32126=== RUN TestConvertHashToNix32/SRI_format_to_Nix32127=== PAUSE TestConvertHashToNix32/SRI_format_to_Nix32128=== CONT TestStreamPushIsolatesFailures129=== CONT TestResolveStorePath130=== CONT TestRegisterUploadedObject_BoundedAgainstSilentServer131=== CONT TestRateLimiterFeedback_400DoesNotCountAsSuccess132=== CONT TestRateLimiterFeedback133=== CONT TestPathInfoCACompatibility134=== RUN TestPathInfoCACompatibility/null_ca_field135=== CONT TestStreamPushStopsWhenCanceled136=== PAUSE TestPathInfoCACompatibility/null_ca_field137=== CONT TestClientSignaturesByStorePath138=== CONT TestStreamPushReportsSkippedPaths139=== CONT TestStreamPushReportsSignatures140=== RUN TestGetStorePathHash/valid_store_path141=== CONT TestStreamPushRequestLine142=== CONT TestParsePathInfoJSON143=== CONT TestStreamPushGivesUpOnDeadServer144=== CONT TestStreamPushBatchesUnderLoad145=== CONT TestStreamPushReportsEveryPath146=== CONT TestEncodeNixBase32WithRealHash147=== RUN TestPathInfoHashCompatibility/old_string_format_with_colon148=== CONT TestParsePathInfoJSONMultiplePaths149=== RUN TestConvertHashToNix32/already_Nix32_format150=== RUN TestPathInfoCACompatibility/old_string_format_-_text151--- PASS: TestStreamPushStopsWhenCanceled (0.00s)152--- PASS: TestClientSignaturesByStorePath (0.00s)153=== CONT TestUploadMultipart_PartsInParallel1542026/11/06 07:18:07 WARN Rate limiter enabled after throttle name=server-test rate=51552026/11/06 07:18:07 ERROR Upload failed error="bad path" count=3156=== RUN TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths157=== RUN TestParsePathInfoJSON/Nix_format158--- PASS: TestEncodeNixBase32WithRealHash (0.00s)159=== PAUSE TestParsePathInfoJSON/Nix_format160=== RUN TestParsePathInfoJSON/Lix_format161=== PAUSE TestParsePathInfoJSON/Lix_format162=== RUN TestParsePathInfoJSON/empty_input163=== PAUSE TestParsePathInfoJSON/empty_input164=== RUN TestParsePathInfoJSON/whitespace_only165=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_colon166=== RUN TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI167=== PAUSE TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI168=== RUN TestPathInfoHashCompatibility/new_structured_format_with_sha512169=== PAUSE TestPathInfoHashCompatibility/new_structured_format_with_sha5121702026/11/06 07:18:07 ERROR Upload failed error="connection refused" count=201712026/11/06 07:18:07 ERROR Server seems unavailable, giving up on batch untried=17172=== PAUSE TestConvertHashToNix32/already_Nix32_format173=== PAUSE TestGetStorePathHash/valid_store_path174=== RUN TestGetStorePathHash/basename_without_hyphen_should_error175=== PAUSE TestGetStorePathHash/basename_without_hyphen_should_error176=== RUN TestGetStorePathHash/hash_with_invalid_characters_should_error177=== PAUSE TestGetStorePathHash/hash_with_invalid_characters_should_error178=== RUN TestGetStorePathHash/hash_with_wrong_length_should_error179=== PAUSE TestGetStorePathHash/hash_with_wrong_length_should_error180=== PAUSE TestParsePathInfoJSON/whitespace_only181=== RUN TestParsePathInfoJSON/invalid_JSON182=== PAUSE TestParsePathInfoJSON/invalid_JSON183=== CONT TestSupersededNARStillUploadsListing184=== RUN TestSupersededNARStillUploadsListing/small_NAR185=== PAUSE TestSupersededNARStillUploadsListing/small_NAR186=== CONT TestUploadMultipart_SupersededByPeer187=== RUN TestUploadMultipart_SupersededByPeer/exists188=== PAUSE TestUploadMultipart_SupersededByPeer/exists189=== RUN TestUploadMultipart_SupersededByPeer/missing190--- PASS: TestResolveStorePath (0.00s)191=== PAUSE TestPathInfoCACompatibility/old_string_format_-_text192=== RUN TestPathInfoCACompatibility/old_string_format_-_fixed_recursive193=== PAUSE TestPathInfoCACompatibility/old_string_format_-_fixed_recursive194=== RUN TestPathInfoCACompatibility/new_structured_format_-_text195=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_text196=== RUN TestPathInfoCACompatibility/new_structured_format_-_nar_method197=== PAUSE TestUploadMultipart_SupersededByPeer/missing198=== RUN TestSupersededNARStillUploadsListing/dump_cut_short199=== PAUSE TestSupersededNARStillUploadsListing/dump_cut_short200=== RUN TestSupersededNARStillUploadsListing/listing_upload_fails201=== CONT TestUploadMultipart_ReturnsAfterDroppedBody202=== RUN TestStreamPushBatchesUnderLoad/oneAtATime=false203=== PAUSE TestStreamPushBatchesUnderLoad/oneAtATime=false204=== RUN TestStreamPushBatchesUnderLoad/oneAtATime=true205=== PAUSE TestStreamPushBatchesUnderLoad/oneAtATime=true206=== PAUSE TestSupersededNARStillUploadsListing/listing_upload_fails207=== CONT TestDoWithRetry_FinalResponseBodyReadable208=== CONT TestShellSplit209--- PASS: TestShellSplit (0.00s)210=== CONT TestRetryTimeoutOutlastsMaxRetries211=== PAUSE TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths212=== RUN TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths213=== PAUSE TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths214=== CONT TestEncodeNixBase32215=== RUN TestEncodeNixBase32/test_string_hash216=== CONT TestRunGarbageCollection_NotFoundAfterLocalRun217=== CONT TestDumpPathSingleFile218=== CONT TestDumpPathMatchesNix219=== RUN TestRateLimiterFeedback/429_enables_limiter220=== RUN TestConvertHashToNix32/invalid_format221=== CONT TestPartSizeForNAR222=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_nar_method223=== PAUSE TestEncodeNixBase32/test_string_hash224=== RUN TestEncodeNixBase32/empty_input225=== CONT TestFilterOversizedClosures226=== RUN TestFilterOversizedClosures/no_limit_keeps_everything227=== PAUSE TestEncodeNixBase32/empty_input228=== PAUSE TestFilterOversizedClosures/no_limit_keeps_everything229=== CONT TestCaseHackSuffix230=== RUN TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped231=== PAUSE TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped232=== RUN TestFilterOversizedClosures/all_closures_skipped233=== PAUSE TestRateLimiterFeedback/429_enables_limiter234=== CONT TestScriptTokenNoExpiryRerunsEveryCall235=== CONT TestScriptTokenEmptyCommand236=== CONT TestScriptTokenScriptFails237=== CONT TestScriptTokenBadJSON238=== CONT TestScriptTokenEmptyToken239=== RUN TestRateLimiterFeedback/503_enables_limiter240=== PAUSE TestRateLimiterFeedback/503_enables_limiter241=== RUN TestRateLimiterFeedback/200_does_not_enable_limiter242=== PAUSE TestRateLimiterFeedback/200_does_not_enable_limiter243=== RUN TestRateLimiterFeedback/400_does_not_enable_limiter244=== PAUSE TestRateLimiterFeedback/400_does_not_enable_limiter245=== PAUSE TestConvertHashToNix32/invalid_format246=== CONT TestScriptTokenCachesUntilRefresh2472026/11/06 07:18:07 ERROR Upload failed error=boom count=12482026/11/06 07:18:07 ERROR Upload failed error=boom count=1249=== CONT TestRunGarbageCollection_FinishedOnAnotherReplica2502026/11/06 07:18:07 WARN Rate limiter enabled after throttle name=server-test rate=5251=== RUN TestPartSizeForNAR/zero_stays_at_minimum252=== PAUSE TestPartSizeForNAR/zero_stays_at_minimum253=== RUN TestPartSizeForNAR/small_stays_at_minimum254=== PAUSE TestPartSizeForNAR/small_stays_at_minimum255=== RUN TestPartSizeForNAR/80_GiB_fits_at_minimum256=== PAUSE TestPartSizeForNAR/80_GiB_fits_at_minimum257=== RUN TestPartSizeForNAR/115_GiB_needs_larger_parts258--- PASS: TestStreamPushIsolatesFailures (0.02s)259--- PASS: TestStreamPushReportsEveryPath (0.02s)260--- PASS: TestScriptTokenEmptyCommand (0.00s)261--- PASS: TestStreamPushGivesUpOnDeadServer (0.02s)262--- PASS: TestStreamPushReportsSkippedPaths (0.02s)263--- PASS: TestStreamPushReportsSignatures (0.02s)264=== RUN TestSetClientTLS/rejects_connection_without_client_cert265=== PAUSE TestSetClientTLS/rejects_connection_without_client_cert266=== RUN TestSetClientTLS/succeeds_with_client_cert_and_CA267=== PAUSE TestSetClientTLS/succeeds_with_client_cert_and_CA268=== RUN TestSetClientTLS/preserves_debug_logging_transport269=== PAUSE TestSetClientTLS/preserves_debug_logging_transport2702026/11/06 07:18:07 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:55042271=== PAUSE TestFilterOversizedClosures/all_closures_skipped272=== CONT TestUploadBuildLog_FileBodyReplayedOnRetry2732026/11/06 07:18:07 WARN Request returned retryable status, retrying attempt=1 backoff=1ms status=502 url=http://127.0.0.1:550432742026/11/06 07:18:07 WARN Rate limiter enabled after throttle name=server-test rate=52752026/11/06 07:18:07 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:55038276=== CONT TestRegisterUploadedObjectReusesConnections277=== CONT TestFileTokenReadsAndCaches2782026/11/06 07:18:07 INFO Garbage collection started279=== PAUSE TestPartSizeForNAR/115_GiB_needs_larger_parts280=== RUN TestPartSizeForNAR/1_TiB281=== PAUSE TestPartSizeForNAR/1_TiB282=== RUN TestPartSizeForNAR/5_TiB_S3_max_object283=== PAUSE TestPartSizeForNAR/5_TiB_S3_max_object284=== RUN TestPartSizeForNAR/capped_at_5_GiB285=== PAUSE TestPartSizeForNAR/capped_at_5_GiB286=== CONT TestFileTokenEmpty2872026/11/06 07:18:07 WARN Rate limiter backed off name=server-test rate=5288--- PASS: TestDoServerRequestAttachesToken (0.03s)2892026/11/06 07:18:07 WARN Request returned retryable status, retrying attempt=2 backoff=1ms status=502 url=http://127.0.0.1:550432902026/11/06 07:18:07 WARN Rate limiter backed off name=server-test rate=52912026/11/06 07:18:07 WARN Request returned retryable status, retrying attempt=2 backoff=0s status=503 url=http://127.0.0.1:55038292=== CONT TestFileTokenMissing293=== CONT TestSetClientTLSErrors294=== CONT TestSetClientTLSDoesNotMutateDefaultTransport295=== CONT TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)296=== CONT TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI297=== RUN TestSetClientTLSErrors/missing_cert_file298=== PAUSE TestSetClientTLSErrors/missing_cert_file299=== RUN TestSetClientTLSErrors/missing_key_file300=== PAUSE TestSetClientTLSErrors/missing_key_file301=== RUN TestSetClientTLSErrors/missing_ca_file302=== PAUSE TestSetClientTLSErrors/missing_ca_file303=== RUN TestSetClientTLSErrors/invalid_ca_file304=== PAUSE TestSetClientTLSErrors/invalid_ca_file305=== CONT TestStaticToken306=== CONT TestPathInfoHashCompatibility/old_string_format_with_colon307=== CONT TestGetStorePathHash/valid_store_path308=== CONT TestParsePathInfoJSON/Nix_format309=== CONT TestParsePathInfoJSON/invalid_JSON310=== CONT TestParsePathInfoJSON/whitespace_only311=== CONT TestParsePathInfoJSON/empty_input312=== CONT TestParsePathInfoJSON/Lix_format3132026/11/06 07:18:07 INFO Garbage collection started314=== CONT TestGetStorePathHash/hash_with_invalid_characters_should_error315=== CONT TestGetStorePathHash/hash_with_wrong_length_should_error316=== CONT TestGetStorePathHash/basename_without_hyphen_should_error317=== CONT TestUploadMultipart_SupersededByPeer/exists318=== CONT TestUploadMultipart_SupersededByPeer/missing319=== CONT TestStreamPushBatchesUnderLoad/oneAtATime=false320=== CONT TestSupersededNARStillUploadsListing/small_NAR321=== CONT TestSupersededNARStillUploadsListing/listing_upload_fails3222026/11/06 07:18:07 INFO Uploading abc-hello (1.0GB)323=== CONT TestPathInfoHashCompatibility/new_structured_format_with_sha512324=== CONT TestStreamPushBatchesUnderLoad/oneAtATime=true325=== CONT TestSupersededNARStillUploadsListing/dump_cut_short3262026/11/06 07:18:07 INFO Uploading abc-hello (1.0GB)327--- PASS: TestRunGarbageCollection_NotFoundAfterLocalRun (0.03s)328--- PASS: TestDoWithRetry_BodyReplayedViaGetBody (0.03s)329--- PASS: TestUploadMultipart_ReturnsAfterDroppedBody (0.03s)330--- PASS: TestStaticToken (0.00s)331--- PASS: TestScriptTokenScriptFails (0.01s)332--- PASS: TestGetStorePathHash (0.00s)333 --- PASS: TestGetStorePathHash/valid_store_path (0.00s)334 --- PASS: TestGetStorePathHash/hash_with_invalid_characters_should_error (0.00s)335 --- PASS: TestGetStorePathHash/hash_with_wrong_length_should_error (0.00s)336 --- PASS: TestGetStorePathHash/basename_without_hyphen_should_error (0.00s)337--- PASS: TestFileTokenEmpty (0.01s)338--- PASS: TestFileTokenReadsAndCaches (0.02s)339--- PASS: TestFileTokenMissing (0.01s)340--- PASS: TestPathInfoHashCompatibility (0.00s)341 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) (0.00s)342 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_colon (0.00s)343 --- PASS: TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI (0.01s)344 --- PASS: TestPathInfoHashCompatibility/new_structured_format_with_sha512 (0.00s)345--- PASS: TestDoWithRetry_FinalResponseBodyReadable (0.03s)346=== CONT TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths347--- PASS: TestSetClientTLSDoesNotMutateDefaultTransport (0.02s)348--- PASS: TestStreamPushBatchesUnderLoad (0.00s)349 --- PASS: TestStreamPushBatchesUnderLoad/oneAtATime=true (0.00s)350 --- PASS: TestStreamPushBatchesUnderLoad/oneAtATime=false (0.02s)351=== CONT TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths352=== CONT TestPathInfoCACompatibility/null_ca_field353=== CONT TestPathInfoCACompatibility/new_structured_format_-_text354=== CONT TestPathInfoCACompatibility/old_string_format_-_fixed_recursive355=== CONT TestPathInfoCACompatibility/old_string_format_-_text356=== CONT TestPathInfoCACompatibility/new_structured_format_-_nar_method357--- PASS: TestPathInfoCACompatibility (0.00s)358 --- PASS: TestPathInfoCACompatibility/null_ca_field (0.00s)359 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_text (0.00s)360 --- PASS: TestPathInfoCACompatibility/old_string_format_-_fixed_recursive (0.00s)361 --- PASS: TestPathInfoCACompatibility/old_string_format_-_text (0.00s)362 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_nar_method (0.00s)363=== CONT TestEncodeNixBase32/test_string_hash364=== CONT TestEncodeNixBase32/empty_input365--- PASS: TestEncodeNixBase32 (0.02s)366 --- PASS: TestEncodeNixBase32/test_string_hash (0.00s)367 --- PASS: TestEncodeNixBase32/empty_input (0.00s)368=== CONT TestRateLimiterFeedback/429_enables_limiter3692026/11/06 07:18:07 WARN Request returned retryable status, retrying attempt=1 backoff=1ms status=502 url=http://127.0.0.1:55043370=== CONT TestConvertHashToNix32/SRI_format_to_Nix32371=== CONT TestConvertHashToNix32/invalid_format372=== CONT TestConvertHashToNix32/already_Nix32_format373--- PASS: TestConvertHashToNix32 (0.02s)374 --- PASS: TestConvertHashToNix32/SRI_format_to_Nix32 (0.00s)375 --- PASS: TestConvertHashToNix32/invalid_format (0.00s)376 --- PASS: TestConvertHashToNix32/already_Nix32_format (0.00s)377=== CONT TestRateLimiterFeedback/200_does_not_enable_limiter378--- PASS: TestParsePathInfoJSON (0.00s)379 --- PASS: TestParsePathInfoJSON/Nix_format (0.00s)380 --- PASS: TestParsePathInfoJSON/invalid_JSON (0.00s)381 --- PASS: TestParsePathInfoJSON/whitespace_only (0.00s)382 --- PASS: TestParsePathInfoJSON/empty_input (0.00s)383 --- PASS: TestParsePathInfoJSON/Lix_format (0.03s)384=== CONT TestRateLimiterFeedback/400_does_not_enable_limiter3852026/11/06 07:18:07 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=0386--- PASS: TestScriptTokenEmptyToken (0.05s)387=== CONT TestRateLimiterFeedback/503_enables_limiter3882026/11/06 07:18:07 WARN Request returned retryable status, retrying attempt=2 backoff=1ms status=502 url=http://127.0.0.1:550433892026/11/06 07:18:07 WARN Rate limiter enabled after throttle name=server-test rate=53902026/11/06 07:18:07 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=429 url=http://127.0.0.1:55129391=== CONT TestSetClientTLS/rejects_connection_without_client_cert392--- PASS: TestParsePathInfoJSONMultiplePaths (0.00s)393 --- PASS: TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths (0.00s)394 --- PASS: TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths (0.01s)395=== CONT TestFilterOversizedClosures/no_limit_keeps_everything3962026/11/06 07:18:07 WARN Rate limiter enabled after throttle name=server-test rate=53972026/11/06 07:18:07 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:55137398=== CONT TestFilterOversizedClosures/all_closures_skipped3992026/11/06 07:18:07 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=50400=== CONT TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped4012026/11/06 07:18:07 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=2000402--- PASS: TestFilterOversizedClosures (0.02s)403 --- PASS: TestFilterOversizedClosures/no_limit_keeps_everything (0.00s)404 --- PASS: TestFilterOversizedClosures/all_closures_skipped (0.00s)405 --- PASS: TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped (0.00s)4062026/11/06 07:18:07 WARN Rate limiter enabled after throttle name=s3-test rate=54072026/11/06 07:18:07 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:550814082026/11/06 07:18:07 WARN Rate limiter backed off name=server-test rate=5409=== CONT TestPartSizeForNAR/zero_stays_at_minimum410=== CONT TestPartSizeForNAR/1_TiB411=== CONT TestPartSizeForNAR/capped_at_5_GiB412=== CONT TestPartSizeForNAR/5_TiB_S3_max_object413=== CONT TestPartSizeForNAR/80_GiB_fits_at_minimum414=== CONT TestPartSizeForNAR/115_GiB_needs_larger_parts415=== CONT TestSetClientTLSErrors/missing_cert_file416=== CONT TestPartSizeForNAR/small_stays_at_minimum417--- PASS: TestPartSizeForNAR (0.03s)418 --- PASS: TestPartSizeForNAR/zero_stays_at_minimum (0.00s)419 --- PASS: TestPartSizeForNAR/1_TiB (0.00s)420 --- PASS: TestPartSizeForNAR/capped_at_5_GiB (0.00s)421 --- PASS: TestPartSizeForNAR/5_TiB_S3_max_object (0.00s)422 --- PASS: TestPartSizeForNAR/80_GiB_fits_at_minimum (0.00s)423 --- PASS: TestPartSizeForNAR/115_GiB_needs_larger_parts (0.00s)424 --- PASS: TestPartSizeForNAR/small_stays_at_minimum (0.00s)425=== CONT TestSetClientTLSErrors/invalid_ca_file426--- PASS: TestUploadMultipart_SupersededByPeer (0.00s)427 --- PASS: TestUploadMultipart_SupersededByPeer/exists (0.03s)428 --- PASS: TestUploadMultipart_SupersededByPeer/missing (0.03s)429=== CONT TestSetClientTLSErrors/missing_ca_file430--- PASS: TestUploadBuildLog_FileBodyReplayedOnRetry (0.05s)4312026/11/06 07:18:07 WARN Request returned retryable status, retrying attempt=3 backoff=1ms status=502 url=http://127.0.0.1:55043432=== CONT TestSetClientTLSErrors/missing_key_file4332026/11/06 07:18:07 WARN Rate limiter backed off name=server-test rate=54342026/11/06 07:18:07 WARN Request returned retryable status, retrying attempt=4 backoff=1ms status=502 url=http://127.0.0.1:55043435=== CONT TestSetClientTLS/succeeds_with_client_cert_and_CA436=== CONT TestSetClientTLS/preserves_debug_logging_transport437--- PASS: TestSetClientTLSErrors (0.00s)438 --- PASS: TestSetClientTLSErrors/missing_cert_file (0.00s)439 --- PASS: TestSetClientTLSErrors/missing_key_file (0.00s)440 --- PASS: TestSetClientTLSErrors/missing_ca_file (0.00s)441 --- PASS: TestSetClientTLSErrors/invalid_ca_file (0.01s)442--- PASS: TestStreamPushRequestLine (0.08s)4432026/11/06 07:18:07 WARN Garbage collection finished on another replica. Its statistics are not available here444--- PASS: TestRunGarbageCollection_FinishedOnAnotherReplica (0.06s)4452026/11/06 07:18:07 WARN Request returned retryable status, retrying attempt=5 backoff=1ms status=502 url=http://127.0.0.1:55043446--- PASS: TestRateLimiterFeedback (0.02s)447 --- PASS: TestRateLimiterFeedback/400_does_not_enable_limiter (0.00s)448 --- PASS: TestRateLimiterFeedback/429_enables_limiter (0.01s)449 --- PASS: TestRateLimiterFeedback/503_enables_limiter (0.01s)450 --- PASS: TestRateLimiterFeedback/200_does_not_enable_limiter (0.02s)451--- PASS: TestScriptTokenNoExpiryRerunsEveryCall (0.07s)4522026/11/06 07:18:07 WARN Request returned retryable status, retrying attempt=6 backoff=1ms status=502 url=http://127.0.0.1:550434532026/11/06 07:18:07 WARN Request returned retryable status, retrying attempt=7 backoff=1ms status=502 url=http://127.0.0.1:550434542026/11/06 07:18:07 WARN Request returned retryable status, retrying attempt=8 backoff=1ms status=502 url=http://127.0.0.1:550434552026/11/06 07:18:07 WARN Request returned retryable status, retrying attempt=9 backoff=1ms status=502 url=http://127.0.0.1:550434562026/11/06 07:18:07 WARN Request returned retryable status, retrying attempt=10 backoff=1ms status=502 url=http://127.0.0.1:550434572026/11/06 07:18:07 WARN Request returned retryable status, retrying attempt=11 backoff=1ms status=502 url=http://127.0.0.1:550434582026/11/06 07:18:07 WARN Request returned retryable status, retrying attempt=12 backoff=1ms status=502 url=http://127.0.0.1:550434592026/11/06 07:18:07 WARN Request returned retryable status, retrying attempt=13 backoff=1ms status=502 url=http://127.0.0.1:550434602026/11/06 07:18:07 WARN Request returned retryable status, retrying attempt=14 backoff=1ms status=502 url=http://127.0.0.1:550434612026/11/06 07:18:07 WARN Request returned retryable status, retrying attempt=15 backoff=1ms status=502 url=http://127.0.0.1:55043462--- PASS: TestScriptTokenBadJSON (0.13s)4632026/11/06 07:18:07 WARN Request returned retryable status, retrying attempt=16 backoff=1ms status=502 url=http://127.0.0.1:550434642026/11/06 07:18:07 WARN Request returned retryable status, retrying attempt=17 backoff=1ms status=502 url=http://127.0.0.1:550434652026/11/06 07:18:07 INFO Uploading abc-hello (1.0GB)466--- PASS: TestRetryTimeoutOutlastsMaxRetries (0.17s)467--- PASS: TestRegisterUploadedObjectReusesConnections (0.15s)4682026/11/06 07:18:07 http: TLS handshake error from 127.0.0.1:55140: remote error: tls: bad certificate469--- PASS: TestSetClientTLS (0.03s)470 --- PASS: TestSetClientTLS/succeeds_with_client_cert_and_CA (0.02s)471 --- PASS: TestSetClientTLS/preserves_debug_logging_transport (0.03s)472 --- PASS: TestSetClientTLS/rejects_connection_without_client_cert (0.10s)473--- PASS: TestDumpPathWriterError (0.18s)474--- PASS: TestDumpPathSingleFile (0.20s)475--- PASS: TestCaseHackSuffix (0.18s)476--- PASS: TestScriptTokenCachesUntilRefresh (0.19s)4772026/11/06 07:18:07 WARN Request failed, retrying attempt=1 backoff=100ms error="Put \"http://127.0.0.1:55112/part/2\": uploading part 1: server returned 404: no such upload\n" url=http://127.0.0.1:55112/part/24782026/11/06 07:18:07 ERROR Failed to close zstd encoder error="io: read/write on closed pipe"479--- PASS: TestDumpPathMatchesNix (0.25s)480--- PASS: TestUploadMultipart_PartsInParallel (0.66s)481--- PASS: TestSupersededNARStillUploadsListing (0.00s)482 --- PASS: TestSupersededNARStillUploadsListing/small_NAR (0.03s)483 --- PASS: TestSupersededNARStillUploadsListing/listing_upload_fails (0.05s)484 --- PASS: TestSupersededNARStillUploadsListing/dump_cut_short (0.66s)4852026/11/06 07:18:08 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:55037/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:55037/api/uploads/complete4862026/11/06 07:18:08 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:55037/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:55037/api/uploads/complete4872026/11/06 07:18:08 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"4882026/11/06 07:18:08 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"4892026/11/06 07:18:08 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:55037/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:55037/api/uploads/complete490--- PASS: TestRateLimiterFeedback_400DoesNotCountAsSuccess (1.00s)4912026/11/06 07:18:08 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"492--- PASS: TestRegisterUploadedObject_BoundedAgainstSilentServer (1.00s)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/6ba07dd8cd494155/build/postgres1642359147/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/6ba07dd8cd494155/build/postgres1642359147/data -l logfile start521522/private/var/tb/4/scratch/6ba07dd8cd494155/build/postgres1642359147:5432 - no response5232026-11-06 07:18:08.852 UTC [85682] LOG: starting PostgreSQL 18.6 on aarch64-apple-darwin25.6.0, compiled by clang version 21.1.8, 64-bit5242026-11-06 07:18:08.852 UTC [85682] LOG: listening on Unix socket "/private/var/tb/4/scratch/6ba07dd8cd494155/build/postgres1642359147/.s.PGSQL.5432"5252026-11-06 07:18:08.856 UTC [85689] LOG: database system was shut down at 2026-11-06 07:18:08 UTC5262026-11-06 07:18:08.857 UTC [85682] LOG: database system is ready to accept connections527/private/var/tb/4/scratch/6ba07dd8cd494155/build/postgres1642359147:5432 - accepting connections528{"timestamp":"2026-11-06T07:18:09.116386Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"2eb4c781-eb27-452c-8ec3-d4a5a6beb424","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":11,"result":"server_error","target":"rustfs::server::http","filename":"rustfs/src/server/layer.rs","line_number":502,"threadName":"rustfs-worker","threadId":"ThreadId(9)"}529{"timestamp":"2026-11-06T07:18:09.226247Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"7efce00f-5bbd-45be-8887-80b2c6365705","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(8)"}530{"timestamp":"2026-11-06T07:18:09.329563Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"aeee7e0f-40c9-4737-bc6c-db03c3f6a9bd","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)"}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:18:09 INFO lead: acquired remote=192.0.2.1:12345792026/11/06 07:18:10 INFO lead: released remote=192.0.2.1:12345802026/11/06 07:18:10 INFO lead: acquired remote=192.0.2.1:12345812026/11/06 07:18:11 INFO lead: released remote=192.0.2.1:1234582--- PASS: TestLeadIncumbentWinsAfterRestart (1.95s)583=== RUN TestLeadIncumbentAnnouncesAtOnce584=== PAUSE TestLeadIncumbentAnnouncesAtOnce585=== RUN TestLeadEndsOnShutdown586=== PAUSE TestLeadEndsOnShutdown587=== RUN TestLeadEndsWhenItsConnectionHangs5882026/11/06 07:18:11 INFO lead: acquired remote=192.0.2.1:12345892026-11-06 07:18:12.818 UTC [86095] FATAL: terminating connection due to administrator command5902026/11/06 07:18:13 INFO lead: acquired remote=192.0.2.1:12345912026/11/06 07:18:14 WARN lead: lock connection lost error="timeout: context deadline exceeded"5922026/11/06 07:18:14 INFO lead: released remote=192.0.2.1:12345932026/11/06 07:18:14 INFO lead: released remote=192.0.2.1:1234594--- PASS: TestLeadEndsWhenItsConnectionHangs (2.83s)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:18:14 INFO Starting HTTP server address=127.0.0.1:551776952026/11/06 07:18:14 INFO Starting HTTP server address=proxy.sock6962026/11/06 07:18:14 WARN mTLS auth: subject not in bound subjects subject="CN=someone"6972026/11/06 07:18:14 INFO Shutdown signal received, draining in-flight requests timeout=10s698--- PASS: TestProxyHeadersOnlyTrustedOnSocket (0.23s)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.02s)765=== RUN TestWatchdogSkipsWhenUnhealthy7662026/11/06 07:18:14 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7672026/11/06 07:18:14 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7682026/11/06 07:18:14 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7692026/11/06 07:18:14 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7702026/11/06 07:18:14 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7712026/11/06 07:18:14 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7722026/11/06 07:18:14 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7732026/11/06 07:18:14 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7742026/11/06 07:18:14 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7752026/11/06 07:18:14 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 TestService_AuthMiddleware802=== CONT TestMetricsCommit803=== CONT TestGCSweepSkipsPendingObjects804=== CONT TestCreatePendingClosure_SmallNARUsesSimplePUT805=== CONT TestPinProtectsFromGC806=== CONT TestCompleteMultipartUnregistered807=== CONT TestGCAdvisoryLockBlocksConcurrentRun808=== CONT TestLeadIncumbentAnnouncesAtOnce809=== CONT TestCacheStatsHandler810=== CONT TestDeduplicatedObjectsRecordedAsPending811=== CONT TestPushDedupSurvivesConcurrentGC812=== CONT TestGCMetrics813=== CONT TestGCBugBareHashReferences814=== CONT TestService_verifyS3ReuploadsStaleNarinfo815=== CONT TestService_verifyS3Integrity816=== RUN TestService_verifyS3ReuploadsStaleNarinfo/lost,_other_NAR_pushed817=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo/lost,_other_NAR_pushed818=== CONT TestService_createPendingClosureHandler819=== RUN TestService_verifyS3ReuploadsStaleNarinfo/intact,_other_NAR_pushed820=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo/intact,_other_NAR_pushed821=== CONT TestService_cleanupPendingClosuresHandler822=== CONT TestUploadHandlersRejectOversizedBody823=== CONT TestUploadHandlersRejectInvalidKeys824=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info825=== CONT TestIsValidUploadKey826=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info827=== CONT TestPendingClosureWriteTimeout828=== CONT TestProxyWriteTimeout829=== CONT TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle830=== RUN TestIsValidUploadKey/narinfo831=== PAUSE TestIsValidUploadKey/narinfo832=== RUN TestIsValidUploadKey/nar_zst833=== PAUSE TestIsValidUploadKey/nar_zst834=== RUN TestIsValidUploadKey/nar_xz835=== CONT TestClientMultipleUploads836=== RUN TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost837=== PAUSE TestIsValidUploadKey/nar_xz838=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost839=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal840=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal841=== RUN TestPendingClosureWriteTimeout/empty842=== PAUSE TestPendingClosureWriteTimeout/empty843=== RUN TestProxyWriteTimeout/narinfo844=== RUN TestPendingClosureWriteTimeout/400_objects845=== RUN TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key846=== PAUSE TestPendingClosureWriteTimeout/400_objects847=== RUN TestIsValidUploadKey/nar_plain848=== PAUSE TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key849=== RUN TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key850=== RUN TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost,_second_pushed851=== PAUSE TestProxyWriteTimeout/narinfo852=== RUN TestPendingClosureWriteTimeout/670k_objects853=== PAUSE TestIsValidUploadKey/nar_plain854=== RUN TestIsValidUploadKey/listing855=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost,_second_pushed856=== RUN TestService_verifyS3ReuploadsStaleNarinfo/lost,_same_NAR_pushed857=== PAUSE TestPendingClosureWriteTimeout/670k_objects858=== RUN TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline859=== RUN TestProxyWriteTimeout/1_GiB_nar860=== PAUSE TestProxyWriteTimeout/1_GiB_nar861=== RUN TestProxyWriteTimeout/10_GiB_nar862=== PAUSE TestProxyWriteTimeout/10_GiB_nar863=== RUN TestProxyWriteTimeout/unknown_size864=== PAUSE TestProxyWriteTimeout/unknown_size865=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo/lost,_same_NAR_pushed866=== PAUSE TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key867=== CONT TestClientSharedPathCommittedMidPush868=== CONT TestSkippedUploadsHandler869=== PAUSE TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline8702026/11/06 07:18:14 INFO Client skipped oversized paths paths=3 nar_bytes=5000000000871=== PAUSE TestIsValidUploadKey/listing872=== RUN TestIsValidUploadKey/build_log873=== CONT TestParseSize874--- PASS: TestParseSize (0.00s)875=== CONT TestService_Rustfstest876=== PAUSE TestIsValidUploadKey/build_log877=== RUN TestIsValidUploadKey/build_log_home-manager_file878=== PAUSE TestIsValidUploadKey/build_log_home-manager_file879=== RUN TestIsValidUploadKey/build_log_plus_in_name880=== PAUSE TestIsValidUploadKey/build_log_plus_in_name881=== RUN TestIsValidUploadKey/build_log_question_mark882=== PAUSE TestIsValidUploadKey/build_log_question_mark883=== RUN TestIsValidUploadKey/build_log_equals884=== PAUSE TestIsValidUploadKey/build_log_equals885=== RUN TestIsValidUploadKey/realisation886=== PAUSE TestIsValidUploadKey/realisation887=== RUN TestIsValidUploadKey/realisation_plus_in_output888=== PAUSE TestIsValidUploadKey/realisation_plus_in_output889=== RUN TestIsValidUploadKey/nix-cache-info890=== PAUSE TestIsValidUploadKey/nix-cache-info891=== RUN TestIsValidUploadKey/index.html892=== PAUSE TestIsValidUploadKey/index.html893=== RUN TestIsValidUploadKey/narinfo_key,_nar_type894=== PAUSE TestIsValidUploadKey/narinfo_key,_nar_type895=== RUN TestIsValidUploadKey/nar_key,_narinfo_type896=== PAUSE TestIsValidUploadKey/nar_key,_narinfo_type897=== RUN TestIsValidUploadKey/listing_key,_narinfo_type898=== PAUSE TestIsValidUploadKey/listing_key,_narinfo_type899=== RUN TestIsValidUploadKey/traversal900=== PAUSE TestIsValidUploadKey/traversal901=== RUN TestIsValidUploadKey/traversal_nar902=== PAUSE TestIsValidUploadKey/traversal_nar903=== RUN TestIsValidUploadKey/absolute904=== PAUSE TestIsValidUploadKey/absolute905=== RUN TestIsValidUploadKey/empty_key906=== PAUSE TestIsValidUploadKey/empty_key907=== RUN TestIsValidUploadKey/unknown_type908=== PAUSE TestIsValidUploadKey/unknown_type909--- PASS: TestSkippedUploadsHandler (0.03s)910=== CONT TestCompletedNarNotReofferedAcrossClosures911=== CONT TestPresignedUploadRegisteredBeforeCommit912=== CONT TestClientWithDependencies913=== RUN TestUploadHandlersRejectOversizedBody/create_pending_closure914=== PAUSE TestUploadHandlersRejectOversizedBody/create_pending_closure915=== RUN TestUploadHandlersRejectOversizedBody/complete_multipart916=== PAUSE TestUploadHandlersRejectOversizedBody/complete_multipart917=== RUN TestUploadHandlersRejectOversizedBody/request_more_parts918=== PAUSE TestUploadHandlersRejectOversizedBody/request_more_parts919=== CONT TestCompleteMultipartUpload_ErrorButObjectExists9202026/11/06 07:18:16 INFO Aborted multipart uploads count=0 kept=09212026/11/06 07:18:16 WARN Force mode enabled - objects will be deleted immediately without grace period9222026/11/06 07:18:16 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=09232026/11/06 07:18:16 INFO Vacuumed table table=pending_closures9242026/11/06 07:18:16 INFO Vacuumed table table=pending_objects9252026/11/06 07:18:16 INFO Vacuumed table table=multipart_uploads9262026/11/06 07:18:16 INFO Vacuumed table table=closures9272026/11/06 07:18:16 INFO Vacuumed table table=objects928--- PASS: TestGCMetrics (1.71s)929=== CONT TestRedundantMultipartUpload930=== NAME TestPinProtectsFromGC931 client_integration_test.go:778: Pinned store path: /private/var/tb/4/scratch/6ba07dd8cd494155/build/TestPinProtectsFromGC61095374/001/store/gpdx3d608x8ikwn5vrlsgwm8zg14fwmw-pinned-file.txt932 client_integration_test.go:779: Unpinned store path: /private/var/tb/4/scratch/6ba07dd8cd494155/build/TestPinProtectsFromGC61095374/001/store/ahxjp4gjcw5g2zknn7c4m0djlvwc1d1d-unpinned-file.txt9332026/11/06 07:18:16 INFO Received uploads request method=POST path=/api/pending_closures9342026/11/06 07:18:16 INFO Received push request method=POST path=/api/pushes9352026/11/06 07:18:16 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)9362026/11/06 07:18:16 INFO Uploading gpdx3d608x8ikwn5vrlsgwm8zg14fwmw-pinned-file.txt (128B)937--- PASS: TestCreatePendingClosure_SmallNARUsesSimplePUT (2.02s)938=== CONT TestPush_SignsNarinfosOfItsPendingObjects9392026/11/06 07:18:16 WARN Failed to register uploaded object key=nar/0qmhsg42pqsz7x6hh02j8gznnac3yi3qpjhrqbwvz88i194jbb5s.nar.zst error="server returned 404: 404 page not found\n"9402026/11/06 07:18:16 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign9412026/11/06 07:18:16 WARN Failed to register uploaded object key=gpdx3d608x8ikwn5vrlsgwm8zg14fwmw.ls error="server returned 404: 404 page not found\n"9422026/11/06 07:18:16 INFO Signed narinfos id=1 count=19432026/11/06 07:18:16 INFO Uploading 1 narinfos9442026/11/06 07:18:16 INFO Received complete push request method=POST path=/api/pushes/1/complete9452026/11/06 07:18:16 WARN Failed to register uploaded object key=gpdx3d608x8ikwn5vrlsgwm8zg14fwmw.narinfo error="server returned 404: 404 page not found\n"9462026/11/06 07:18:16 INFO Completed push id=1 objects=3 duration=34.745584ms9472026/11/06 07:18:16 INFO Upload complete. (356ms)9482026/11/06 07:18:16 INFO lead: acquired remote=192.0.2.1:12349492026/11/06 07:18:16 INFO lead: released remote=192.0.2.1:1234950--- PASS: TestLeadIncumbentAnnouncesAtOnce (2.27s)951=== CONT TestPush_RejectsBadRequests9522026/11/06 07:18:16 INFO Received push request method=POST path=/api/pushes9532026/11/06 07:18:16 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)9542026/11/06 07:18:16 INFO Uploading ahxjp4gjcw5g2zknn7c4m0djlvwc1d1d-unpinned-file.txt (128B)9552026/11/06 07:18:17 WARN Failed to register uploaded object key=nar/0gh0wdnr6gmk4r5sfzzh12isnl14rgmkrwy1ws41hpsrlndclg5h.nar.zst error="server returned 404: 404 page not found\n"9562026/11/06 07:18:17 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign9572026/11/06 07:18:17 WARN Failed to register uploaded object key=ahxjp4gjcw5g2zknn7c4m0djlvwc1d1d.ls error="server returned 404: 404 page not found\n"9582026/11/06 07:18:17 INFO Signed narinfos id=2 count=19592026/11/06 07:18:17 INFO Uploading 1 narinfos9602026/11/06 07:18:17 INFO Received complete push request method=POST path=/api/pushes/2/complete9612026/11/06 07:18:17 WARN Failed to register uploaded object key=ahxjp4gjcw5g2zknn7c4m0djlvwc1d1d.narinfo error="server returned 404: 404 page not found\n"9622026/11/06 07:18:17 INFO Completed push id=2 objects=3 duration=867.5µs9632026/11/06 07:18:17 INFO Upload complete. (168ms)9642026/11/06 07:18:17 INFO Starting cleanup of old closures method=DELETE path=/api/closures9652026/11/06 07:18:17 INFO Garbage collection started9662026/11/06 07:18:17 INFO Aborted multipart uploads count=0 kept=09672026/11/06 07:18:17 WARN Force mode enabled - objects will be deleted immediately without grace period9682026/11/06 07:18:17 INFO Received push request method=POST path=/api/pushes9692026/11/06 07:18:17 INFO Received complete push request method=POST path=/api/pushes/1/complete9702026/11/06 07:18:17 INFO Completed push id=1 objects=4 duration=24.444458ms9712026/11/06 07:18:17 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete9722026/11/06 07:18:17 INFO Completed upload id=2 objects=2 duration=422.416µs973--- PASS: TestMetricsCommit (2.59s)974=== CONT TestPush_SkippedKeySurvivesGCBeforeCommit9752026/11/06 07:18:17 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"976--- PASS: TestGCAdvisoryLockBlocksConcurrentRun (2.75s)977=== CONT TestPush_RootsAreLockedInByteOrder9782026/11/06 07:18:17 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=09792026/11/06 07:18:17 INFO Vacuumed table table=pending_closures9802026/11/06 07:18:17 INFO Vacuumed table table=pending_objects9812026/11/06 07:18:17 INFO Vacuumed table table=multipart_uploads9822026/11/06 07:18:17 INFO Vacuumed table table=closures9832026/11/06 07:18:17 INFO Vacuumed table table=objects9842026/11/06 07:18:17 INFO Received uploads request method=POST path=/api/pending_closures9852026/11/06 07:18:17 INFO Aborted multipart uploads count=0 kept=09862026/11/06 07:18:17 WARN Force mode enabled - objects will be deleted immediately without grace period9872026/11/06 07:18:17 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=09882026/11/06 07:18:17 INFO Vacuumed table table=pending_closures9892026/11/06 07:18:17 WARN Authentication failed token_preview=wrongtoken token_length=10 reason="static API token mismatch"990--- PASS: TestService_AuthMiddleware (3.12s)991=== CONT TestPush_CompleteWaitsForCleanupOfThePush9922026/11/06 07:18:17 INFO Vacuumed table table=pending_objects9932026/11/06 07:18:17 INFO Vacuumed table table=multipart_uploads9942026/11/06 07:18:17 INFO Vacuumed table table=closures9952026/11/06 07:18:17 INFO Vacuumed table table=objects996--- PASS: TestGCSweepSkipsPendingObjects (3.16s)997=== CONT TestPush_RepeatedRootCommitsOnce9982026/11/06 07:18:18 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9992026/11/06 07:18:18 ERROR Failed to get multipart upload error="no rows in result set" upload_id=does-not-exist object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst1000--- PASS: TestCompleteMultipartUnregistered (3.32s)1001=== CONT TestPush_CompleteCommitsEveryRoot10022026/11/06 07:18:18 INFO Received uploads request method=POST path=/api/pending_closures1003--- PASS: TestGCBugBareHashReferences (3.99s)1004=== CONT TestPush_OverlappingRootsStoreOneRowPerKey10052026/11/06 07:18:18 INFO Received uploads request method=POST path=/api/pending_closures1006--- PASS: TestDeduplicatedObjectsRecordedAsPending (4.06s)1007=== CONT TestReadRedirectUsesPublicS3URL10082026/11/06 07:18:19 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=010092026/11/06 07:18:19 INFO Received create pin request method=POST path=/api/pins/myapp1010--- PASS: TestService_Rustfstest (4.39s)1011=== CONT TestReadProxyRangeRequest1012=== NAME TestClientMultipleUploads1013 client_integration_test.go:405: Created store path 0: /private/var/tb/4/scratch/6ba07dd8cd494155/build/TestClientMultipleUploads1801362775/001/store/6m0ixs4k29fshl0i28bz789p6s8ag453-test-file-0.txt10142026/11/06 07:18:19 INFO Created/updated pin name=myapp store_path=/private/var/tb/4/scratch/6ba07dd8cd494155/build/TestPinProtectsFromGC61095374/001/store/gpdx3d608x8ikwn5vrlsgwm8zg14fwmw-pinned-file.txt narinfo_key=gpdx3d608x8ikwn5vrlsgwm8zg14fwmw.narinfo10152026/11/06 07:18:19 INFO Starting cleanup of old closures method=DELETE path=/api/closures10162026/11/06 07:18:19 INFO Garbage collection started10172026/11/06 07:18:19 INFO Aborted multipart uploads count=0 kept=010182026/11/06 07:18:19 WARN Force mode enabled - objects will be deleted immediately without grace period10192026/11/06 07:18:19 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=010202026/11/06 07:18:19 INFO Vacuumed table table=pending_closures10212026/11/06 07:18:19 INFO Vacuumed table table=pending_objects10222026/11/06 07:18:19 INFO Vacuumed table table=multipart_uploads10232026/11/06 07:18:19 INFO Vacuumed table table=closures10242026/11/06 07:18:19 INFO Vacuumed table table=objects10252026/11/06 07:18:19 INFO Received uploads request method=POST path=/api/pending_closures10262026/11/06 07:18:19 INFO Received uploads request method=POST path=/api/pending_closures10272026/11/06 07:18:19 INFO Received uploads request method=POST path=/api/pending_closures1028 client_integration_test.go:405: Created store path 1: /private/var/tb/4/scratch/6ba07dd8cd494155/build/TestClientMultipleUploads1801362775/001/store/sb6r9k905brpjm73dpfrlyjhdk4npdh1-test-file-1.txt10292026/11/06 07:18:19 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1030 client_integration_test.go:405: Created store path 2: /private/var/tb/4/scratch/6ba07dd8cd494155/build/TestClientMultipleUploads1801362775/001/store/qnx4cqclxd0k2s52cbihfpwkv5jqw388-test-file-2.txt10312026/11/06 07:18:19 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst upload_id=NjA1YThjNTgtZTllYS00MjkyLWFhMDctYjhhMGIxNjQxMjliLjkwYWI2ODQzLWFkMGUtNGVkZC1iYTAwLWI0NDc5YzJiOGY5YXgxNzkzOTQ5NDk4MjUyMzY5MDAw parts=1010322026/11/06 07:18:19 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete10332026/11/06 07:18:19 INFO Received uploads request method=POST path=/api/pending_closures10342026/11/06 07:18:19 INFO Completed upload id=1 objects=2 duration=9.2745ms10352026/11/06 07:18:19 INFO Received uploads request method=POST path=/api/pending_closures10362026/11/06 07:18:19 INFO Received uploads request method=POST path=/api/pending_closures10372026/11/06 07:18:19 INFO Object in database but missing from S3 key=dadb44fdadb44fdadb44fdadb44f0000.narinfo10382026/11/06 07:18:19 WARN Found objects in DB but missing from S3, will re-upload count=11039--- PASS: TestService_verifyS3Integrity (5.07s)1040=== CONT TestReadRedirectKeepsNarinfoProxied10412026/11/06 07:18:19 INFO Received uploads request method=POST path=/api/pending_closures10422026/11/06 07:18:19 INFO Received push request method=POST path=/api/pushes10432026/11/06 07:18:19 INFO Aborted multipart uploads count=0 kept=010442026/11/06 07:18:19 INFO Uploading 3 paths to 127.0.0.1 (0 already cached)10452026/11/06 07:18:19 INFO Uploading 6m0ixs4k29fshl0i28bz789p6s8ag453-test-file-0.txt (160B)10462026/11/06 07:18:19 INFO Uploading sb6r9k905brpjm73dpfrlyjhdk4npdh1-test-file-1.txt (160B)10472026/11/06 07:18:19 INFO Uploading qnx4cqclxd0k2s52cbihfpwkv5jqw388-test-file-2.txt (160B)10482026/11/06 07:18:19 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=010492026/11/06 07:18:19 WARN Failed to register uploaded object key=sb6r9k905brpjm73dpfrlyjhdk4npdh1.ls error="server returned 404: 404 page not found\n"10502026/11/06 07:18:19 WARN Failed to register uploaded object key=nar/1823g6vx4q5zqvr73m7lkq1wpk40fin7bsc792di430yk7sg4lka.nar.zst error="server returned 404: 404 page not found\n"10512026/11/06 07:18:19 WARN Failed to register uploaded object key=6m0ixs4k29fshl0i28bz789p6s8ag453.ls error="server returned 404: 404 page not found\n"10522026/11/06 07:18:19 INFO Vacuumed table table=pending_closures10532026/11/06 07:18:19 WARN Failed to register uploaded object key=qnx4cqclxd0k2s52cbihfpwkv5jqw388.ls error="server returned 404: 404 page not found\n"10542026/11/06 07:18:19 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign10552026/11/06 07:18:19 WARN Failed to register uploaded object key=nar/13p9pqi0ga6fx2apcwls9hjnv7nmf740ggpn5zvfzdsp5vz2bbg4.nar.zst error="server returned 404: 404 page not found\n"10562026/11/06 07:18:19 WARN Failed to register uploaded object key=nar/0ahq3izw3h0b0c08p3xdfclh758fwxnp85ccvflasb4vnfsv50ri.nar.zst error="server returned 404: 404 page not found\n"10572026/11/06 07:18:19 INFO Signed narinfos id=1 count=310582026/11/06 07:18:19 INFO Uploading 3 narinfos10592026/11/06 07:18:20 INFO Vacuumed table table=pending_objects10602026/11/06 07:18:20 INFO Vacuumed table table=multipart_uploads10612026/11/06 07:18:20 WARN Failed to register uploaded object key=6m0ixs4k29fshl0i28bz789p6s8ag453.narinfo error="server returned 404: 404 page not found\n"10622026/11/06 07:18:20 WARN Failed to register uploaded object key=sb6r9k905brpjm73dpfrlyjhdk4npdh1.narinfo error="server returned 404: 404 page not found\n"10632026/11/06 07:18:20 INFO Vacuumed table table=closures10642026/11/06 07:18:20 INFO Received complete push request method=POST path=/api/pushes/1/complete10652026/11/06 07:18:20 WARN Failed to register uploaded object key=qnx4cqclxd0k2s52cbihfpwkv5jqw388.narinfo error="server returned 404: 404 page not found\n"10662026/11/06 07:18:20 INFO Vacuumed table table=objects10672026/11/06 07:18:20 INFO Completed push id=1 objects=9 duration=27.840292ms10682026/11/06 07:18:20 INFO Upload complete. (318ms)1069=== NAME TestClientMultipleUploads1070 client_integration_test.go:416: Uploaded 3 paths in 378.8955ms10712026/11/06 07:18:20 INFO Aborted multipart uploads count=0 kept=010722026/11/06 07:18:20 WARN Force mode enabled - objects will be deleted immediately without grace period10732026/11/06 07:18:20 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=010742026/11/06 07:18:20 INFO Vacuumed table table=pending_closures10752026/11/06 07:18:20 INFO Vacuumed table table=pending_objects10762026/11/06 07:18:20 INFO Vacuumed table table=multipart_uploads10772026/11/06 07:18:20 INFO Vacuumed table table=closures10782026/11/06 07:18:20 INFO Vacuumed table table=objects1079--- PASS: TestPushDedupSurvivesConcurrentGC (5.48s)1080=== CONT TestReadRedirectNar1081=== CONT TestReadProxyDisabled1082--- PASS: TestClientMultipleUploads (5.49s)10832026/11/06 07:18:20 INFO Received cleanup request method=DELETE path=/api/pending_closures10842026/11/06 07:18:20 INFO Aborted multipart uploads count=0 kept=010852026/11/06 07:18:20 INFO Received uploads request method=POST path=/api/pending_closures10862026/11/06 07:18:20 INFO Received cleanup request method=DELETE path=/api/pending_closures10872026/11/06 07:18:20 INFO Aborted multipart uploads count=1 kept=010882026/11/06 07:18:20 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete10892026-11-06 07:18:20.365 UTC [86398] ERROR: Closure does not exist: id=110902026-11-06 07:18:20.365 UTC [86398] CONTEXT: PL/pgSQL function commit_pending_closure(bigint) line 13 at RAISE10912026-11-06 07:18:20.365 UTC [86398] STATEMENT: -- name: CommitPendingClosure :one1092 SELECT commit_pending_closure($1::bigint)::bigint1093 1094--- PASS: TestService_cleanupPendingClosuresHandler (5.68s)1095=== CONT TestReadProxyRootRedirectsToIndexHTML10962026/11/06 07:18:20 INFO Received uploads request method=POST path=/api/pending_closures10972026/11/06 07:18:20 INFO Received complete multipart upload request method=POST path=/api/multipart/complete10982026/11/06 07:18:20 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified key does not exist." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=NjA1YThjNTgtZTllYS00MjkyLWFhMDctYjhhMGIxNjQxMjliLmJiNDdmODY4LTk0ODgtNDc0NC1hMjU0LTRmNmI3OTIwYWI3MngxNzkzOTQ5NTAwNTgxODkyMDAw10992026/11/06 07:18:20 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=NjA1YThjNTgtZTllYS00MjkyLWFhMDctYjhhMGIxNjQxMjliLmJiNDdmODY4LTk0ODgtNDc0NC1hMjU0LTRmNmI3OTIwYWI3MngxNzkzOTQ5NTAwNTgxODkyMDAw parts=11100--- PASS: TestCompleteMultipartUpload_ErrorButObjectExists (5.89s)1101=== CONT TestReadProxyConditionalGet11022026/11/06 07:18:20 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11032026/11/06 07:18:21 INFO Completed multipart upload object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst upload_id=NjA1YThjNTgtZTllYS00MjkyLWFhMDctYjhhMGIxNjQxMjliLjU3OGU3N2ZmLTU0NjgtNDZmNy04MzA0LWUzOTE4NzAxNTQwNHgxNzkzOTQ5NDk5NTI4OTg0MDAw parts=1011042026/11/06 07:18:21 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete11052026/11/06 07:18:21 INFO Completed upload id=1 objects=2 duration=12.697166ms11062026/11/06 07:18:21 INFO Received get closure request method=GET path=/api/closures/0000000000000000000000000000000011072026/11/06 07:18:21 INFO Received uploads request method=POST path=/api/pending_closures11082026/11/06 07:18:21 INFO Starting cleanup of old closures method=DELETE path=/api/closures11092026/11/06 07:18:21 INFO Aborted multipart uploads count=0 kept=011102026/11/06 07:18:21 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=011112026/11/06 07:18:21 INFO Received uploads request method=POST path=/api/pending_closures11122026/11/06 07:18:21 INFO Vacuumed table table=pending_closures11132026/11/06 07:18:21 INFO Vacuumed table table=pending_objects1114=== NAME TestPinProtectsFromGC1115 client_integration_test.go:887: Pin successfully protected closure from garbage collection11162026/11/06 07:18:21 INFO Vacuumed table table=multipart_uploads1117--- PASS: TestPinProtectsFromGC (6.63s)1118=== CONT TestReadProxyOutlastsServerWriteTimeout11192026/11/06 07:18:21 INFO Vacuumed table table=closures1120=== NAME TestClientWithDependencies1121 client_integration_test.go:660: Built derivation: /private/var/tb/4/scratch/6ba07dd8cd494155/build/TestClientWithDependencies2994298792/001/store/rqv3mxscd3239fk5j6l5y9s7vlpbay6r-test-script11222026/11/06 07:18:21 INFO Vacuumed table table=objects11232026/11/06 07:18:21 INFO Received get closure request method=GET path=/api/closures/000000000000000000000000000000001124--- PASS: TestService_createPendingClosureHandler (6.73s)1125=== CONT TestReadProxyHead1126=== NAME TestClientWithDependencies1127 client_integration_test.go:662: Found 1 dependencies (including self)11282026/11/06 07:18:21 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11292026/11/06 07:18:21 INFO Received push request method=POST path=/api/pushes11302026/11/06 07:18:21 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)11312026/11/06 07:18:21 INFO Uploading rqv3mxscd3239fk5j6l5y9s7vlpbay6r-test-script (136B)11322026/11/06 07:18:21 WARN Failed to register uploaded object key=rqv3mxscd3239fk5j6l5y9s7vlpbay6r.ls error="server returned 404: 404 page not found\n"11332026/11/06 07:18:21 WARN Failed to register uploaded object key=nar/1s7yghixzpinyqm7g59kyn3sav81pmnsdi5v63m6x4r2vacy907j.nar.zst error="server returned 404: 404 page not found\n"11342026/11/06 07:18:21 WARN Failed to register uploaded object key=log/4af80lx6lszyx96myh8fbmrfj79bkjlq-test-script.drv error="server returned 404: 404 page not found\n"11352026/11/06 07:18:21 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign11362026/11/06 07:18:21 INFO Signed narinfos id=1 count=111372026/11/06 07:18:21 INFO Uploading 1 narinfos11382026/11/06 07:18:21 INFO Received complete push request method=POST path=/api/pushes/1/complete11392026/11/06 07:18:21 WARN Failed to register uploaded object key=rqv3mxscd3239fk5j6l5y9s7vlpbay6r.narinfo error="server returned 404: 404 page not found\n"11402026/11/06 07:18:21 INFO Completed push id=1 objects=4 duration=26.329125ms11412026/11/06 07:18:21 INFO Upload complete. (313ms)11422026/11/06 07:18:21 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1143 client_integration_test.go:664: Skipping nix copy test - isolated store (/private/var/tb/4/scratch/6ba07dd8cd494155/build/TestClientWithDependencies2994298792/001/store) requires matching store prefix11442026/11/06 07:18:21 INFO Completed multipart upload object_key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhh0100000000000000000000.nar.zst upload_id=NjA1YThjNTgtZTllYS00MjkyLWFhMDctYjhhMGIxNjQxMjliLmI3ODlkNGMzLTFmN2UtNDE0Yy1iZjAzLTY3N2ZhM2JhY2QzN3gxNzkzOTQ5NDk5OTI4ODM0MDAw parts=1211452026/11/06 07:18:21 INFO Received uploads request method=POST path=/api/pending_closures1146--- PASS: TestCacheStatsHandler (7.30s)1147--- PASS: TestCompletedNarNotReofferedAcrossClosures (7.19s)1148=== CONT TestReadProxyInvalidPath1149=== CONT TestReadProxy4041150--- PASS: TestClientWithDependencies (7.18s)1151=== CONT TestReadProxyNarStreaming11522026/11/06 07:18:22 INFO Received push request method=POST path=/api/pushes11532026/11/06 07:18:22 INFO Uploading 2 paths to 127.0.0.1 (0 already cached)11542026/11/06 07:18:22 INFO Uploading ds67h2ikal5fgxhz33r4jshl7p1dpz18-shared-dep (136B)11552026/11/06 07:18:22 INFO Uploading 3yybqczlnjx2fjfvrr6v0whkc132cqgd-top (264B)11562026/11/06 07:18:22 INFO Received uploads request method=POST path=/api/pending_closures11572026/11/06 07:18:22 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"11582026/11/06 07:18:22 WARN Failed to register uploaded object key=nar/1frlpnqkr3vlvj68anaplz9wxkrkvxdrlpgvbjpff89ilxnbcybq.nar.zst error="server returned 404: 404 page not found\n"11592026/11/06 07:18:22 WARN Failed to register uploaded object key=ds67h2ikal5fgxhz33r4jshl7p1dpz18.ls error="server returned 404: 404 page not found\n"11602026/11/06 07:18:22 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign11612026/11/06 07:18:22 WARN Failed to register uploaded object key=3yybqczlnjx2fjfvrr6v0whkc132cqgd.ls error="server returned 404: 404 page not found\n"11622026/11/06 07:18:22 INFO Signed narinfos id=1 count=211632026/11/06 07:18:22 INFO Uploading 2 narinfos11642026/11/06 07:18:22 WARN Failed to register uploaded object key=3yybqczlnjx2fjfvrr6v0whkc132cqgd.narinfo error="server returned 404: 404 page not found\n"11652026/11/06 07:18:22 INFO Received complete push request method=POST path=/api/pushes/1/complete11662026/11/06 07:18:22 WARN Failed to register uploaded object key=ds67h2ikal5fgxhz33r4jshl7p1dpz18.narinfo error="server returned 404: 404 page not found\n"11672026/11/06 07:18:22 INFO Completed push id=1 objects=6 duration=32.161167ms11682026/11/06 07:18:22 INFO Upload complete. (308ms)1169=== NAME TestClientSharedPathCommittedMidPush1170 client_integration_test.go:727: Retrieved narinfo from S3:1171 StorePath: /private/var/tb/4/scratch/6ba07dd8cd494155/build/TestClientSharedPathCommittedMidPush216456984/001/store/ds67h2ikal5fgxhz33r4jshl7p1dpz18-shared-dep1172 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1173 Compression: zstd1174 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821175 NarSize: 1361176 References: 1177 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1178 client_integration_test.go:727: Retrieved narinfo from S3:1179 StorePath: /private/var/tb/4/scratch/6ba07dd8cd494155/build/TestClientSharedPathCommittedMidPush216456984/001/store/3yybqczlnjx2fjfvrr6v0whkc132cqgd-top1180 URL: nar/1frlpnqkr3vlvj68anaplz9wxkrkvxdrlpgvbjpff89ilxnbcybq.nar.zst1181 Compression: zstd1182 NarHash: sha256:1frlpnqkr3vlvj68anaplz9wxkrkvxdrlpgvbjpff89ilxnbcybq1183 NarSize: 2641184 References: /private/var/tb/4/scratch/6ba07dd8cd494155/build/TestClientSharedPathCommittedMidPush216456984/001/store/ds67h2ikal5fgxhz33r4jshl7p1dpz18-shared-dep1185 CA: text:sha256:0w7c1cskp7p48d978nh6max9qg8fzq3hmmg8i71gx42bk5bmxi4411862026/11/06 07:18:22 INFO Registered completed upload object_key=nar/jjjjjjjjjjjjjjjjjjjjjjjjjjjjjj0100000000000000000000.nar.zst11872026/11/06 07:18:22 INFO Received uploads request method=POST path=/api/pending_closures1188--- PASS: TestPresignedUploadRegisteredBeforeCommit (7.68s)1189=== CONT TestReadProxyContentNegotiation1190--- PASS: TestClientSharedPathCommittedMidPush (7.73s)1191=== CONT TestReadProxyNarinfoAlreadyDecompressed11922026/11/06 07:18:22 INFO Received uploads request method=POST path=/api/pending_closures11932026/11/06 07:18:22 INFO Received uploads request method=POST path=/api/pending_closures11942026/11/06 07:18:22 INFO Received push request method=POST path=/api/pushes11952026/11/06 07:18:23 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign11962026/11/06 07:18:23 INFO Signed narinfos id=1 count=111972026/11/06 07:18:23 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign11982026/11/06 07:18:23 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign11992026/11/06 07:18:23 ERROR Failed to sign narinfos signer="index 1" error="signing key cannot be nil"12002026/11/06 07:18:23 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign12012026/11/06 07:18:23 ERROR Failed to sign narinfos signer=niks3-test-1 error="signer failed"12022026/11/06 07:18:23 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign12032026/11/06 07:18:23 ERROR Signer returned unexpected signature count signer=niks3-test-1 got=0 want=112042026/11/06 07:18:23 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign12052026/11/06 07:18:23 ERROR Signer returned unexpected object key signer=niks3-test-1 object_key=unexpected.narinfo1206--- PASS: TestPush_SignsNarinfosOfItsPendingObjects (6.31s)1207=== CONT TestReadProxyNarinfo1208=== RUN TestPush_RejectsBadRequests/no_objects1209=== PAUSE TestPush_RejectsBadRequests/no_objects1210=== RUN TestPush_RejectsBadRequests/bad_root1211=== PAUSE TestPush_RejectsBadRequests/bad_root1212=== RUN TestPush_RejectsBadRequests/root_not_in_objects1213=== PAUSE TestPush_RejectsBadRequests/root_not_in_objects1214=== RUN TestPush_RejectsBadRequests/no_roots1215=== PAUSE TestPush_RejectsBadRequests/no_roots1216=== CONT TestIsValidCachePath1217=== RUN TestIsValidCachePath/narinfo1218=== PAUSE TestIsValidCachePath/narinfo1219=== RUN TestIsValidCachePath/narinfo_all_nix_base32_chars1220=== PAUSE TestIsValidCachePath/narinfo_all_nix_base32_chars1221=== RUN TestIsValidCachePath/nar_zst1222=== PAUSE TestIsValidCachePath/nar_zst1223=== RUN TestIsValidCachePath/nar_xz1224=== PAUSE TestIsValidCachePath/nar_xz1225=== RUN TestIsValidCachePath/nar_bz21226=== PAUSE TestIsValidCachePath/nar_bz21227=== RUN TestIsValidCachePath/nar_uncompressed1228=== PAUSE TestIsValidCachePath/nar_uncompressed1229=== RUN TestIsValidCachePath/ls1230=== PAUSE TestIsValidCachePath/ls1231=== RUN TestIsValidCachePath/log1232=== PAUSE TestIsValidCachePath/log1233=== RUN TestIsValidCachePath/realisation1234=== PAUSE TestIsValidCachePath/realisation1235=== RUN TestIsValidCachePath/nix-cache-info1236=== PAUSE TestIsValidCachePath/nix-cache-info1237=== RUN TestIsValidCachePath/index.html1238=== PAUSE TestIsValidCachePath/index.html1239=== RUN TestIsValidCachePath/traversal_parent1240=== PAUSE TestIsValidCachePath/traversal_parent1241=== RUN TestIsValidCachePath/traversal_in_middle1242=== PAUSE TestIsValidCachePath/traversal_in_middle1243=== RUN TestIsValidCachePath/invalid_char_e1244=== PAUSE TestIsValidCachePath/invalid_char_e1245=== RUN TestIsValidCachePath/invalid_char_u1246=== PAUSE TestIsValidCachePath/invalid_char_u1247=== RUN TestIsValidCachePath/random_path1248=== PAUSE TestIsValidCachePath/random_path1249=== RUN TestIsValidCachePath/empty1250=== PAUSE TestIsValidCachePath/empty1251=== RUN TestIsValidCachePath/leading_slash1252=== PAUSE TestIsValidCachePath/leading_slash1253=== RUN TestIsValidCachePath/wrong_extension1254=== PAUSE TestIsValidCachePath/wrong_extension1255=== RUN TestIsValidCachePath/short_hash1256=== PAUSE TestIsValidCachePath/short_hash1257=== CONT TestParseSingleRange1258=== RUN TestParseSingleRange/none1259=== PAUSE TestParseSingleRange/none1260=== RUN TestParseSingleRange/unknown_unit1261=== PAUSE TestParseSingleRange/unknown_unit1262=== RUN TestParseSingleRange/multi-range_ignored1263=== PAUSE TestParseSingleRange/multi-range_ignored1264=== RUN TestParseSingleRange/malformed_no_dash1265=== PAUSE TestParseSingleRange/malformed_no_dash1266=== RUN TestParseSingleRange/malformed_both_empty1267=== PAUSE TestParseSingleRange/malformed_both_empty1268=== RUN TestParseSingleRange/malformed_end_before_start1269=== PAUSE TestParseSingleRange/malformed_end_before_start1270=== RUN TestParseSingleRange/closed1271=== PAUSE TestParseSingleRange/closed1272=== RUN TestParseSingleRange/open-ended1273=== PAUSE TestParseSingleRange/open-ended1274=== RUN TestParseSingleRange/end_clamped_to_size1275=== PAUSE TestParseSingleRange/end_clamped_to_size1276=== RUN TestParseSingleRange/suffix1277=== PAUSE TestParseSingleRange/suffix1278=== RUN TestParseSingleRange/suffix_exceeds_size1279=== PAUSE TestParseSingleRange/suffix_exceeds_size1280=== RUN TestParseSingleRange/single_byte1281=== PAUSE TestParseSingleRange/single_byte1282=== RUN TestParseSingleRange/start_past_EOF1283=== PAUSE TestParseSingleRange/start_past_EOF1284=== RUN TestParseSingleRange/start_far_past_EOF1285=== PAUSE TestParseSingleRange/start_far_past_EOF1286=== CONT TestPresentNotReportedWhileGCDeletesClosure1287=== RUN TestPresentNotReportedWhileGCDeletesClosure/stale1288=== PAUSE TestPresentNotReportedWhileGCDeletesClosure/stale1289=== RUN TestPresentNotReportedWhileGCDeletesClosure/fresh1290=== PAUSE TestPresentNotReportedWhileGCDeletesClosure/fresh1291=== CONT TestPresentRefreshesOnlyStaleClosures12922026/11/06 07:18:23 INFO Received push request method=POST path=/api/pushes12932026/11/06 07:18:23 INFO Received complete push request method=POST path=/api/pushes/1/complete12942026/11/06 07:18:23 INFO Completed push id=1 objects=4 duration=40.306625ms12952026/11/06 07:18:23 INFO Received push request method=POST path=/api/pushes12962026/11/06 07:18:23 INFO Aborted multipart uploads count=0 kept=012972026/11/06 07:18:23 WARN Force mode enabled - objects will be deleted immediately without grace period12982026/11/06 07:18:23 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=012992026/11/06 07:18:23 INFO Vacuumed table table=pending_closures13002026/11/06 07:18:23 INFO Vacuumed table table=pending_objects13012026/11/06 07:18:23 INFO Vacuumed table table=multipart_uploads13022026/11/06 07:18:23 INFO Received push request method=POST path=/api/pushes13032026/11/06 07:18:23 INFO Vacuumed table table=closures13042026/11/06 07:18:24 INFO Vacuumed table table=objects13052026/11/06 07:18:24 INFO Received complete push request method=POST path=/api/pushes/2/complete13062026/11/06 07:18:24 INFO Completed push id=2 objects=4 duration=31.938583ms1307--- PASS: TestPush_SkippedKeySurvivesGCBeforeCommit (6.79s)1308=== CONT TestPresentReportsOnlyClosureRoots13092026-11-06 07:18:24.180 UTC [86464] ERROR: could not obtain lock on row in relation "closures"13102026-11-06 07:18:24.180 UTC [86464] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT13112026-11-06 07:18:24.183 UTC [86464] ERROR: could not obtain lock on row in relation "closures"13122026-11-06 07:18:24.183 UTC [86464] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT13132026-11-06 07:18:24.186 UTC [86464] ERROR: could not obtain lock on row in relation "closures"13142026-11-06 07:18:24.186 UTC [86464] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT13152026-11-06 07:18:24.195 UTC [86464] ERROR: could not obtain lock on row in relation "closures"13162026-11-06 07:18:24.195 UTC [86464] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT13172026-11-06 07:18:24.204 UTC [86464] ERROR: could not obtain lock on row in relation "closures"13182026-11-06 07:18:24.204 UTC [86464] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT1319--- PASS: TestPush_RootsAreLockedInByteOrder (6.81s)1320=== CONT TestCreatePin_ReservedPins13212026/11/06 07:18:24 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:55320/oidc13222026/11/06 07:18:24 INFO Received push request method=POST path=/api/pushes13232026/11/06 07:18:24 INFO Received complete push request method=POST path=/api/pushes/1/complete13242026/11/06 07:18:24 INFO Completed push id=1 objects=4 duration=42.473167ms1325--- PASS: TestPush_RepeatedRootCommitsOnce (6.67s)1326=== CONT TestOrphanedObjectsGCStressTest13272026/11/06 07:18:24 INFO Received complete multipart upload request method=POST path=/api/multipart/complete13282026/11/06 07:18:24 INFO Received push request method=POST path=/api/pushes13292026/11/06 07:18:24 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=NjA1YThjNTgtZTllYS00MjkyLWFhMDctYjhhMGIxNjQxMjliLmY1ZTY2ZjA0LTlmYWEtNDk3Ny1hZDQ4LTEwOWI0M2U2ODZmNXgxNzkzOTQ5NTAyNjU0OTk4MDAw parts=1213302026/11/06 07:18:24 INFO Received uploads request method=POST path=/api/pending_closures13312026/11/06 07:18:24 INFO Received uploads request method=POST path=/api/pending_closures13322026/11/06 07:18:25 INFO Received push request method=POST path=/api/pushes13332026-11-06 07:18:25.170 UTC [86623] ERROR: Push does not exist: id=113342026-11-06 07:18:25.170 UTC [86623] CONTEXT: PL/pgSQL function commit_push(bigint) line 11 at RAISE13352026-11-06 07:18:25.170 UTC [86623] STATEMENT: SELECT commit_push($1)1336--- PASS: TestPush_CompleteWaitsForCleanupOfThePush (7.38s)1337=== CONT TestOrphanedObjectsGC13382026/11/06 07:18:25 INFO Received complete push request method=POST path=/api/pushes/1/complete13392026/11/06 07:18:25 INFO Completed push id=1 objects=6 duration=47.666458ms1340--- PASS: TestPush_CompleteCommitsEveryRoot (7.25s)1341=== CONT TestObjectStatsUpdatedOncePerCommit13422026/11/06 07:18:25 INFO Received push request method=POST path=/api/pushes1343--- PASS: TestPush_OverlappingRootsStoreOneRowPerKey (6.84s)1344=== CONT TestObjectStatsTrigger1345--- PASS: TestReadRedirectUsesPublicS3URL (7.03s)1346=== CONT TestPendingCleanupUsesOneCutoff1347--- PASS: TestReadProxyRangeRequest (6.90s)1348=== CONT TestMultipartUploadAbortedWhenCancelledBeforeRecorded13492026/11/06 07:18:26 WARN Rate limiter enabled after throttle name=s3-test rate=513502026/11/06 07:18:26 WARN S3 rate limit hit operation="complete multipart upload" error="Please reduce your request rate."1351=== NAME TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle1352 throttle_test.go:213: Proxy stats: total=13, throttled=10, completeMultipart=101353 throttle_test.go:215: Rate limiter: enabled=true, rate=5.001354--- PASS: TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle (11.54s)1355=== CONT TestMultipartCleanup1356--- PASS: TestReadRedirectKeepsNarinfoProxied (6.73s)1357=== CONT TestServerTLSConfig1358=== RUN TestServerTLSConfig/no_client_CA1359=== PAUSE TestServerTLSConfig/no_client_CA1360=== RUN TestServerTLSConfig/missing_CA_file1361=== PAUSE TestServerTLSConfig/missing_CA_file1362=== RUN TestServerTLSConfig/not_a_PEM_file1363=== PAUSE TestServerTLSConfig/not_a_PEM_file1364=== CONT TestService_NativeMTLS13652026/11/06 07:18:26 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1366--- PASS: TestReadProxyDisabled (6.58s)1367=== CONT TestService_healthCheckHandler13682026/11/06 07:18:26 WARN Failed to abort redundant multipart upload, keeping its row object_key=nar/gggggggggggggggggggggggggggggg0200000000000000000000.nar.zst upload_id=NjA1YThjNTgtZTllYS00MjkyLWFhMDctYjhhMGIxNjQxMjliLjRhZDVjNTZjLWZjYzAtNGZhYS05YTM1LWQ0NzRmNWVhNDZmYXgxNzkzOTQ5NTA0NzM2MDQ5MDAw error="Get \"http://127.0.0.1:1/bucket28/?location=\": dial tcp 127.0.0.1:1: connect: connection refused"13692026/11/06 07:18:26 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0200000000000000000000.nar.zst upload_id=NjA1YThjNTgtZTllYS00MjkyLWFhMDctYjhhMGIxNjQxMjliLmM4YTYwNWEyLWQyMTktNDllMi1iOWJiLTg4NDljNjAwYjVjZngxNzkzOTQ5NTA0NjgzNTg1MDAw parts=1213702026/11/06 07:18:26 INFO Received cleanup request method=DELETE path=/api/pending_closures13712026/11/06 07:18:26 INFO Aborted multipart uploads count=1 kept=01372--- PASS: TestRedundantMultipartUpload (10.49s)1373=== CONT TestMetricsInventory1374--- PASS: TestReadRedirectNar (6.94s)1375=== CONT TestLeadEndsOnShutdown1376--- PASS: TestReadProxyRootRedirectsToIndexHTML (7.05s)1377=== CONT TestNARDeduplicationMetadataUploadBug1378--- PASS: TestReadProxyConditionalGet (6.79s)1379=== CONT TestCreatePendingClosureRejectsOversizedNAR13802026/11/06 07:18:27 INFO Received uploads request method=POST path=/api/pending_closures1381--- PASS: TestCreatePendingClosureRejectsOversizedNAR (0.00s)1382=== CONT TestGCTaskStore_PhaseUpdates1383--- PASS: TestGCTaskStore_PhaseUpdates (0.00s)1384=== CONT TestGracefulShutdownDrainsInflight13852026/11/06 07:18:27 INFO Starting HTTP server address=127.0.0.1:5538013862026/11/06 07:18:27 INFO Shutdown signal received, draining in-flight requests timeout=10s1387--- PASS: TestGracefulShutdownDrainsInflight (0.08s)1388=== CONT TestGCTaskStore_Fail1389--- PASS: TestGCTaskStore_Fail (0.00s)1390=== CONT TestConcurrentCommitsSharingObjectsDoNotDeadlock1391--- PASS: TestReadProxyHead (6.91s)1392=== CONT TestLeadElectsOneAndHandsOver1393--- PASS: TestReadProxyInvalidPath (6.98s)1394=== CONT TestConnectWaitsForAPeerMigration1395--- PASS: TestReadProxy404 (7.21s)1396=== CONT TestResolveDBConnectionString1397=== RUN TestResolveDBConnectionString/flag_wins1398=== PAUSE TestResolveDBConnectionString/flag_wins1399=== RUN TestResolveDBConnectionString/file_when_flag_empty1400=== PAUSE TestResolveDBConnectionString/file_when_flag_empty1401=== RUN TestResolveDBConnectionString/missing_file_is_an_error1402=== PAUSE TestResolveDBConnectionString/missing_file_is_an_error1403=== RUN TestResolveDBConnectionString/PGHOST_allows_empty1404=== PAUSE TestResolveDBConnectionString/PGHOST_allows_empty1405=== RUN TestResolveDBConnectionString/nothing_configured1406=== PAUSE TestResolveDBConnectionString/nothing_configured1407=== CONT TestService_AuthMiddleware_OIDC14082026/11/06 07:18:29 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:55398/oidc1409--- PASS: TestReadProxyNarStreaming (7.35s)1410=== CONT TestCacheConfigHandler1411=== RUN TestCacheConfigHandler/full_config,_no_issuer1412=== PAUSE TestCacheConfigHandler/full_config,_no_issuer1413=== RUN TestCacheConfigHandler/no_cache_url_configured1414=== PAUSE TestCacheConfigHandler/no_cache_url_configured1415=== RUN TestCacheConfigHandler/no_signing_keys1416=== PAUSE TestCacheConfigHandler/no_signing_keys1417=== RUN TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1418=== PAUSE TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1419=== CONT TestService_ReadScope_PublicByDefault1420--- PASS: TestReadProxyContentNegotiation (7.13s)1421=== CONT TestService_RequireScope_OIDC14222026/11/06 07:18:29 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:55409/oidc1423--- PASS: TestReadProxyNarinfoAlreadyDecompressed (7.29s)1424=== CONT TestService_AuthMiddleware_MTLSBoundSubjects1425--- PASS: TestPresentRefreshesOnlyStaleClosures (6.92s)1426=== CONT TestService_ReadAuthMiddleware14272026/11/06 07:18:30 ERROR Failed to decode narinfo key=3hcdxyjf9yiq7qf3i4548drb6sjmwa1v.narinfo limit=16777216 error=<nil>1428--- PASS: TestReadProxyNarinfo (7.65s)1429=== CONT TestGetExistingObjectsLocksRows1430--- PASS: TestPresentReportsOnlyClosureRoots (6.80s)1431=== CONT TestGenerateLandingPage1432--- PASS: TestGenerateLandingPage (0.00s)1433=== CONT TestGCTaskStore_DeduplicateSameParams1434--- PASS: TestGCTaskStore_DeduplicateSameParams (0.00s)1435=== CONT TestGCTaskStore_StartNew1436--- PASS: TestGCTaskStore_StartNew (0.00s)1437=== CONT TestClientFallsBackToClosures14382026/11/06 07:18:31 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux14392026/11/06 07:18:31 WARN Refused reserved pin name=worker-x86_64-linux14402026/11/06 07:18:31 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux14412026/11/06 07:18:31 INFO Received create pin request method=POST path=/api/pins/my-app14422026/11/06 07:18:31 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux1443--- PASS: TestCreatePin_ReservedPins (6.88s)1444=== CONT TestGCEndsOnShutdown1445=== RUN TestGCEndsOnShutdown/before_the_run1446=== PAUSE TestGCEndsOnShutdown/before_the_run1447=== RUN TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete1448=== PAUSE TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete1449=== RUN TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark1450=== PAUSE TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark1451=== CONT TestDeleteClosuresRacingPins1452--- PASS: TestReadProxyOutlastsServerWriteTimeout (11.04s)1453=== CONT TestCommitRacingPendingCleanupKeepsObjects1454--- PASS: TestObjectStatsUpdatedOncePerCommit (7.14s)1455=== CONT TestClientErrorHandling1456=== RUN TestClientErrorHandling/InvalidStorePath1457=== PAUSE TestClientErrorHandling/InvalidStorePath1458=== RUN TestClientErrorHandling/InvalidAuthToken1459=== PAUSE TestClientErrorHandling/InvalidAuthToken1460=== RUN TestClientErrorHandling/ServerNotAvailable1461=== PAUSE TestClientErrorHandling/ServerNotAvailable1462=== CONT TestPushWaitsForSweepHoldingRow1463--- PASS: TestObjectStatsTrigger (6.97s)1464=== CONT TestClientIntegration14652026/11/06 07:18:32 INFO Received uploads request method=POST path=/api/pending_closures14662026/11/06 07:18:32 INFO Received uploads request method=POST path=/api/pending_closures14672026/11/06 07:18:32 INFO Received cleanup request method=DELETE path=/api/pending_closures14682026/11/06 07:18:33 INFO Received uploads request method=POST path=/api/pending_closures1469--- PASS: TestMultipartUploadAbortedWhenCancelledBeforeRecorded (7.21s)1470=== CONT TestSweepRechecksPendingAfterLocking14712026/11/06 07:18:33 INFO Received uploads request method=POST path=/api/pending_closures14722026/11/06 07:18:33 INFO Received cleanup request method=DELETE path=/api/pending_closures14732026/11/06 07:18:33 WARN Failed to abort upload, keeping its closure key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst error="Get \"http://127.0.0.1:1/bucket61/?location=\": dial tcp 127.0.0.1:1: connect: connection refused" code=""14742026/11/06 07:18:33 INFO Aborted multipart uploads count=0 kept=114752026/11/06 07:18:33 INFO Received cleanup request method=DELETE path=/api/pending_closures14762026/11/06 07:18:33 INFO Aborted multipart uploads count=1 kept=01477--- PASS: TestMultipartCleanup (7.77s)1478=== CONT TestClientPushesUseOnePush1479=== NAME TestOrphanedObjectsGC1480 orphaned_objects_gc_test.go:287: GC Test Summary:1481 orphaned_objects_gc_test.go:288: - Kept: 2 objects from closure A1482 orphaned_objects_gc_test.go:289: - Deleted: 2 objects from closure B1483 orphaned_objects_gc_test.go:290: - Deleted: 6 orphaned chain objects (X1->X2->X3)1484 orphaned_objects_gc_test.go:291: - Deleted: 2 orphaned single objects (Y)1485 orphaned_objects_gc_test.go:292: - Total deleted: 10 objects1486--- PASS: TestOrphanedObjectsGC (8.94s)1487=== CONT TestService_AuthMiddleware_MTLSProxyHeader14882026/11/06 07:18:34 WARN mTLS auth: subject not in bound subjects subject="CN=reader"14892026/11/06 07:18:34 WARN mTLS auth: subject not in bound subjects subject="CN=reader"1490--- PASS: TestService_NativeMTLS (7.65s)1491=== CONT TestGCTaskStore_GetReturnsLatest1492--- PASS: TestGCTaskStore_GetReturnsLatest (0.00s)1493=== CONT TestGCTaskStore_CompletedAllowsNewTask1494--- PASS: TestGCTaskStore_CompletedAllowsNewTask (0.00s)1495=== CONT TestGCSweepDeliversEachKeyOnce1496--- PASS: TestService_healthCheckHandler (7.62s)1497=== CONT TestCreatePendingClosureVerifyS3FailureReleasesConnection1498--- PASS: TestMetricsInventory (7.93s)1499=== CONT TestGCTaskStore_GetEmpty1500--- PASS: TestGCTaskStore_GetEmpty (0.00s)1501=== CONT TestForceGCDuringPushOffersSweptObject1502=== RUN TestForceGCDuringPushOffersSweptObject/before_pending_rows1503=== PAUSE TestForceGCDuringPushOffersSweptObject/before_pending_rows1504=== RUN TestForceGCDuringPushOffersSweptObject/after_presence_check1505=== PAUSE TestForceGCDuringPushOffersSweptObject/after_presence_check1506=== CONT TestRegisterCompletedObjectNeedsPendingRow15072026/11/06 07:18:35 INFO lead: acquired remote=192.0.2.1:12341508=== NAME TestNARDeduplicationMetadataUploadBug1509 metadata_upload_test.go:48: First store path: /private/var/tb/4/scratch/6ba07dd8cd494155/build/TestNARDeduplicationMetadataUploadBug3746798573/001/store/a5a1970sqsxzy9pvjgzc08r14ph850pg-file1.txt1510--- PASS: TestConnectWaitsForAPeerMigration (6.77s)1511=== CONT TestService_readinessHandler15122026/11/06 07:18:35 INFO Received push request method=POST path=/api/pushes15132026/11/06 07:18:35 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)15142026/11/06 07:18:35 INFO Uploading a5a1970sqsxzy9pvjgzc08r14ph850pg-file1.txt (160B)15152026/11/06 07:18:35 WARN Failed to register uploaded object key=a5a1970sqsxzy9pvjgzc08r14ph850pg.ls error="server returned 404: 404 page not found\n"15162026/11/06 07:18:35 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign15172026/11/06 07:18:35 WARN Failed to register uploaded object key=nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst error="server returned 404: 404 page not found\n"15182026/11/06 07:18:35 INFO Signed narinfos id=1 count=115192026/11/06 07:18:35 INFO Uploading 1 narinfos15202026/11/06 07:18:35 INFO lead: acquired remote=192.0.2.1:123415212026/11/06 07:18:36 INFO Received complete push request method=POST path=/api/pushes/1/complete15222026/11/06 07:18:36 WARN Failed to register uploaded object key=a5a1970sqsxzy9pvjgzc08r14ph850pg.narinfo error="server returned 404: 404 page not found\n"15232026/11/06 07:18:36 INFO Completed push id=1 objects=3 duration=24.819375ms15242026/11/06 07:18:36 INFO Upload complete. (272ms)1525=== NAME TestNARDeduplicationMetadataUploadBug1526 metadata_upload_test.go:54: Retrieved narinfo from S3:1527 StorePath: /private/var/tb/4/scratch/6ba07dd8cd494155/build/TestNARDeduplicationMetadataUploadBug3746798573/001/store/a5a1970sqsxzy9pvjgzc08r14ph850pg-file1.txt1528 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1529 Compression: zstd1530 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1531 NarSize: 1601532 References: 1533 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1534 metadata_upload_test.go:55: Retrieved .ls file from S3 (compressed size: 77 bytes)1535 metadata_upload_test.go:55: Decompressed .ls content (64 bytes):1536 {"version":1,"root":{"type":"regular","size":44,"narOffset":96}}15372026/11/06 07:18:36 INFO lead: released remote=192.0.2.1:12341538--- PASS: TestLeadEndsOnShutdown (8.99s)1539=== CONT TestSweepSkipsRowsLockedByPush1540=== NAME TestNARDeduplicationMetadataUploadBug1541 metadata_upload_test.go:64: Second store path (same content): /private/var/tb/4/scratch/6ba07dd8cd494155/build/TestNARDeduplicationMetadataUploadBug3746798573/001/store/m5lmrs2i9snzwxwzkqmjnr0zg6qz9mqm-file2.txt1542=== RUN TestService_AuthMiddleware_OIDC/valid_OIDC_token1543=== PAUSE TestService_AuthMiddleware_OIDC/valid_OIDC_token1544=== RUN TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1545=== PAUSE TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1546=== RUN TestService_AuthMiddleware_OIDC/malformed_token_rejected1547=== PAUSE TestService_AuthMiddleware_OIDC/malformed_token_rejected1548=== RUN TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1549=== PAUSE TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1550=== CONT TestFailedS3DeleteKeepsTombstone15512026/11/06 07:18:36 INFO Received push request method=POST path=/api/pushes15522026/11/06 07:18:36 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)15532026/11/06 07:18:36 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign15542026/11/06 07:18:36 WARN Failed to register uploaded object key=m5lmrs2i9snzwxwzkqmjnr0zg6qz9mqm.ls error="server returned 404: 404 page not found\n"15552026/11/06 07:18:36 INFO Signed narinfos id=2 count=115562026/11/06 07:18:36 INFO Uploading 1 narinfos15572026/11/06 07:18:36 INFO Received complete push request method=POST path=/api/pushes/2/complete15582026/11/06 07:18:36 WARN Failed to register uploaded object key=m5lmrs2i9snzwxwzkqmjnr0zg6qz9mqm.narinfo error="server returned 404: 404 page not found\n"15592026/11/06 07:18:36 INFO Completed push id=2 objects=3 duration=1.497375ms15602026/11/06 07:18:36 INFO Upload complete. (164ms)1561=== NAME TestNARDeduplicationMetadataUploadBug1562 metadata_upload_test.go:76: Retrieved narinfo from S3:1563 StorePath: /private/var/tb/4/scratch/6ba07dd8cd494155/build/TestNARDeduplicationMetadataUploadBug3746798573/001/store/m5lmrs2i9snzwxwzkqmjnr0zg6qz9mqm-file2.txt1564 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1565 Compression: zstd1566 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1567 NarSize: 1601568 References: 1569 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1570 metadata_upload_test.go:77: Retrieved .ls file from S3 (compressed size: 62 bytes)1571 metadata_upload_test.go:77: Decompressed .ls content (49 bytes):1572 {"version":1,"root":{"type":"regular","size":44}}1573--- PASS: TestNARDeduplicationMetadataUploadBug (9.01s)1574=== CONT TestTombstonedObjectOfferedWithoutWaiting1575--- PASS: TestService_ReadScope_PublicByDefault (7.19s)1576=== CONT TestClientCADerivations1577--- PASS: TestConcurrentCommitsSharingObjectsDoNotDeadlock (8.88s)1578=== CONT TestCacheConfigHandlerMaxNarSize1579--- PASS: TestCacheConfigHandlerMaxNarSize (0.00s)1580=== CONT TestGCTaskStore_ConflictDifferentParams1581--- PASS: TestGCTaskStore_ConflictDifferentParams (0.00s)1582=== CONT TestProxyWriteTimeout/narinfo1583=== CONT TestProxyWriteTimeout/unknown_size1584=== CONT TestProxyWriteTimeout/10_GiB_nar1585=== CONT TestProxyWriteTimeout/1_GiB_nar1586--- PASS: TestProxyWriteTimeout (0.08s)1587 --- PASS: TestProxyWriteTimeout/narinfo (0.00s)1588 --- PASS: TestProxyWriteTimeout/unknown_size (0.00s)1589 --- PASS: TestProxyWriteTimeout/10_GiB_nar (0.00s)1590 --- PASS: TestProxyWriteTimeout/1_GiB_nar (0.00s)1591=== CONT TestService_verifyS3ReuploadsStaleNarinfo/lost,_other_NAR_pushed15922026/11/06 07:18:36 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted,O=Other"15932026/11/06 07:18:36 WARN mTLS auth: bound subjects configured but subject DN unavailable15942026/11/06 07:18:36 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted"1595--- PASS: TestService_AuthMiddleware_MTLSBoundSubjects (6.99s)1596=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info15972026/11/06 07:18:36 INFO Received uploads request method=POST path=/1598=== CONT TestPendingClosureWriteTimeout/empty1599=== CONT TestService_verifyS3ReuploadsStaleNarinfo/lost,_same_NAR_pushed1600=== RUN TestService_RequireScope_OIDC/builder_may_write1601=== PAUSE TestService_RequireScope_OIDC/builder_may_write1602=== RUN TestService_RequireScope_OIDC/builder_may_not_admin1603=== PAUSE TestService_RequireScope_OIDC/builder_may_not_admin1604=== RUN TestService_RequireScope_OIDC/ops_may_admin1605=== PAUSE TestService_RequireScope_OIDC/ops_may_admin1606=== RUN TestService_RequireScope_OIDC/ops_may_not_write1607=== PAUSE TestService_RequireScope_OIDC/ops_may_not_write1608=== RUN TestService_RequireScope_OIDC/reader_may_not_write1609=== PAUSE TestService_RequireScope_OIDC/reader_may_not_write1610=== RUN TestService_RequireScope_OIDC/static_token_may_admin1611=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin1612=== RUN TestService_RequireScope_OIDC/static_token_may_write1613=== PAUSE TestService_RequireScope_OIDC/static_token_may_write1614=== RUN TestService_RequireScope_OIDC/reader_may_read1615=== PAUSE TestService_RequireScope_OIDC/reader_may_read1616=== RUN TestService_RequireScope_OIDC/writer_implies_read1617=== PAUSE TestService_RequireScope_OIDC/writer_implies_read1618=== RUN TestService_RequireScope_OIDC/anonymous_may_not_read1619=== PAUSE TestService_RequireScope_OIDC/anonymous_may_not_read1620=== RUN TestService_RequireScope_OIDC/reader_may_read_with_netrc1621=== PAUSE TestService_RequireScope_OIDC/reader_may_read_with_netrc1622=== RUN TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1623=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1624=== RUN TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read1625=== PAUSE TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read1626=== RUN TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1627=== PAUSE TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1628=== CONT TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost,_second_pushed16292026/11/06 07:18:37 INFO lead: released remote=192.0.2.1:123416302026/11/06 07:18:37 INFO lead: acquired remote=192.0.2.1:12341631--- PASS: TestService_ReadAuthMiddleware (7.17s)1632=== CONT TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost1633--- PASS: TestGetExistingObjectsLocksRows (6.98s)1634=== CONT TestService_verifyS3ReuploadsStaleNarinfo/intact,_other_NAR_pushed16352026/11/06 07:18:38 INFO lead: released remote=192.0.2.1:12341636--- PASS: TestLeadElectsOneAndHandsOver (9.93s)1637=== CONT TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key16382026/11/06 07:18:38 INFO Received request for more parts method=POST path=/1639=== CONT TestIsValidUploadKey/narinfo1640=== CONT TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key16412026/11/06 07:18:38 INFO Received complete multipart upload request method=POST path=/1642=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal16432026/11/06 07:18:38 INFO Received uploads request method=POST path=/1644--- PASS: TestUploadHandlersRejectInvalidKeys (0.08s)1645 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info (0.00s)1646 --- PASS: TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key (0.00s)1647 --- PASS: TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key (0.00s)1648 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal (0.00s)1649=== CONT TestIsValidUploadKey/traversal_nar1650=== CONT TestIsValidUploadKey/nix-cache-info1651=== CONT TestIsValidUploadKey/traversal1652=== CONT TestIsValidUploadKey/listing_key,_narinfo_type1653=== CONT TestIsValidUploadKey/nar_key,_narinfo_type1654=== CONT TestIsValidUploadKey/narinfo_key,_nar_type1655=== CONT TestIsValidUploadKey/index.html1656=== CONT TestIsValidUploadKey/empty_key1657=== CONT TestIsValidUploadKey/unknown_type1658=== CONT TestPendingClosureWriteTimeout/670k_objects1659=== CONT TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline16602026/11/06 07:18:38 INFO Received uploads request method=POST path=/api/pending_closures16612026/11/06 07:18:38 INFO Received uploads request method=POST path=/api/pending_closures16622026/11/06 07:18:38 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)16632026/11/06 07:18:38 INFO Uploading r37mvg4g57xczscp2afi3rrm3blys4vn-shared-dep (136B)16642026/11/06 07:18:38 INFO Uploading jx2vblk0b8vlvc55da3qlwk3x1s4g73q-a (256B)16652026/11/06 07:18:38 WARN Failed to register uploaded object key=i877k3y9g9g69q50yc8ba27pyiapm79n.ls error="server returned 404: 404 page not found\n"16662026/11/06 07:18:38 WARN Failed to register uploaded object key=jx2vblk0b8vlvc55da3qlwk3x1s4g73q.ls error="server returned 404: 404 page not found\n"16672026/11/06 07:18:38 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"16682026/11/06 07:18:38 WARN Failed to register uploaded object key=r37mvg4g57xczscp2afi3rrm3blys4vn.ls error="server returned 404: 404 page not found\n"16692026/11/06 07:18:38 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign16702026/11/06 07:18:38 WARN Failed to register uploaded object key=nar/0wdj1nhkfl7dq72gh6hn4lia7syz6znk8r4r6b96ilfa3dr8dgjd.nar.zst error="server returned 404: 404 page not found\n"16712026/11/06 07:18:38 INFO Signed narinfos id=2 count=216722026/11/06 07:18:38 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign16732026/11/06 07:18:38 INFO Signed narinfos id=1 count=216742026/11/06 07:18:38 INFO Uploading 4 narinfos16752026/11/06 07:18:38 WARN Failed to register uploaded object key=i877k3y9g9g69q50yc8ba27pyiapm79n.narinfo error="server returned 404: 404 page not found\n"16762026/11/06 07:18:38 WARN Failed to register uploaded object key=r37mvg4g57xczscp2afi3rrm3blys4vn.narinfo error="server returned 404: 404 page not found\n"16772026/11/06 07:18:38 WARN Failed to register uploaded object key=jx2vblk0b8vlvc55da3qlwk3x1s4g73q.narinfo error="server returned 404: 404 page not found\n"16782026/11/06 07:18:38 INFO Aborted multipart uploads count=0 kept=016792026/11/06 07:18:38 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete16802026/11/06 07:18:38 WARN Failed to register uploaded object key=r37mvg4g57xczscp2afi3rrm3blys4vn.narinfo error="server returned 404: 404 page not found\n"16812026/11/06 07:18:38 WARN Force mode enabled - objects will be deleted immediately without grace period16822026/11/06 07:18: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=016832026/11/06 07:18:38 INFO Completed upload id=1 objects=6 duration=25.32725ms16842026/11/06 07:18:38 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete16852026/11/06 07:18:38 INFO Completed upload id=2 objects=6 duration=3.515291ms16862026/11/06 07:18:38 INFO Upload complete. (438ms)1687=== NAME TestClientFallsBackToClosures1688 client_pushes_test.go:112: Retrieved narinfo from S3:1689 StorePath: /private/var/tb/4/scratch/6ba07dd8cd494155/build/TestClientFallsBackToClosures2713625260/001/store/r37mvg4g57xczscp2afi3rrm3blys4vn-shared-dep1690 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1691 Compression: zstd1692 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821693 NarSize: 1361694 References: 1695 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1696 client_pushes_test.go:112: Retrieved narinfo from S3:1697 StorePath: /private/var/tb/4/scratch/6ba07dd8cd494155/build/TestClientFallsBackToClosures2713625260/001/store/jx2vblk0b8vlvc55da3qlwk3x1s4g73q-a1698 URL: nar/0wdj1nhkfl7dq72gh6hn4lia7syz6znk8r4r6b96ilfa3dr8dgjd.nar.zst1699 Compression: zstd1700 NarHash: sha256:0wdj1nhkfl7dq72gh6hn4lia7syz6znk8r4r6b96ilfa3dr8dgjd1701 NarSize: 2561702 References: /private/var/tb/4/scratch/6ba07dd8cd494155/build/TestClientFallsBackToClosures2713625260/001/store/r37mvg4g57xczscp2afi3rrm3blys4vn-shared-dep1703 CA: text:sha256:03147r6k1wab0a75nwy2538bzla4cy2s55r8bj7rz62nll6f0ac317042026/11/06 07:18:38 INFO Vacuumed table table=pending_closures1705 client_pushes_test.go:112: Retrieved narinfo from S3:1706 StorePath: /private/var/tb/4/scratch/6ba07dd8cd494155/build/TestClientFallsBackToClosures2713625260/001/store/i877k3y9g9g69q50yc8ba27pyiapm79n-b1707 URL: nar/0wdj1nhkfl7dq72gh6hn4lia7syz6znk8r4r6b96ilfa3dr8dgjd.nar.zst1708 Compression: zstd1709 NarHash: sha256:0wdj1nhkfl7dq72gh6hn4lia7syz6znk8r4r6b96ilfa3dr8dgjd1710 NarSize: 2561711 References: /private/var/tb/4/scratch/6ba07dd8cd494155/build/TestClientFallsBackToClosures2713625260/001/store/r37mvg4g57xczscp2afi3rrm3blys4vn-shared-dep1712 CA: text:sha256:03147r6k1wab0a75nwy2538bzla4cy2s55r8bj7rz62nll6f0ac317132026/11/06 07:18:38 INFO Vacuumed table table=pending_objects17142026/11/06 07:18:38 INFO Vacuumed table table=multipart_uploads17152026/11/06 07:18:38 INFO Received uploads request method=POST path=/api/pending_closures17162026/11/06 07:18:38 INFO Vacuumed table table=closures17172026/11/06 07:18:38 INFO Vacuumed table table=objects1718--- PASS: TestClientFallsBackToClosures (8.02s)1719=== CONT TestIsValidUploadKey/absolute1720=== CONT TestPendingClosureWriteTimeout/400_objects1721=== CONT TestIsValidUploadKey/build_log_home-manager_file1722=== CONT TestIsValidUploadKey/realisation_plus_in_output1723=== CONT TestIsValidUploadKey/realisation1724=== CONT TestIsValidUploadKey/build_log_equals1725=== CONT TestIsValidUploadKey/build_log_question_mark1726=== CONT TestIsValidUploadKey/build_log_plus_in_name1727=== CONT TestIsValidUploadKey/nar_plain1728=== CONT TestIsValidUploadKey/build_log1729=== CONT TestIsValidUploadKey/listing1730=== CONT TestIsValidUploadKey/nar_xz1731=== CONT TestIsValidUploadKey/nar_zst17322026/11/06 07:18:38 INFO Aborted multipart uploads count=1 kept=01733--- PASS: TestIsValidUploadKey (0.11s)1734 --- PASS: TestIsValidUploadKey/narinfo (0.00s)1735 --- PASS: TestIsValidUploadKey/traversal_nar (0.00s)1736 --- PASS: TestIsValidUploadKey/nix-cache-info (0.00s)1737 --- PASS: TestIsValidUploadKey/traversal (0.00s)1738 --- PASS: TestIsValidUploadKey/listing_key,_narinfo_type (0.00s)1739 --- PASS: TestIsValidUploadKey/nar_key,_narinfo_type (0.00s)1740 --- PASS: TestIsValidUploadKey/narinfo_key,_nar_type (0.00s)1741 --- PASS: TestIsValidUploadKey/index.html (0.00s)1742 --- PASS: TestIsValidUploadKey/empty_key (0.00s)1743 --- PASS: TestIsValidUploadKey/unknown_type (0.00s)1744 --- PASS: TestIsValidUploadKey/absolute (0.00s)1745 --- PASS: TestIsValidUploadKey/build_log_home-manager_file (0.00s)1746 --- PASS: TestIsValidUploadKey/realisation_plus_in_output (0.00s)1747 --- PASS: TestIsValidUploadKey/realisation (0.00s)1748 --- PASS: TestIsValidUploadKey/build_log_equals (0.00s)1749 --- PASS: TestIsValidUploadKey/build_log_question_mark (0.00s)1750 --- PASS: TestIsValidUploadKey/build_log_plus_in_name (0.00s)1751 --- PASS: TestIsValidUploadKey/nar_plain (0.00s)1752 --- PASS: TestIsValidUploadKey/build_log (0.00s)1753 --- PASS: TestIsValidUploadKey/listing (0.00s)1754 --- PASS: TestIsValidUploadKey/nar_xz (0.00s)1755 --- PASS: TestIsValidUploadKey/nar_zst (0.00s)1756=== CONT TestUploadHandlersRejectOversizedBody/create_pending_closure17572026/11/06 07:18:38 INFO Received uploads request method=POST path=/1758--- PASS: TestCommitRacingPendingCleanupKeepsObjects (6.57s)1759=== CONT TestUploadHandlersRejectOversizedBody/request_more_parts17602026/11/06 07:18:38 INFO Received request for more parts method=POST path=/17612026/11/06 07:18:38 INFO Received cleanup request method=DELETE path=/api/pending_closures1762=== CONT TestUploadHandlersRejectOversizedBody/complete_multipart17632026/11/06 07:18:38 INFO Received complete multipart upload request method=POST path=/17642026/11/06 07:18:38 INFO Aborted multipart uploads count=1 kept=01765--- PASS: TestPendingCleanupUsesOneCutoff (13.21s)1766=== CONT TestPush_RejectsBadRequests/no_objects17672026/11/06 07:18:38 INFO Received push request method=POST path=/api/pushes1768=== CONT TestPush_RejectsBadRequests/root_not_in_objects17692026/11/06 07:18:38 INFO Received push request method=POST path=/api/pushes1770=== CONT TestPush_RejectsBadRequests/no_roots17712026/11/06 07:18:38 INFO Received push request method=POST path=/api/pushes1772=== CONT TestPush_RejectsBadRequests/bad_root17732026/11/06 07:18:38 INFO Received push request method=POST path=/api/pushes1774--- PASS: TestPush_RejectsBadRequests (6.26s)1775 --- PASS: TestPush_RejectsBadRequests/no_objects (0.00s)1776 --- PASS: TestPush_RejectsBadRequests/root_not_in_objects (0.00s)1777 --- PASS: TestPush_RejectsBadRequests/no_roots (0.00s)1778 --- PASS: TestPush_RejectsBadRequests/bad_root (0.00s)1779=== CONT TestIsValidCachePath/narinfo1780=== CONT TestParseSingleRange/none1781=== CONT TestIsValidCachePath/short_hash1782=== CONT TestIsValidCachePath/wrong_extension1783=== CONT TestIsValidCachePath/leading_slash1784=== CONT TestIsValidCachePath/empty1785=== CONT TestIsValidCachePath/random_path1786=== CONT TestIsValidCachePath/invalid_char_u1787=== CONT TestIsValidCachePath/invalid_char_e1788=== CONT TestIsValidCachePath/traversal_in_middle1789=== CONT TestIsValidCachePath/traversal_parent1790=== CONT TestIsValidCachePath/index.html1791=== CONT TestIsValidCachePath/nix-cache-info1792=== CONT TestIsValidCachePath/realisation1793=== CONT TestIsValidCachePath/log1794=== CONT TestIsValidCachePath/ls1795=== CONT TestIsValidCachePath/nar_uncompressed1796=== CONT TestIsValidCachePath/nar_bz21797=== CONT TestIsValidCachePath/nar_xz1798=== CONT TestIsValidCachePath/nar_zst1799=== CONT TestIsValidCachePath/narinfo_all_nix_base32_chars1800--- PASS: TestIsValidCachePath (0.00s)1801 --- PASS: TestIsValidCachePath/narinfo (0.00s)1802 --- PASS: TestIsValidCachePath/short_hash (0.00s)1803 --- PASS: TestIsValidCachePath/wrong_extension (0.00s)1804 --- PASS: TestIsValidCachePath/leading_slash (0.00s)1805 --- PASS: TestIsValidCachePath/empty (0.00s)1806 --- PASS: TestIsValidCachePath/random_path (0.00s)1807 --- PASS: TestIsValidCachePath/invalid_char_u (0.00s)1808 --- PASS: TestIsValidCachePath/invalid_char_e (0.00s)1809 --- PASS: TestIsValidCachePath/traversal_in_middle (0.00s)1810 --- PASS: TestIsValidCachePath/traversal_parent (0.00s)1811 --- PASS: TestIsValidCachePath/index.html (0.00s)1812 --- PASS: TestIsValidCachePath/nix-cache-info (0.00s)1813 --- PASS: TestIsValidCachePath/realisation (0.00s)1814 --- PASS: TestIsValidCachePath/log (0.00s)1815 --- PASS: TestIsValidCachePath/ls (0.00s)1816 --- PASS: TestIsValidCachePath/nar_uncompressed (0.00s)1817 --- PASS: TestIsValidCachePath/nar_bz2 (0.00s)1818 --- PASS: TestIsValidCachePath/nar_xz (0.00s)1819 --- PASS: TestIsValidCachePath/nar_zst (0.00s)1820 --- PASS: TestIsValidCachePath/narinfo_all_nix_base32_chars (0.00s)1821=== CONT TestPresentNotReportedWhileGCDeletesClosure/stale1822=== CONT TestParseSingleRange/start_far_past_EOF1823=== CONT TestParseSingleRange/start_past_EOF1824=== CONT TestParseSingleRange/single_byte1825=== CONT TestParseSingleRange/suffix_exceeds_size1826=== CONT TestParseSingleRange/suffix1827=== CONT TestParseSingleRange/end_clamped_to_size1828=== CONT TestParseSingleRange/open-ended1829=== CONT TestParseSingleRange/closed1830=== CONT TestParseSingleRange/malformed_end_before_start1831=== CONT TestParseSingleRange/malformed_both_empty1832=== CONT TestParseSingleRange/malformed_no_dash1833=== CONT TestParseSingleRange/multi-range_ignored1834=== CONT TestParseSingleRange/unknown_unit1835=== CONT TestPresentNotReportedWhileGCDeletesClosure/fresh1836--- PASS: TestParseSingleRange (0.00s)1837 --- PASS: TestParseSingleRange/none (0.00s)1838 --- PASS: TestParseSingleRange/start_far_past_EOF (0.00s)1839 --- PASS: TestParseSingleRange/start_past_EOF (0.00s)1840 --- PASS: TestParseSingleRange/single_byte (0.00s)1841 --- PASS: TestParseSingleRange/suffix_exceeds_size (0.00s)1842 --- PASS: TestParseSingleRange/suffix (0.00s)1843 --- PASS: TestParseSingleRange/end_clamped_to_size (0.00s)1844 --- PASS: TestParseSingleRange/open-ended (0.00s)1845 --- PASS: TestParseSingleRange/closed (0.00s)1846 --- PASS: TestParseSingleRange/malformed_end_before_start (0.00s)1847 --- PASS: TestParseSingleRange/malformed_both_empty (0.00s)1848 --- PASS: TestParseSingleRange/malformed_no_dash (0.00s)1849 --- PASS: TestParseSingleRange/multi-range_ignored (0.00s)1850 --- PASS: TestParseSingleRange/unknown_unit (0.00s)1851=== CONT TestServerTLSConfig/no_client_CA1852=== CONT TestServerTLSConfig/not_a_PEM_file1853--- PASS: TestUploadHandlersRejectOversizedBody (0.36s)1854 --- PASS: TestUploadHandlersRejectOversizedBody/request_more_parts (0.03s)1855 --- PASS: TestUploadHandlersRejectOversizedBody/complete_multipart (0.03s)1856 --- PASS: TestUploadHandlersRejectOversizedBody/create_pending_closure (0.38s)1857=== CONT TestServerTLSConfig/missing_CA_file1858=== CONT TestResolveDBConnectionString/flag_wins1859=== CONT TestResolveDBConnectionString/PGHOST_allows_empty1860=== CONT TestResolveDBConnectionString/nothing_configured1861=== CONT TestResolveDBConnectionString/missing_file_is_an_error1862=== CONT TestResolveDBConnectionString/file_when_flag_empty1863--- PASS: TestServerTLSConfig (0.00s)1864 --- PASS: TestServerTLSConfig/no_client_CA (0.00s)1865 --- PASS: TestServerTLSConfig/not_a_PEM_file (0.02s)1866 --- PASS: TestServerTLSConfig/missing_CA_file (0.00s)1867=== CONT TestCacheConfigHandler/full_config,_no_issuer1868=== CONT TestCacheConfigHandler/no_signing_keys1869=== CONT TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1870--- PASS: TestResolveDBConnectionString (0.01s)1871 --- PASS: TestResolveDBConnectionString/flag_wins (0.00s)1872 --- PASS: TestResolveDBConnectionString/PGHOST_allows_empty (0.00s)1873 --- PASS: TestResolveDBConnectionString/nothing_configured (0.00s)1874 --- PASS: TestResolveDBConnectionString/missing_file_is_an_error (0.00s)1875 --- PASS: TestResolveDBConnectionString/file_when_flag_empty (0.00s)1876=== CONT TestCacheConfigHandler/no_cache_url_configured1877--- PASS: TestCacheConfigHandler (0.00s)1878 --- PASS: TestCacheConfigHandler/full_config,_no_issuer (0.00s)1879 --- PASS: TestCacheConfigHandler/no_signing_keys (0.00s)1880 --- PASS: TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator (0.00s)1881 --- PASS: TestCacheConfigHandler/no_cache_url_configured (0.00s)1882=== CONT TestGCEndsOnShutdown/before_the_run1883=== NAME TestClientIntegration1884 client_integration_test.go:291: Created store path: /private/var/tb/4/scratch/6ba07dd8cd494155/build/TestClientIntegration185399395/002/store/rvwmnb9gfmqznd95bdp28lr4pamdrc0x-test-file.txt1885--- PASS: TestPushWaitsForSweepHoldingRow (7.01s)1886=== CONT TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark18872026/11/06 07:18:39 INFO Aborted multipart uploads count=0 kept=018882026/11/06 07:18:39 WARN Force mode enabled - objects will be deleted immediately without grace period18892026/11/06 07:18:39 INFO Received push request method=POST path=/api/pushes18902026/11/06 07:18:39 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)18912026/11/06 07:18:39 INFO Uploading rvwmnb9gfmqznd95bdp28lr4pamdrc0x-test-file.txt (152B)18922026/11/06 07:18:39 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=018932026/11/06 07:18:39 INFO Vacuumed table table=pending_closures18942026/11/06 07:18:39 INFO Vacuumed table table=pending_objects18952026/11/06 07:18:39 INFO Vacuumed table table=multipart_uploads18962026/11/06 07:18:39 WARN Failed to register uploaded object key=rvwmnb9gfmqznd95bdp28lr4pamdrc0x.ls error="server returned 404: 404 page not found\n"18972026/11/06 07:18:39 INFO Vacuumed table table=closures18982026/11/06 07:18:39 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign18992026/11/06 07:18:39 WARN Failed to register uploaded object key=nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst error="server returned 404: 404 page not found\n"19002026/11/06 07:18:39 INFO Signed narinfos id=1 count=119012026/11/06 07:18:39 INFO Uploading 1 narinfos19022026/11/06 07:18:39 INFO Vacuumed table table=objects1903--- PASS: TestSweepRechecksPendingAfterLocking (6.43s)1904=== CONT TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete19052026/11/06 07:18:39 INFO Received complete push request method=POST path=/api/pushes/1/complete19062026/11/06 07:18:39 WARN Failed to register uploaded object key=rvwmnb9gfmqznd95bdp28lr4pamdrc0x.narinfo error="server returned 404: 404 page not found\n"19072026/11/06 07:18:39 INFO Completed push id=1 objects=3 duration=19.551291ms19082026/11/06 07:18:39 INFO Upload complete. (267ms)19092026/11/06 07:18:39 INFO All 1 paths already cached1910=== NAME TestClientIntegration1911 client_integration_test.go:317: Retrieved narinfo from S3:1912 StorePath: /private/var/tb/4/scratch/6ba07dd8cd494155/build/TestClientIntegration185399395/002/store/rvwmnb9gfmqznd95bdp28lr4pamdrc0x-test-file.txt1913 URL: nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst1914 Compression: zstd1915 NarHash: sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11916 NarSize: 1521917 References: 1918 CA: fixed:r:sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11919 client_integration_test.go:318: Retrieved .ls file from S3 (compressed size: 77 bytes)1920 client_integration_test.go:318: Decompressed .ls content (64 bytes):1921 {"version":1,"root":{"type":"regular","size":39,"narOffset":96}}1922--- PASS: TestService_AuthMiddleware_MTLSProxyHeader (6.00s)1923=== CONT TestClientErrorHandling/InvalidStorePath19242026/11/06 07:18:40 INFO Received push request method=POST path=/api/pushes19252026/11/06 07:18:40 INFO Object in database but missing from S3 key=rvwmnb9gfmqznd95bdp28lr4pamdrc0x.ls19262026/11/06 07:18:40 WARN Found objects in DB but missing from S3, will re-upload count=119272026/11/06 07:18:40 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)19282026/11/06 07:18:40 INFO Received complete push request method=POST path=/api/pushes/2/complete19292026/11/06 07:18:40 WARN Failed to register uploaded object key=rvwmnb9gfmqznd95bdp28lr4pamdrc0x.ls error="server returned 404: 404 page not found\n"19302026/11/06 07:18:40 INFO Completed push id=2 objects=3 duration=15.587417ms19312026/11/06 07:18:40 INFO Upload complete. (142ms)1932=== NAME TestClientIntegration1933 client_integration_test.go:335: Retrieved .ls file from S3 (compressed size: 62 bytes)1934 client_integration_test.go:335: Decompressed .ls content (49 bytes):1935 {"version":1,"root":{"type":"regular","size":39}}19362026/11/06 07:18:40 INFO Received push request method=POST path=/api/pushes19372026/11/06 07:18:40 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)19382026/11/06 07:18:40 INFO Uploading b5nnidhn2vs1ddhx2y0y300xzg235b7l-shared-dep (136B)19392026/11/06 07:18:40 INFO Uploading 4y9zsd7hwb90sj2dxhn6c30pjr39k7cl-a (256B)19402026/11/06 07:18:40 WARN Failed to register uploaded object key=4y9zsd7hwb90sj2dxhn6c30pjr39k7cl.ls error="server returned 404: 404 page not found\n"19412026/11/06 07:18:40 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"19422026/11/06 07:18:40 WARN Failed to register uploaded object key=b5nnidhn2vs1ddhx2y0y300xzg235b7l.ls error="server returned 404: 404 page not found\n"19432026/11/06 07:18:40 WARN Failed to register uploaded object key=nar/1yrbvz2gaxf8y1l8c21v8p2mv0356kdi9mc7zmsnqca05sr90g39.nar.zst error="server returned 404: 404 page not found\n"19442026/11/06 07:18:40 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign19452026/11/06 07:18:40 WARN Failed to register uploaded object key=ymzdkygzr6sc3pkm8zl1hrha17mng436.ls error="server returned 404: 404 page not found\n"19462026/11/06 07:18:40 INFO Signed narinfos id=1 count=319472026/11/06 07:18:40 INFO Uploading 3 narinfos19482026/11/06 07:18:40 INFO Aborted multipart uploads count=0 kept=019492026/11/06 07:18:40 WARN Failed to register uploaded object key=b5nnidhn2vs1ddhx2y0y300xzg235b7l.narinfo error="server returned 404: 404 page not found\n"19502026/11/06 07:18:40 WARN Force mode enabled - objects will be deleted immediately without grace period19512026/11/06 07:18:40 WARN Failed to register uploaded object key=ymzdkygzr6sc3pkm8zl1hrha17mng436.narinfo error="server returned 404: 404 page not found\n"19522026/11/06 07:18:40 INFO Received complete push request method=POST path=/api/pushes/1/complete19532026/11/06 07:18:40 WARN Failed to register uploaded object key=4y9zsd7hwb90sj2dxhn6c30pjr39k7cl.narinfo error="server returned 404: 404 page not found\n"19542026/11/06 07:18:40 INFO Completed push id=1 objects=8 duration=31.644875ms19552026/11/06 07:18:40 INFO Received push request method=POST path=/api/pushes19562026/11/06 07:18:40 INFO Upload complete. (423ms)19572026/11/06 07:18:40 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)1958=== NAME TestClientPushesUseOnePush1959 client_pushes_test.go:97: Retrieved narinfo from S3:1960 StorePath: /private/var/tb/4/scratch/6ba07dd8cd494155/build/TestClientPushesUseOnePush2680232062/001/store/b5nnidhn2vs1ddhx2y0y300xzg235b7l-shared-dep1961 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1962 Compression: zstd1963 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821964 NarSize: 1361965 References: 1966 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1967 client_pushes_test.go:97: Retrieved narinfo from S3:1968 StorePath: /private/var/tb/4/scratch/6ba07dd8cd494155/build/TestClientPushesUseOnePush2680232062/001/store/4y9zsd7hwb90sj2dxhn6c30pjr39k7cl-a1969 URL: nar/1yrbvz2gaxf8y1l8c21v8p2mv0356kdi9mc7zmsnqca05sr90g39.nar.zst1970 Compression: zstd1971 NarHash: sha256:1yrbvz2gaxf8y1l8c21v8p2mv0356kdi9mc7zmsnqca05sr90g391972 NarSize: 2561973 References: /private/var/tb/4/scratch/6ba07dd8cd494155/build/TestClientPushesUseOnePush2680232062/001/store/b5nnidhn2vs1ddhx2y0y300xzg235b7l-shared-dep1974 CA: text:sha256:1s7z6vavdzmhp3la1pxqpnhn9ccn1xaa7g6vz9l3hjd8pn5af1pa1975 client_pushes_test.go:97: Retrieved narinfo from S3:1976 StorePath: /private/var/tb/4/scratch/6ba07dd8cd494155/build/TestClientPushesUseOnePush2680232062/001/store/ymzdkygzr6sc3pkm8zl1hrha17mng436-b1977 URL: nar/1yrbvz2gaxf8y1l8c21v8p2mv0356kdi9mc7zmsnqca05sr90g39.nar.zst1978 Compression: zstd1979 NarHash: sha256:1yrbvz2gaxf8y1l8c21v8p2mv0356kdi9mc7zmsnqca05sr90g391980 NarSize: 2561981 References: /private/var/tb/4/scratch/6ba07dd8cd494155/build/TestClientPushesUseOnePush2680232062/001/store/b5nnidhn2vs1ddhx2y0y300xzg235b7l-shared-dep1982 CA: text:sha256:1s7z6vavdzmhp3la1pxqpnhn9ccn1xaa7g6vz9l3hjd8pn5af1pa19832026/11/06 07:18:40 INFO Received complete push request method=POST path=/api/pushes/3/complete19842026/11/06 07:18:40 WARN Failed to register uploaded object key=rvwmnb9gfmqznd95bdp28lr4pamdrc0x.ls error="server returned 404: 404 page not found\n"19852026/11/06 07:18:40 INFO Completed push id=3 objects=3 duration=743.708µs19862026/11/06 07:18:40 INFO Upload complete. (159ms)1987=== NAME TestClientIntegration1988 client_integration_test.go:352: Retrieved .ls file from S3 (compressed size: 62 bytes)1989 client_integration_test.go:352: Decompressed .ls content (49 bytes):1990 {"version":1,"root":{"type":"regular","size":39}}1991 client_integration_test.go:363: Testing garbage collection...19922026/11/06 07:18:40 INFO Starting cleanup of old closures method=DELETE path=/api/closures19932026/11/06 07:18:40 INFO Garbage collection started19942026/11/06 07:18:40 INFO Aborted multipart uploads count=0 kept=019952026/11/06 07:18:40 INFO Received uploads request method=POST path=/api/pending_closures1996--- PASS: TestClientPushesUseOnePush (6.92s)19972026/11/06 07:18:40 WARN Force mode enabled - objects will be deleted immediately without grace period1998=== CONT TestClientErrorHandling/ServerNotAvailable1999--- PASS: TestCreatePendingClosureVerifyS3FailureReleasesConnection (6.81s)2000=== CONT TestClientErrorHandling/InvalidAuthToken20012026/11/06 07:18:41 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=020022026/11/06 07:18:41 INFO Vacuumed table table=pending_closures20032026/11/06 07:18:41 INFO Vacuumed table table=pending_objects20042026/11/06 07:18:41 INFO Vacuumed table table=multipart_uploads20052026/11/06 07:18:41 INFO Vacuumed table table=closures20062026/11/06 07:18:41 INFO Vacuumed table table=objects2007--- PASS: TestGCSweepDeliversEachKeyOnce (7.32s)2008=== CONT TestForceGCDuringPushOffersSweptObject/before_pending_rows2009--- PASS: TestRegisterCompletedObjectNeedsPendingRow (6.70s)2010=== CONT TestForceGCDuringPushOffersSweptObject/after_presence_check20112026/11/06 07:18:41 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=1 objects-marked-for-deletion=3 objects-deleted-after-grace-period=3 objects-failed-to-delete=020122026/11/06 07:18:41 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/present20132026/11/06 07:18:41 INFO Vacuumed table table=pending_closures20142026/11/06 07:18:41 INFO Vacuumed table table=pending_objects20152026/11/06 07:18:41 INFO Vacuumed table table=multipart_uploads20162026/11/06 07:18:41 INFO Vacuumed table table=closures20172026/11/06 07:18:41 WARN Request failed, retrying attempt=2 backoff=184.048862ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present20182026/11/06 07:18:41 INFO Vacuumed table table=objects20192026/11/06 07:18:41 WARN readiness check failed error="closed pool"2020--- PASS: TestService_readinessHandler (6.13s)2021=== CONT TestService_AuthMiddleware_OIDC/valid_OIDC_token2022=== CONT TestService_AuthMiddleware_OIDC/malformed_token_rejected20232026/11/06 07:18:41 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]2024=== CONT TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2025=== CONT TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected20262026/11/06 07:18:41 WARN Authentication failed token_preview=eyJhbGciOi...7xCUXi61NQ token_length=701 oidc_error="no rule matched: claim \"repository_owner\" value [otherorg] not in allowed patterns [myorg]" oidc_provider=test tried_providers=[test]2027=== CONT TestService_RequireScope_OIDC/builder_may_write2028=== CONT TestService_RequireScope_OIDC/reader_may_read2029=== CONT TestService_RequireScope_OIDC/empty_netrc_password_may_not_read2030=== CONT TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read20312026/11/06 07:18:41 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]2032--- PASS: TestService_AuthMiddleware_OIDC (7.07s)2033 --- PASS: TestService_AuthMiddleware_OIDC/valid_OIDC_token (0.00s)2034 --- PASS: TestService_AuthMiddleware_OIDC/malformed_token_rejected (0.00s)2035 --- PASS: TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured (0.00s)2036 --- PASS: TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected (0.01s)2037=== CONT TestService_RequireScope_OIDC/anonymous_may_not_read2038=== CONT TestService_RequireScope_OIDC/writer_implies_read2039=== CONT TestService_RequireScope_OIDC/static_token_may_admin_with_netrc2040=== CONT TestService_RequireScope_OIDC/reader_may_not_write2041=== CONT TestService_RequireScope_OIDC/static_token_may_write2042=== CONT TestService_RequireScope_OIDC/static_token_may_admin2043=== CONT TestService_RequireScope_OIDC/ops_may_admin2044=== CONT TestService_RequireScope_OIDC/ops_may_not_write2045=== CONT TestService_RequireScope_OIDC/builder_may_not_admin2046=== CONT TestService_RequireScope_OIDC/reader_may_read_with_netrc2047--- PASS: TestService_RequireScope_OIDC (7.44s)2048 --- PASS: TestService_RequireScope_OIDC/builder_may_write (0.00s)2049 --- PASS: TestService_RequireScope_OIDC/reader_may_read (0.00s)2050 --- PASS: TestService_RequireScope_OIDC/empty_netrc_password_may_not_read (0.00s)2051 --- PASS: TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read (0.00s)2052 --- PASS: TestService_RequireScope_OIDC/anonymous_may_not_read (0.00s)2053 --- PASS: TestService_RequireScope_OIDC/writer_implies_read (0.00s)2054 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin_with_netrc (0.00s)2055 --- PASS: TestService_RequireScope_OIDC/reader_may_not_write (0.00s)2056 --- PASS: TestService_RequireScope_OIDC/static_token_may_write (0.00s)2057 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin (0.00s)2058 --- PASS: TestService_RequireScope_OIDC/ops_may_admin (0.00s)2059 --- PASS: TestService_RequireScope_OIDC/ops_may_not_write (0.00s)2060 --- PASS: TestService_RequireScope_OIDC/builder_may_not_admin (0.00s)2061 --- PASS: TestService_RequireScope_OIDC/reader_may_read_with_netrc (0.00s)20622026/11/06 07:18:41 WARN Request failed, retrying attempt=3 backoff=394.978354ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present20632026/11/06 07:18:42 WARN Request failed, retrying attempt=4 backoff=854.752633ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present20642026/11/06 07:18:42 INFO Aborted multipart uploads count=0 kept=020652026/11/06 07:18:42 WARN Force mode enabled - objects will be deleted immediately without grace period20662026/11/06 07:18:42 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=020672026/11/06 07:18:42 INFO Vacuumed table table=pending_closures20682026/11/06 07:18:42 INFO Vacuumed table table=pending_objects20692026/11/06 07:18:42 INFO Vacuumed table table=multipart_uploads20702026/11/06 07:18:42 INFO Vacuumed table table=closures20712026/11/06 07:18:42 INFO Vacuumed table table=objects20722026/11/06 07:18:42 INFO Aborted multipart uploads count=0 kept=020732026/11/06 07:18:42 WARN Force mode enabled - objects will be deleted immediately without grace period20742026/11/06 07:18:42 INFO Received uploads request method=POST path=/api/pending_closures20752026/11/06 07:18:42 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=020762026/11/06 07:18:42 INFO Vacuumed table table=pending_closures20772026/11/06 07:18:42 INFO Vacuumed table table=pending_objects20782026/11/06 07:18:42 INFO Vacuumed table table=multipart_uploads20792026/11/06 07:18:42 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=020802026/11/06 07:18:42 INFO Vacuumed table table=closures2081=== NAME TestClientIntegration2082 client_integration_test.go:370: Objects in database after GC:2083 client_integration_test.go:370: Successfully deleted all objects with GC --force20842026/11/06 07:18:42 INFO Vacuumed table table=objects2085--- PASS: TestSweepSkipsRowsLockedByPush (6.83s)2086--- PASS: TestClientIntegration (10.48s)20872026/11/06 07:18:43 INFO Aborted multipart uploads count=0 kept=020882026/11/06 07:18:43 WARN Force mode enabled - objects will be deleted immediately without grace period20892026/11/06 07:18:43 ERROR failed to remove object object=nar/dddddddddddddddddddddddddddddddddddddddddddddddddddd.nar.zst error="Access Denied."20902026/11/06 07:18:43 ERROR failed to remove object object=dddddddddddddddddddddddddddddddd.narinfo error="Access Denied."2091--- PASS: TestFailedS3DeleteKeepsTombstone (6.79s)20922026/11/06 07:18:43 INFO Received uploads request method=POST path=/api/pending_closures2093--- PASS: TestTombstonedObjectOfferedWithoutWaiting (6.69s)20942026/11/06 07:18:43 WARN Request failed, retrying attempt=5 backoff=1.660009682s error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present2095--- PASS: TestDeleteClosuresRacingPins (12.17s)20962026/11/06 07:18:43 INFO Received uploads request method=POST path=/api/pending_closures2097=== NAME TestClientCADerivations2098 client_ca_test.go:136: Built CA derivation: /private/var/tb/4/scratch/6ba07dd8cd494155/build/TestClientCADerivations2977892668/001/store/6qpp6izhryvr4fznyypcd5l69a757as3-ca-test2099 client_ca_test.go:139: Found 1 dependencies (including self)21002026/11/06 07:18:43 INFO Received uploads request method=POST path=/api/pending_closures2101=== NAME TestOrphanedObjectsGCStressTest2102 orphaned_objects_gc_test.go:422: Created 10 active closures, 5 to-delete closures, 20 orphaned chains21032026/11/06 07:18:44 INFO Received push request method=POST path=/api/pushes21042026/11/06 07:18:44 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)2105 orphaned_objects_gc_test.go:440: Marked 210 objects for deletion21062026/11/06 07:18:44 INFO Uploading 6qpp6izhryvr4fznyypcd5l69a757as3-ca-test (144B)21072026/11/06 07:18:44 WARN Failed to register uploaded object key=nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst error="server returned 404: 404 page not found\n"21082026/11/06 07:18:44 WARN Failed to register uploaded object key=6qpp6izhryvr4fznyypcd5l69a757as3.ls error="server returned 404: 404 page not found\n"21092026/11/06 07:18:44 WARN Failed to register uploaded object key=log/d3168sj9fp9vl8fs736ban2pqajclh49-ca-test.drv error="server returned 404: 404 page not found\n"21102026/11/06 07:18:44 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign21112026/11/06 07:18:44 INFO Signed narinfos id=1 count=121122026/11/06 07:18:44 INFO Uploading 1 narinfos21132026/11/06 07:18:44 INFO Received complete push request method=POST path=/api/pushes/1/complete21142026/11/06 07:18:44 WARN Failed to register uploaded object key=6qpp6izhryvr4fznyypcd5l69a757as3.narinfo error="server returned 404: 404 page not found\n"21152026/11/06 07:18:44 INFO Received uploads request method=POST path=/api/pending_closures21162026/11/06 07:18:44 INFO Completed push id=1 objects=4 duration=21.72625ms21172026/11/06 07:18:44 INFO Upload complete. (304ms)2118=== NAME TestClientCADerivations2119 client_ca_test.go:180: Narinfo contains CA field: StorePath: /private/var/tb/4/scratch/6ba07dd8cd494155/build/TestClientCADerivations2977892668/001/store/6qpp6izhryvr4fznyypcd5l69a757as3-ca-test2120 URL: nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst2121 Compression: zstd2122 NarHash: sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n2123 NarSize: 1442124 References: 2125 Deriver: /private/var/tb/4/scratch/6ba07dd8cd494155/build/TestClientCADerivations2977892668/001/store/d3168sj9fp9vl8fs736ban2pqajclh49-ca-test.drv2126 CA: fixed:r:sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n2127 client_ca_test.go:185: Checking for realisation files in S3...2128 client_ca_test.go:207: No realisation files uploaded - this is expected for locally built CA derivations2129 client_ca_test.go:208: Locally built CA derivations don't have DrvOutput IDs until they're substituted from a cache2130 client_ca_test.go:258: nix copy output: error: binary cache 's3://bucket90?endpoint=http://localhost:55153®ion=eu-west-1' is for Nix stores with prefix '/nix/store', not '/private/var/tb/4/scratch/6ba07dd8cd494155/build/TestClientCADerivations2977892668/001/store'2131 client_ca_test.go:259: nix copy failed (might be expected with isolated stores): exit status 12132--- PASS: TestClientCADerivations (7.94s)21332026/11/06 07:18:44 INFO Received uploads request method=POST path=/api/pending_closures21342026/11/06 07:18:44 INFO Received uploads request method=POST path=/api/pending_closures21352026/11/06 07:18:44 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-config21362026/11/06 07:18:45 WARN Request failed, retrying attempt=2 backoff=206.002502ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21372026/11/06 07:18:45 INFO Received complete multipart upload request method=POST path=/api/multipart/complete21382026/11/06 07:18:45 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000100000000000000000000.nar.zst upload_id=NjA1YThjNTgtZTllYS00MjkyLWFhMDctYjhhMGIxNjQxMjliLmFlM2EwNTM4LTNkMzYtNGY4Yy1iYWRhLTM4NThlZTY0MWEyNXgxNzkzOTQ5NTIzNjU1MDQyMDAw parts=1021392026/11/06 07:18:45 INFO Received uploads request method=POST path=/api/pending_closures21402026/11/06 07:18:45 WARN Request failed, retrying attempt=3 backoff=369.754352ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21412026/11/06 07:18:45 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete21422026/11/06 07:18:45 INFO Completed upload id=1 objects=3 duration=16.002084ms21432026/11/06 07:18:45 INFO Received complete multipart upload request method=POST path=/api/multipart/complete21442026/11/06 07:18:45 WARN Request failed, retrying attempt=4 backoff=831.226274ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21452026/11/06 07:18:45 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000500000000000000000000.nar.zst upload_id=NjA1YThjNTgtZTllYS00MjkyLWFhMDctYjhhMGIxNjQxMjliLjU2NjVmMGM4LWJjZDYtNDJhOS05ZTQ4LWFiZWRmNDEwNzMwNngxNzkzOTQ5NTIzOTQ0Nzg5MDAw parts=1021462026/11/06 07:18:45 INFO Received uploads request method=POST path=/api/pending_closures21472026/11/06 07:18:45 INFO Object in database but missing from S3 key=nar/dadb44fdadb44fdadb44fdadb44f000100000000000000000000.nar.zst21482026/11/06 07:18:45 WARN Narinfo references a NAR missing from S3, will re-upload narinfo=dadb44fdadb44fdadb44fdadb44f0001.narinfo21492026/11/06 07:18:45 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete21502026/11/06 07:18:45 INFO Completed upload id=1 objects=3 duration=13.418958ms2151--- PASS: TestPendingClosureWriteTimeout (0.08s)2152 --- PASS: TestPendingClosureWriteTimeout/empty (0.00s)2153 --- PASS: TestPendingClosureWriteTimeout/670k_objects (0.00s)2154 --- PASS: TestPendingClosureWriteTimeout/400_objects (0.00s)2155 --- PASS: TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline (7.82s)21562026/11/06 07:18:46 INFO Received complete multipart upload request method=POST path=/api/multipart/complete21572026/11/06 07:18:46 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000400000000000000000000.nar.zst upload_id=NjA1YThjNTgtZTllYS00MjkyLWFhMDctYjhhMGIxNjQxMjliLjkwZjgyNzU0LWNkM2YtNDkxZC04NTFjLTRiMzNiZDVmNjg4YXgxNzkzOTQ5NTI0MjcwMzQzMDAw parts=1021582026/11/06 07:18:46 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete21592026/11/06 07:18:46 INFO Completed upload id=1 objects=3 duration=32.502208ms21602026/11/06 07:18:46 INFO Received uploads request method=POST path=/api/pending_closures21612026/11/06 07:18:46 INFO Received uploads request method=POST path=/api/pending_closures21622026/11/06 07:18:46 INFO Object in database but missing from S3 key=nar/dadb44fdadb44fdadb44fdadb44f000500000000000000000000.nar.zst21632026/11/06 07:18:46 WARN Found objects in DB but missing from S3, will re-upload count=121642026/11/06 07:18:46 WARN Request failed, retrying attempt=5 backoff=1.49201896s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21652026/11/06 07:18:46 INFO Received complete multipart upload request method=POST path=/api/multipart/complete2166--- PASS: TestPresentNotReportedWhileGCDeletesClosure (0.00s)2167 --- PASS: TestPresentNotReportedWhileGCDeletesClosure/fresh (7.11s)2168 --- PASS: TestPresentNotReportedWhileGCDeletesClosure/stale (7.55s)21692026/11/06 07:18:46 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000300000000000000000000.nar.zst upload_id=NjA1YThjNTgtZTllYS00MjkyLWFhMDctYjhhMGIxNjQxMjliLjhjODlmZjQ5LTdkODAtNDg4Yi04ZDllLTExZmI2NDI0MjUzY3gxNzkzOTQ5NTI0NTMwNDU0MDAw parts=1021702026/11/06 07:18:46 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete21712026/11/06 07:18:46 INFO Completed upload id=1 objects=3 duration=15.005125ms21722026/11/06 07:18:46 INFO Received uploads request method=POST path=/api/pending_closures21732026/11/06 07:18:46 INFO Received complete multipart upload request method=POST path=/api/multipart/complete21742026/11/06 07:18:46 INFO Aborted multipart uploads count=0 kept=021752026/11/06 07:18:46 WARN Force mode enabled - objects will be deleted immediately without grace period21762026-11-06 07:18:46.947 UTC [87068] ERROR: canceling statement due to user request21772026-11-06 07:18:46.947 UTC [87068] STATEMENT: -- name: MarkStaleObjects :execrows2178 WITH RECURSIVE ct AS (2179 SELECT timezone('UTC', now()) AS now2180 ),2181 closure_reach AS (2182 -- Start with all closure keys2183 SELECT o.key, o.refs2184 FROM objects o2185 INNER JOIN closures c ON o.key = c.key2186 UNION2187 -- Recursively add all referenced objects2188 SELECT o.key, o.refs2189 FROM objects o2190 INNER JOIN closure_reach cr ON o.key = ANY(cr.refs)2191 ),2192 reachable_objects AS (2193 SELECT DISTINCT key FROM closure_reach2194 ),2195 stale_objects AS (2196 SELECT o.key2197 FROM objects AS o, ct2198 WHERE2199 NOT EXISTS (2200 SELECT 12201 FROM reachable_objects ro2202 WHERE ro.key = o.key2203 )2204 AND NOT EXISTS (2205 SELECT 12206 FROM pending_objects AS po2207 WHERE po.key = o.key2208 )2209 AND o.deleted_at IS NULL -- Only mark fresh objects2210 ORDER BY o.key COLLATE "C" -- lock in key order, like commit_pending_closure2211 FOR UPDATE2212 )2213 UPDATE objects2214 SET2215 deleted_at = ct.now,2216 first_deleted_at = COALESCE(first_deleted_at, ct.now)2217 FROM stale_objects, ct2218 WHERE objects.key = stale_objects.key2219 22202026/11/06 07:18:47 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000200000000000000000000.nar.zst upload_id=NjA1YThjNTgtZTllYS00MjkyLWFhMDctYjhhMGIxNjQxMjliLmEzYzhkZjA2LTIxMWYtNDNlMi1iMTlmLThlYWViZTNjYTMxMXgxNzkzOTQ5NTI0ODk2NjYxMDAw parts=1022212026/11/06 07:18:47 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete22222026/11/06 07:18:47 INFO Completed upload id=1 objects=3 duration=12.919042ms22232026/11/06 07:18:47 INFO Received uploads request method=POST path=/api/pending_closures22242026/11/06 07:18:47 INFO Aborted multipart uploads count=0 kept=022252026/11/06 07:18:47 WARN Force mode enabled - objects will be deleted immediately without grace period22262026/11/06 07:18:47 ERROR failed to remove object object=nar/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa.nar.zst error="Post \"http://localhost:55153/bucket101/?delete=\": context canceled"2227--- PASS: TestGCEndsOnShutdown (0.00s)2228 --- PASS: TestGCEndsOnShutdown/before_the_run (7.15s)2229 --- PASS: TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark (7.51s)2230 --- PASS: TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete (7.56s)22312026/11/06 07:18:47 INFO Received complete multipart upload request method=POST path=/api/multipart/complete22322026/11/06 07:18:47 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"22332026/11/06 07:18:47 WARN Request failed, retrying attempt=1 backoff=100ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22342026/11/06 07:18:47 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f100400000000000000000000.nar.zst upload_id=NjA1YThjNTgtZTllYS00MjkyLWFhMDctYjhhMGIxNjQxMjliLjUyMjA0MjFlLTY4ODItNDJjZi1iMjUxLTNiZWZmYTcwMWUxMXgxNzkzOTQ5NTI2MzM0NjM3MDAw parts=1022352026/11/06 07:18:47 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete22362026/11/06 07:18:48 INFO Completed upload id=2 objects=3 duration=1.092625ms22372026/11/06 07:18:48 WARN Request failed, retrying attempt=2 backoff=191.897027ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22382026/11/06 07:18:48 INFO Received uploads request method=POST path=/api/pending_closures22392026/11/06 07:18:48 INFO Aborted multipart uploads count=0 kept=022402026/11/06 07:18:48 WARN Force mode enabled - objects will be deleted immediately without grace period22412026/11/06 07:18:48 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"22422026/11/06 07:18:48 INFO Received complete multipart upload request method=POST path=/api/multipart/complete22432026/11/06 07:18:48 WARN Request failed, retrying attempt=3 backoff=381.802433ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22442026/11/06 07:18:48 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"22452026/11/06 07:18:48 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f100300000000000000000000.nar.zst upload_id=NjA1YThjNTgtZTllYS00MjkyLWFhMDctYjhhMGIxNjQxMjliLmE1MTUyZTFmLWQzZDQtNGE3My04M2Q2LTJiNWNmZTkyM2E0ZXgxNzkzOTQ5NTI2NzEyMDI5MDAw parts=1022462026/11/06 07:18:48 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete22472026/11/06 07:18:48 INFO Completed upload id=2 objects=3 duration=478.041µs22482026/11/06 07:18:48 INFO Received uploads request method=POST path=/api/pending_closures22492026/11/06 07:18:48 INFO Object in database but missing from S3 key=nar/dadb44fdadb44fdadb44fdadb44f000400000000000000000000.nar.zst22502026/11/06 07:18:48 WARN Narinfo references a NAR missing from S3, will re-upload narinfo=dadb44fdadb44fdadb44fdadb44f0004.narinfo22512026/11/06 07:18:48 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=022522026/11/06 07:18:48 INFO Vacuumed table table=pending_closures22532026/11/06 07:18:48 INFO Vacuumed table table=pending_objects22542026/11/06 07:18:48 INFO Vacuumed table table=multipart_uploads22552026/11/06 07:18:48 INFO Vacuumed table table=closures22562026/11/06 07:18:48 INFO Vacuumed table table=objects22572026/11/06 07:18:48 INFO Received uploads request method=POST path=/api/pending_closures22582026/11/06 07:18:48 INFO Aborted multipart uploads count=0 kept=022592026/11/06 07:18:48 WARN Force mode enabled - objects will be deleted immediately without grace period22602026/11/06 07:18: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=022612026/11/06 07:18:48 INFO Vacuumed table table=pending_closures22622026/11/06 07:18:48 INFO Vacuumed table table=pending_objects22632026/11/06 07:18:48 INFO Vacuumed table table=multipart_uploads22642026/11/06 07:18:48 INFO Vacuumed table table=closures22652026/11/06 07:18:48 INFO Vacuumed table table=objects2266--- PASS: TestForceGCDuringPushOffersSweptObject (0.00s)2267 --- PASS: TestForceGCDuringPushOffersSweptObject/before_pending_rows (7.07s)2268 --- PASS: TestForceGCDuringPushOffersSweptObject/after_presence_check (7.07s)22692026/11/06 07:18:48 INFO Received uploads request method=POST path=/api/pending_closures22702026/11/06 07:18:48 INFO Object in database but missing from S3 key=nar/dadb44fdadb44fdadb44fdadb44f000300000000000000000000.nar.zst22712026/11/06 07:18:48 WARN Narinfo references a NAR missing from S3, will re-upload narinfo=dadb44fdadb44fdadb44fdadb44f0003.narinfo22722026/11/06 07:18:48 WARN Request failed, retrying attempt=4 backoff=777.598587ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config2273--- PASS: TestService_verifyS3ReuploadsStaleNarinfo (0.08s)2274 --- PASS: TestService_verifyS3ReuploadsStaleNarinfo/lost,_other_NAR_pushed (9.12s)2275 --- PASS: TestService_verifyS3ReuploadsStaleNarinfo/lost,_same_NAR_pushed (9.64s)2276 --- PASS: TestService_verifyS3ReuploadsStaleNarinfo/intact,_other_NAR_pushed (9.44s)2277 --- PASS: TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost,_second_pushed (11.31s)2278 --- PASS: TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost (11.35s)22792026/11/06 07:18:49 WARN Request failed, retrying attempt=5 backoff=1.696690221s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22802026/11/06 07:18:51 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures22812026/11/06 07:18:51 WARN Request failed, retrying attempt=2 backoff=200.63768ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures22822026/11/06 07:18:51 WARN Request failed, retrying attempt=3 backoff=361.55398ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures22832026/11/06 07:18:51 WARN Request failed, retrying attempt=4 backoff=817.279178ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures22842026/11/06 07:18:52 WARN Request failed, retrying attempt=5 backoff=1.62465624s error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures2285--- PASS: TestClientErrorHandling (0.02s)2286 --- PASS: TestClientErrorHandling/InvalidStorePath (7.48s)2287 --- PASS: TestClientErrorHandling/InvalidAuthToken (7.16s)2288 --- PASS: TestClientErrorHandling/ServerNotAvailable (13.59s)2289=== NAME TestOrphanedObjectsGCStressTest2290 orphaned_objects_gc_test.go:503: Stress test completed successfully:2291 orphaned_objects_gc_test.go:504: - Active objects preserved: 202292 orphaned_objects_gc_test.go:505: - Objects deleted: 2102293 orphaned_objects_gc_test.go:506: - Total GC'd: 2102294--- PASS: TestOrphanedObjectsGCStressTest (33.88s)2295PASS2296{"timestamp":"2026-11-06T07:18:58.408189Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:55645","error_kind":"io_error","error":"Cancelled","result":"transport_error","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":2561,"threadName":"rustfs-worker","threadId":"ThreadId(2)"}2297{"timestamp":"2026-11-06T07:18:58.408609Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:55680","error_kind":"io_error","error":"Cancelled","result":"transport_error","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":2561,"threadName":"rustfs-worker","threadId":"ThreadId(7)"}2298{"timestamp":"2026-11-06T07:18:58.409537Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:55531","error_kind":"io_error","error":"Cancelled","result":"transport_error","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":2561,"threadName":"rustfs-worker","threadId":"ThreadId(7)"}2299{"timestamp":"2026-11-06T07:18:58.409838Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:55636","error_kind":"io_error","error":"Cancelled","result":"transport_error","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":2561,"threadName":"rustfs-worker","threadId":"ThreadId(7)"}2300{"timestamp":"2026-11-06T07:18:58.410218Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:55236","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)"}23012026-11-06 07:18:58.596 UTC [85682] LOG: received smart shutdown request23022026-11-06 07:18:58.598 UTC [85682] LOG: background worker "logical replication launcher" (PID 85692) exited with exit code 123032026-11-06 07:18:58.603 UTC [85687] LOG: shutting down23042026-11-06 07:18:58.603 UTC [85687] LOG: checkpoint starting: shutdown immediate23052026-11-06 07:19:00.256 UTC [85687] LOG: checkpoint complete: wrote 11301 buffers (69.0%), wrote 4 SLRU buffers; 0 WAL file(s) added, 0 removed, 32 recycled; write=0.887 s, sync=0.710 s, total=1.654 s; sync files=35724, longest=0.011 s, average=0.001 s; distance=525283 kB, estimate=525283 kB; lsn=0/21885CC8, redo lsn=0/21885CC823062026-11-06 07:19:00.279 UTC [85682] LOG: database system is shut down2307Running OIDC tests...2308=== RUN TestAudienceForIssuer2309=== PAUSE TestAudienceForIssuer2310=== RUN TestGlobMatch2311=== PAUSE TestGlobMatch2312=== RUN TestValidateToken_ValidToken2313=== PAUSE TestValidateToken_ValidToken2314=== RUN TestValidateToken_WrongAudience2315=== PAUSE TestValidateToken_WrongAudience2316=== RUN TestValidateToken_Expired2317=== PAUSE TestValidateToken_Expired2318=== RUN TestValidateToken_BoundClaimsMismatch2319=== PAUSE TestValidateToken_BoundClaimsMismatch2320=== RUN TestValidateToken_BoundSubjectMismatch2321=== PAUSE TestValidateToken_BoundSubjectMismatch2322=== RUN TestValidateToken_MultipleProviders2323=== PAUSE TestValidateToken_MultipleProviders2324=== RUN TestValidateToken_NoMatchingProvider2325=== PAUSE TestValidateToken_NoMatchingProvider2326=== RUN TestValidateToken_KubernetesServiceAccount2327=== PAUSE TestValidateToken_KubernetesServiceAccount2328=== RUN TestNewValidator_KubernetesRequiresCA2329=== PAUSE TestNewValidator_KubernetesRequiresCA2330=== RUN TestValidateToken_KubernetesIssuerFromOwnToken2331=== PAUSE TestValidateToken_KubernetesIssuerFromOwnToken2332=== RUN TestPins_ReservedForMatchingRule2333=== PAUSE TestPins_ReservedForMatchingRule2334=== RUN TestPins_TopLevelShorthand2335=== PAUSE TestPins_TopLevelShorthand2336=== RUN TestPins_ConfigValidation2337=== PAUSE TestPins_ConfigValidation2338=== RUN TestScopes_LegacyProviderDefaultsToWrite2339=== PAUSE TestScopes_LegacyProviderDefaultsToWrite2340=== RUN TestScopes_Rules2341=== PAUSE TestScopes_Rules2342=== RUN TestScopes_ConfigValidation2343=== PAUSE TestScopes_ConfigValidation2344=== CONT TestAudienceForIssuer2345=== CONT TestValidateToken_KubernetesServiceAccount2346=== CONT TestValidateToken_ValidToken2347--- PASS: TestAudienceForIssuer (0.00s)2348=== CONT TestValidateToken_NoMatchingProvider2349=== CONT TestValidateToken_MultipleProviders2350=== CONT TestValidateToken_BoundSubjectMismatch2351=== CONT TestValidateToken_BoundClaimsMismatch2352=== CONT TestValidateToken_Expired2353=== CONT TestGlobMatch2354=== RUN TestGlobMatch/foo_foo2355=== PAUSE TestGlobMatch/foo_foo2356=== RUN TestGlobMatch/foo_bar2357=== PAUSE TestGlobMatch/foo_bar2358=== RUN TestGlobMatch/*_2359=== PAUSE TestGlobMatch/*_2360=== RUN TestGlobMatch/*_anything2361=== PAUSE TestGlobMatch/*_anything2362=== RUN TestGlobMatch/foo*_foo2363=== CONT TestPins_ConfigValidation2364=== CONT TestScopes_ConfigValidation2365=== CONT TestScopes_Rules2366=== CONT TestScopes_LegacyProviderDefaultsToWrite2367=== CONT TestValidateToken_WrongAudience2368=== CONT TestPins_ReservedForMatchingRule2369--- PASS: TestPins_ConfigValidation (0.00s)2370--- PASS: TestScopes_ConfigValidation (0.00s)2371=== CONT TestPins_TopLevelShorthand2372=== CONT TestValidateToken_KubernetesIssuerFromOwnToken2373=== CONT TestNewValidator_KubernetesRequiresCA2374=== PAUSE TestGlobMatch/foo*_foo2375=== RUN TestGlobMatch/foo*_foobar2376=== PAUSE TestGlobMatch/foo*_foobar2377=== RUN TestGlobMatch/foo*_bar2378=== PAUSE TestGlobMatch/foo*_bar2379=== RUN TestGlobMatch/*bar_bar2380=== PAUSE TestGlobMatch/*bar_bar2381=== RUN TestGlobMatch/*bar_foobar2382=== PAUSE TestGlobMatch/*bar_foobar2383=== RUN TestGlobMatch/*bar_foo2384=== PAUSE TestGlobMatch/*bar_foo2385=== RUN TestGlobMatch/foo*bar_foobar2386=== PAUSE TestGlobMatch/foo*bar_foobar2387=== RUN TestGlobMatch/foo*bar_foo123bar2388=== PAUSE TestGlobMatch/foo*bar_foo123bar2389=== RUN TestGlobMatch/foo*bar_foobarbaz2390=== PAUSE TestGlobMatch/foo*bar_foobarbaz2391=== RUN TestGlobMatch/*/*_foo/bar2392=== PAUSE TestGlobMatch/*/*_foo/bar2393=== RUN TestGlobMatch/*/*_foo2394=== PAUSE TestGlobMatch/*/*_foo2395=== RUN TestGlobMatch/refs/heads/*_refs/heads/main2396=== PAUSE TestGlobMatch/refs/heads/*_refs/heads/main2397=== RUN TestGlobMatch/refs/heads/*_refs/tags/v1.02398=== PAUSE TestGlobMatch/refs/heads/*_refs/tags/v1.02399=== RUN TestGlobMatch/refs/*/main_refs/heads/main2400=== PAUSE TestGlobMatch/refs/*/main_refs/heads/main2401=== RUN TestGlobMatch/fo?_foo2402=== PAUSE TestGlobMatch/fo?_foo2403=== RUN TestGlobMatch/fo?_fo2404=== PAUSE TestGlobMatch/fo?_fo2405=== RUN TestGlobMatch/fo?_fooo2406=== PAUSE TestGlobMatch/fo?_fooo2407=== RUN TestGlobMatch/?oo_foo2408=== PAUSE TestGlobMatch/?oo_foo2409=== RUN TestGlobMatch/?oo_boo2410=== PAUSE TestGlobMatch/?oo_boo2411=== RUN TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2412=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2413=== RUN TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2414=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2415=== CONT TestGlobMatch/foo_foo24162026/11/06 07:19:01 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:55703/oidc2417=== CONT TestGlobMatch/*/*_foo/bar24182026/11/06 07:19:01 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:55705/oidc2419=== CONT TestGlobMatch/*/*_foo2420=== CONT TestGlobMatch/?oo_foo2421=== CONT TestGlobMatch/fo?_fooo2422=== CONT TestGlobMatch/foo*_foo2423=== CONT TestGlobMatch/*_2424=== CONT TestGlobMatch/foo*_bar2425=== CONT TestGlobMatch/*_anything2426=== CONT TestGlobMatch/foo*_foobar2427=== CONT TestGlobMatch/foo*bar_foobar2428=== CONT TestGlobMatch/*bar_foo2429=== CONT TestGlobMatch/foo*bar_foobarbaz2430=== CONT TestGlobMatch/*bar_foobar2431=== CONT TestGlobMatch/foo*bar_foo123bar2432=== CONT TestGlobMatch/foo_bar2433=== CONT TestGlobMatch/fo?_fo2434=== CONT TestGlobMatch/fo?_foo2435=== CONT TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2436=== CONT TestGlobMatch/refs/*/main_refs/heads/main2437=== CONT TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2438=== CONT TestGlobMatch/refs/heads/*_refs/tags/v1.02439=== CONT TestGlobMatch/refs/heads/*_refs/heads/main2440=== CONT TestGlobMatch/?oo_boo2441=== CONT TestGlobMatch/*bar_bar2442--- PASS: TestGlobMatch (0.04s)2443 --- PASS: TestGlobMatch/foo_foo (0.00s)2444 --- PASS: TestGlobMatch/*/*_foo/bar (0.00s)2445 --- PASS: TestGlobMatch/*/*_foo (0.00s)2446 --- PASS: TestGlobMatch/?oo_foo (0.00s)2447 --- PASS: TestGlobMatch/fo?_fooo (0.00s)2448 --- PASS: TestGlobMatch/foo*_foo (0.00s)2449 --- PASS: TestGlobMatch/*_ (0.00s)2450 --- PASS: TestGlobMatch/foo*_bar (0.00s)2451 --- PASS: TestGlobMatch/*_anything (0.00s)2452 --- PASS: TestGlobMatch/foo*_foobar (0.00s)2453 --- PASS: TestGlobMatch/foo*bar_foobar (0.00s)2454 --- PASS: TestGlobMatch/*bar_foo (0.00s)2455 --- PASS: TestGlobMatch/foo*bar_foobarbaz (0.00s)2456 --- PASS: TestGlobMatch/*bar_foobar (0.00s)2457 --- PASS: TestGlobMatch/foo*bar_foo123bar (0.00s)2458 --- PASS: TestGlobMatch/foo_bar (0.00s)2459 --- PASS: TestGlobMatch/fo?_fo (0.00s)2460 --- PASS: TestGlobMatch/fo?_foo (0.00s)2461 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main (0.00s)2462 --- PASS: TestGlobMatch/refs/*/main_refs/heads/main (0.00s)2463 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main (0.00s)2464 --- PASS: TestGlobMatch/refs/heads/*_refs/tags/v1.0 (0.00s)2465 --- PASS: TestGlobMatch/refs/heads/*_refs/heads/main (0.00s)2466 --- PASS: TestGlobMatch/?oo_boo (0.00s)2467 --- PASS: TestGlobMatch/*bar_bar (0.00s)2468--- PASS: TestValidateToken_BoundSubjectMismatch (0.04s)2469--- PASS: TestValidateToken_ValidToken (0.04s)24702026/11/06 07:19:01 http: TLS handshake error from 127.0.0.1:55708: read tcp 127.0.0.1:55707->127.0.0.1:55708: use of closed network connection2471--- PASS: TestNewValidator_KubernetesRequiresCA (0.04s)24722026/11/06 07:19:01 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:55709/oidc2473--- PASS: TestValidateToken_Expired (0.07s)24742026/11/06 07:19:01 INFO OIDC provider initialized name=kubernetes issuer=https://127.0.0.1:557112475--- PASS: TestValidateToken_KubernetesServiceAccount (0.07s)24762026/11/06 07:19:01 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:55713/oidc2477--- PASS: TestPins_TopLevelShorthand (0.07s)24782026/11/06 07:19:01 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:55715/oidc24792026/11/06 07:19:01 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:55717/oidc24802026/11/06 07:19:01 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:55719/oidc2481--- PASS: TestPins_ReservedForMatchingRule (0.08s)2482--- PASS: TestScopes_Rules (0.09s)24832026/11/06 07:19:01 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:55702/oidc2484--- PASS: TestScopes_LegacyProviderDefaultsToWrite (0.09s)24852026/11/06 07:19:01 INFO OIDC provider initialized name=provider2 issuer=http://127.0.0.1:55721/oidc24862026/11/06 07:19:01 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:55724/oidc2487--- PASS: TestValidateToken_MultipleProviders (0.09s)2488--- PASS: TestValidateToken_BoundClaimsMismatch (0.09s)24892026/11/06 07:19:01 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:55726/oidc2490--- PASS: TestValidateToken_NoMatchingProvider (0.11s)24912026/11/06 07:19:01 INFO OIDC provider initialized name=kubernetes issuer=https://oidc.eks.invalid/id/ABC1232492--- PASS: TestValidateToken_KubernetesIssuerFromOwnToken (0.10s)24932026/11/06 07:19:01 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:55731/oidc2494--- PASS: TestValidateToken_WrongAudience (0.13s)2495PASS2496Running hook tests...2497=== RUN TestSendPathsEmpty2498=== PAUSE TestSendPathsEmpty2499=== RUN TestQueueEnqueueAndFetch2500=== PAUSE TestQueueEnqueueAndFetch2501=== RUN TestQueueDeduplication2502=== PAUSE TestQueueDeduplication2503=== RUN TestQueueRemove2504=== PAUSE TestQueueRemove2505=== RUN TestQueueFetchBatchLimit2506=== PAUSE TestQueueFetchBatchLimit2507=== RUN TestQueueRetryMovesToBack2508=== PAUSE TestQueueRetryMovesToBack2509=== RUN TestQueueFetchRemoveLifecycle2510=== PAUSE TestQueueFetchRemoveLifecycle2511=== RUN TestQueueConcurrentWriters2512=== PAUSE TestQueueConcurrentWriters2513=== RUN TestQueueRemoveLargeClosure2514=== PAUSE TestQueueRemoveLargeClosure2515=== RUN TestServerClientIntegration2516--- PASS: TestServerClientIntegration (0.00s)2517=== RUN TestServerQueueError25182026/11/06 07:19:01 ERROR Failed to queue paths error="permission denied" count=12519--- PASS: TestServerQueueError (0.00s)2520=== RUN TestGetListenerSocketActivation2521 server_test.go:145: systemd socket activation does not exist on darwin2522--- SKIP: TestGetListenerSocketActivation (0.00s)2523=== RUN TestServerStalledClientDoesNotBlockShutdown2524=== PAUSE TestServerStalledClientDoesNotBlockShutdown2525=== RUN TestServerBacksOffOnAcceptErrors2526=== PAUSE TestServerBacksOffOnAcceptErrors2527=== RUN TestDrainIsolatesPoisonPath2528=== PAUSE TestDrainIsolatesPoisonPath2529=== RUN TestRunNotBlockedByPoisonHead2530=== PAUSE TestRunNotBlockedByPoisonHead2531=== RUN TestDrainGivesUpWhenServerDown2532=== PAUSE TestDrainGivesUpWhenServerDown2533=== RUN TestFailedPathPrunedByLaterClosure2534=== PAUSE TestFailedPathPrunedByLaterClosure2535=== RUN TestWorkerUploadsAndRemoves2536=== PAUSE TestWorkerUploadsAndRemoves2537=== RUN TestWorkerSkipsGCdPaths2538=== PAUSE TestWorkerSkipsGCdPaths2539=== RUN TestWorkerPrunesClosureDeps2540=== PAUSE TestWorkerPrunesClosureDeps2541=== RUN TestDrainTimeout2542=== PAUSE TestDrainTimeout2543=== RUN TestWorkerRemoveFailureIsNotProgress2544=== PAUSE TestWorkerRemoveFailureIsNotProgress2545=== RUN TestWorkerKeepsPathItCannotStat2546=== PAUSE TestWorkerKeepsPathItCannotStat2547=== CONT TestSendPathsEmpty2548=== CONT TestWorkerRemoveFailureIsNotProgress2549=== CONT TestWorkerKeepsPathItCannotStat2550--- PASS: TestSendPathsEmpty (0.00s)2551=== CONT TestDrainIsolatesPoisonPath2552=== CONT TestServerBacksOffOnAcceptErrors25532026/11/06 07:19:01 ERROR Accept failed error="too many open files"2554=== CONT TestServerStalledClientDoesNotBlockShutdown2555=== CONT TestQueueRemoveLargeClosure2556=== CONT TestQueueConcurrentWriters2557=== CONT TestQueueFetchRemoveLifecycle2558=== CONT TestQueueRetryMovesToBack2559=== CONT TestQueueFetchBatchLimit2560=== CONT TestQueueRemove2561=== CONT TestQueueDeduplication2562=== CONT TestQueueEnqueueAndFetch2563=== CONT TestWorkerUploadsAndRemoves2564=== CONT TestDrainTimeout2565=== CONT TestWorkerSkipsGCdPaths2566=== CONT TestDrainGivesUpWhenServerDown2567=== CONT TestFailedPathPrunedByLaterClosure2568=== CONT TestRunNotBlockedByPoisonHead2569=== CONT TestWorkerPrunesClosureDeps25702026/11/06 07:19:01 ERROR Accept failed error="too many open files"25712026/11/06 07:19:01 INFO Upload queue status pending=225722026/11/06 07:19:01 INFO Uploading batch count=12573--- PASS: TestQueueFetchRemoveLifecycle (0.01s)25742026/11/06 07:19:01 INFO Uploading batch count=125752026/11/06 07:19:01 ERROR Upload failed error="upload failed" count=12576--- PASS: TestQueueEnqueueAndFetch (0.01s)25772026/11/06 07:19:01 INFO Uploading batch count=225782026/11/06 07:19:01 INFO Uploading batch count=225792026/11/06 07:19:01 ERROR Upload failed error="upload failed" count=225802026/11/06 07:19:01 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/4/scratch/6ba07dd8cd494155/build/TestDrainGivesUpWhenServerDown1877406643/002/a2581--- PASS: TestQueueFetchBatchLimit (0.01s)25822026/11/06 07:19:01 INFO Upload queue status pending=325832026/11/06 07:19:01 INFO Uploading batch count=125842026/11/06 07:19:01 ERROR Upload failed error="upload failed" count=125852026/11/06 07:19:01 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/4/scratch/6ba07dd8cd494155/build/TestDrainGivesUpWhenServerDown1877406643/002/b25862026/11/06 07:19:01 INFO Uploading batch count=225872026/11/06 07:19:01 ERROR Upload failed error="upload failed" count=225882026/11/06 07:19:01 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/4/scratch/6ba07dd8cd494155/build/TestDrainGivesUpWhenServerDown1877406643/002/c25892026/11/06 07:19:01 INFO Upload queue status pending=225902026/11/06 07:19:01 INFO Uploading batch count=125912026/11/06 07:19:01 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/4/scratch/6ba07dd8cd494155/build/TestDrainGivesUpWhenServerDown1877406643/002/d2592--- PASS: TestQueueDeduplication (0.01s)25932026/11/06 07:19:01 WARN Store path no longer exists (garbage collected?), removing from queue path=/private/var/tb/4/scratch/6ba07dd8cd494155/build/TestWorkerSkipsGCdPaths2901445796/002/nonexistent25942026/11/06 07:19:01 INFO Uploading batch count=125952026/11/06 07:19:01 INFO Uploading batch count=225962026/11/06 07:19:01 ERROR Upload failed error="upload failed" count=225972026/11/06 07:19:01 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/4/scratch/6ba07dd8cd494155/build/TestDrainGivesUpWhenServerDown1877406643/002/e25982026/11/06 07:19:01 WARN Cannot stat store path, will retry later path=/private/var/tb/4/scratch/6ba07dd8cd494155/build/TestWorkerKeepsPathItCannotStat15769316/002/locked/aaa error="stat /private/var/tb/4/scratch/6ba07dd8cd494155/build/TestWorkerKeepsPathItCannotStat15769316/002/locked/aaa: permission denied"25992026/11/06 07:19:01 INFO Uploading batch count=126002026/11/06 07:19:01 INFO Upload queue status pending=226012026/11/06 07:19:01 WARN Store path no longer exists (garbage collected?), removing from queue path=/private/var/tb/4/scratch/6ba07dd8cd494155/build/TestWorkerRemoveFailureIsNotProgress466387136/002/nonexistent26022026/11/06 07:19:01 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=126032026/11/06 07:19:01 INFO Uploading batch count=226042026/11/06 07:19:01 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/4/scratch/6ba07dd8cd494155/build/TestDrainGivesUpWhenServerDown1877406643/002/f26052026/11/06 07:19:01 INFO Uploading batch count=426062026/11/06 07:19:01 ERROR Upload failed error="upload failed" count=426072026/11/06 07:19:01 ERROR Accept failed error="too many open files"26082026/11/06 07:19:01 WARN Cannot stat store path, will retry later path=/private/var/tb/4/scratch/6ba07dd8cd494155/build/TestWorkerKeepsPathItCannotStat15769316/002/locked/aaa error="stat /private/var/tb/4/scratch/6ba07dd8cd494155/build/TestWorkerKeepsPathItCannotStat15769316/002/locked/aaa: permission denied"26092026/11/06 07:19:01 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/4/scratch/6ba07dd8cd494155/build/TestDrainIsolatesPoisonPath2744411183/002/bbb26102026/11/06 07:19:01 WARN Cannot stat store path, will retry later path=/private/var/tb/4/scratch/6ba07dd8cd494155/build/TestWorkerKeepsPathItCannotStat15769316/002/locked/aaa error="stat /private/var/tb/4/scratch/6ba07dd8cd494155/build/TestWorkerKeepsPathItCannotStat15769316/002/locked/aaa: permission denied"26112026/11/06 07:19:01 ERROR Drain finished with paths left in queue remaining=1026122026/11/06 07:19:01 WARN Store path no longer exists (garbage collected?), removing from queue path=/private/var/tb/4/scratch/6ba07dd8cd494155/build/TestWorkerRemoveFailureIsNotProgress466387136/002/nonexistent26132026/11/06 07:19:01 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=126142026/11/06 07:19:01 WARN Store path no longer exists (garbage collected?), removing from queue path=/private/var/tb/4/scratch/6ba07dd8cd494155/build/TestWorkerRemoveFailureIsNotProgress466387136/002/nonexistent2615--- PASS: TestQueueRemove (0.02s)26162026/11/06 07:19:01 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=126172026/11/06 07:19:01 ERROR Drain finished with paths left in queue remaining=126182026/11/06 07:19:01 ERROR Drain finished with paths left in queue remaining=12619--- PASS: TestQueueRetryMovesToBack (0.02s)2620--- PASS: TestWorkerRemoveFailureIsNotProgress (0.02s)26212026/11/06 07:19:01 INFO Uploading batch count=126222026/11/06 07:19:01 ERROR Upload failed error="upload failed" count=12623--- PASS: TestFailedPathPrunedByLaterClosure (0.02s)2624--- PASS: TestWorkerKeepsPathItCannotStat (0.02s)26252026/11/06 07:19:01 INFO Uploading batch count=126262026/11/06 07:19:01 ERROR Upload failed error="upload failed" count=12627--- PASS: TestDrainGivesUpWhenServerDown (0.02s)26282026/11/06 07:19:01 INFO Uploading batch count=126292026/11/06 07:19:01 ERROR Upload failed error="upload failed" count=126302026/11/06 07:19:01 ERROR Drain finished with paths left in queue remaining=12631--- PASS: TestDrainIsolatesPoisonPath (0.02s)2632--- PASS: TestWorkerPrunesClosureDeps (0.03s)2633--- PASS: TestWorkerSkipsGCdPaths (0.03s)26342026/11/06 07:19:01 ERROR Accept failed error="too many open files"2635--- PASS: TestWorkerUploadsAndRemoves (0.03s)2636--- PASS: TestQueueRemoveLargeClosure (0.04s)2637--- PASS: TestQueueConcurrentWriters (0.04s)26382026/11/06 07:19:01 ERROR Accept failed error="too many open files"26392026/11/06 07:19:02 ERROR Accept failed error="too many open files"26402026/11/06 07:19:02 ERROR Failed to decode request error="read unix /private/var/tb/4/scratch/6ba07dd8cd494155/build/hook1120785004/test.sock->: i/o timeout"26412026/11/06 07:19:02 ERROR Failed to write response error="write unix /private/var/tb/4/scratch/6ba07dd8cd494155/build/hook1120785004/test.sock->: i/o timeout"2642--- PASS: TestServerStalledClientDoesNotBlockShutdown (0.20s)26432026/11/06 07:19:02 ERROR Upload failed error="context deadline exceeded" count=226442026/11/06 07:19:02 ERROR Drain finished with paths left in queue remaining=42645--- PASS: TestDrainTimeout (0.22s)26462026/11/06 07:19:02 ERROR Accept failed error="too many open files"26472026/11/06 07:19:02 ERROR Accept failed error="too many open files"2648--- PASS: TestServerBacksOffOnAcceptErrors (0.64s)26492026/11/06 07:19:02 INFO Uploading batch count=126502026/11/06 07:19:02 INFO Uploading batch count=126512026/11/06 07:19:02 INFO Uploading batch count=126522026/11/06 07:19:02 ERROR Upload failed error="upload failed" count=126532026/11/06 07:19:02 INFO Uploading batch count=126542026/11/06 07:19:02 ERROR Upload failed error="upload failed" count=126552026/11/06 07:19:02 INFO Uploading batch count=126562026/11/06 07:19:02 ERROR Upload failed error="upload failed" count=126572026/11/06 07:19:02 INFO Uploading batch count=126582026/11/06 07:19:02 ERROR Upload failed error="upload failed" count=126592026/11/06 07:19:02 ERROR Drain finished with paths left in queue remaining=12660--- PASS: TestRunNotBlockedByPoisonHead (1.04s)2661PASS2662Running signing tests...2663=== RUN TestExternalSigner2664=== PAUSE TestExternalSigner2665=== RUN TestExternalSignerWrongPublicKey2666=== PAUSE TestExternalSignerWrongPublicKey2667=== RUN TestExternalSignerErrors2668=== PAUSE TestExternalSignerErrors2669=== RUN TestExternalSignerRestartsAfterCrash2670=== PAUSE TestExternalSignerRestartsAfterCrash2671=== RUN TestExternalSignerProgramErrorKeepsProcess2672=== PAUSE TestExternalSignerProgramErrorKeepsProcess2673=== RUN TestExternalSignerClose2674=== PAUSE TestExternalSignerClose2675=== RUN TestExternalSignerRejectsInvalidPublicKey2676=== PAUSE TestExternalSignerRejectsInvalidPublicKey2677=== RUN TestExternalSignerCancellation2678=== PAUSE TestExternalSignerCancellation2679=== RUN TestGenerateFingerprint2680=== PAUSE TestGenerateFingerprint2681=== RUN TestParseSigningKey2682=== PAUSE TestParseSigningKey2683=== RUN TestSign2684=== PAUSE TestSign2685=== RUN TestSignBatch2686=== PAUSE TestSignBatch2687=== RUN TestNilKeyPublicKey2688=== PAUSE TestNilKeyPublicKey2689=== RUN TestSignErrors2690=== PAUSE TestSignErrors2691=== CONT TestExternalSigner2692=== CONT TestExternalSignerRejectsInvalidPublicKey2693=== CONT TestSignBatch2694=== RUN TestExternalSignerRejectsInvalidPublicKey/#002695=== PAUSE TestExternalSignerRejectsInvalidPublicKey/#002696=== RUN TestExternalSignerRejectsInvalidPublicKey/no-colon2697=== PAUSE TestExternalSignerRejectsInvalidPublicKey/no-colon2698=== RUN TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2699=== PAUSE TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2700=== CONT TestSign2701=== CONT TestSignErrors2702=== CONT TestNilKeyPublicKey2703--- PASS: TestNilKeyPublicKey (0.00s)2704=== CONT TestParseSigningKey2705=== RUN TestParseSigningKey/valid_32-byte_key2706=== RUN TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2707=== PAUSE TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2708=== CONT TestGenerateFingerprint2709=== RUN TestGenerateFingerprint/basic_with_references2710=== PAUSE TestGenerateFingerprint/basic_with_references2711=== RUN TestGenerateFingerprint/no_references2712=== PAUSE TestGenerateFingerprint/no_references2713=== RUN TestGenerateFingerprint/unsorted_references_get_sorted2714=== PAUSE TestGenerateFingerprint/unsorted_references_get_sorted2715=== RUN TestGenerateFingerprint/invalid_nar_hash_prefix2716=== CONT TestExternalSignerCancellation2717=== CONT TestExternalSignerRestartsAfterCrash2718=== CONT TestExternalSignerClose2719=== CONT TestExternalSignerProgramErrorKeepsProcess2720=== CONT TestExternalSignerErrors2721=== RUN TestExternalSignerErrors/wrong_shape2722=== PAUSE TestExternalSignerErrors/wrong_shape2723=== RUN TestExternalSignerErrors/wrong_signature_name2724=== PAUSE TestExternalSignerErrors/wrong_signature_name2725=== RUN TestExternalSignerErrors/invalid_signature_base642726=== PAUSE TestExternalSignerErrors/invalid_signature_base642727=== RUN TestExternalSignerErrors/invalid_JSON2728=== PAUSE TestExternalSignerErrors/invalid_JSON2729=== RUN TestExternalSignerErrors/missing_signatures2730=== CONT TestExternalSignerWrongPublicKey2731=== PAUSE TestExternalSignerErrors/missing_signatures2732=== RUN TestExternalSignerErrors/unrequested_key2733=== PAUSE TestExternalSignerErrors/unrequested_key2734=== RUN TestExternalSignerErrors/program_error2735=== PAUSE TestExternalSignerErrors/program_error2736=== RUN TestExternalSignerErrors/exit_on_request2737=== PAUSE TestExternalSignerErrors/exit_on_request2738=== PAUSE TestParseSigningKey/valid_32-byte_key2739=== RUN TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2740=== PAUSE TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2741=== CONT TestExternalSignerRejectsInvalidPublicKey/#002742=== CONT TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2743=== CONT TestExternalSignerRejectsInvalidPublicKey/no-colon2744=== RUN TestParseSigningKey/valid_32-byte_key_with_different_name2745=== PAUSE TestParseSigningKey/valid_32-byte_key_with_different_name2746=== RUN TestParseSigningKey/no_colon2747=== PAUSE TestParseSigningKey/no_colon2748=== RUN TestParseSigningKey/empty_name2749=== RUN TestExternalSignerErrors/wrong_id2750=== CONT TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2751=== CONT TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2752--- PASS: TestExternalSignerRejectsInvalidPublicKey (0.00s)2753 --- PASS: TestExternalSignerRejectsInvalidPublicKey/#00 (0.00s)2754 --- PASS: TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA= (0.00s)2755 --- PASS: TestExternalSignerRejectsInvalidPublicKey/no-colon (0.00s)2756 --- PASS: TestExternalSignerRejectsInvalidPublicKey/test-key:invalid! (0.00s)2757 --- PASS: TestExternalSignerRejectsInvalidPublicKey/test-key:YQ== (0.00s)2758=== PAUSE TestGenerateFingerprint/invalid_nar_hash_prefix2759=== RUN TestGenerateFingerprint/invalid_nar_hash_length2760=== PAUSE TestGenerateFingerprint/invalid_nar_hash_length2761=== RUN TestGenerateFingerprint/invalid_store_path_prefix2762=== PAUSE TestGenerateFingerprint/invalid_store_path_prefix2763=== RUN TestGenerateFingerprint/invalid_reference_prefix2764=== PAUSE TestGenerateFingerprint/invalid_reference_prefix2765=== PAUSE TestExternalSignerErrors/wrong_id2766=== RUN TestExternalSignerErrors/missing_signature_name2767=== PAUSE TestExternalSignerErrors/missing_signature_name2768=== RUN TestExternalSignerErrors/exit_at_startup2769=== PAUSE TestExternalSignerErrors/exit_at_startup2770=== RUN TestExternalSignerErrors/null2771=== PAUSE TestExternalSignerErrors/null2772=== RUN TestExternalSignerErrors/null_signatures2773=== PAUSE TestExternalSignerErrors/null_signatures2774=== RUN TestExternalSignerErrors/wrong_signatures_shape2775=== PAUSE TestExternalSignerErrors/wrong_signatures_shape2776=== RUN TestExternalSignerErrors/too_few_signatures2777=== PAUSE TestExternalSignerErrors/too_few_signatures2778=== RUN TestExternalSignerErrors/wrong_signature_length2779=== PAUSE TestExternalSignerErrors/wrong_signature_length2780=== CONT TestExternalSignerErrors/wrong_shape2781=== CONT TestExternalSignerErrors/missing_signature_name2782=== CONT TestExternalSignerErrors/wrong_signatures_shape2783--- PASS: TestSign (0.00s)2784=== CONT TestGenerateFingerprint/basic_with_references2785=== CONT TestExternalSignerErrors/null_signatures2786=== PAUSE TestParseSigningKey/empty_name2787=== RUN TestParseSigningKey/invalid_base642788=== PAUSE TestParseSigningKey/invalid_base642789=== RUN TestParseSigningKey/wrong_length2790=== PAUSE TestParseSigningKey/wrong_length2791=== CONT TestParseSigningKey/valid_32-byte_key2792--- PASS: TestSignBatch (0.00s)2793=== RUN TestSignErrors/nil_key2794=== PAUSE TestSignErrors/nil_key2795=== CONT TestExternalSignerErrors/wrong_signature_length2796=== CONT TestGenerateFingerprint/invalid_nar_hash_length2797=== CONT TestParseSigningKey/no_colon2798=== CONT TestParseSigningKey/valid_32-byte_key_with_different_name2799=== CONT TestGenerateFingerprint/invalid_nar_hash_prefix2800=== CONT TestExternalSignerErrors/exit_at_startup2801=== CONT TestExternalSignerErrors/program_error2802=== CONT TestGenerateFingerprint/unsorted_references_get_sorted2803=== CONT TestExternalSignerErrors/null2804=== CONT TestGenerateFingerprint/no_references2805=== CONT TestExternalSignerErrors/too_few_signatures2806=== CONT TestExternalSignerErrors/unrequested_key2807=== CONT TestGenerateFingerprint/invalid_store_path_prefix2808=== CONT TestParseSigningKey/wrong_length2809=== CONT TestExternalSignerErrors/invalid_signature_base642810=== CONT TestExternalSignerErrors/wrong_id2811=== CONT TestParseSigningKey/invalid_base642812=== CONT TestExternalSignerErrors/missing_signatures2813=== CONT TestParseSigningKey/empty_name2814--- PASS: TestParseSigningKey (0.00s)2815 --- PASS: TestParseSigningKey/valid_32-byte_key (0.00s)2816 --- PASS: TestParseSigningKey/no_colon (0.00s)2817 --- PASS: TestParseSigningKey/valid_32-byte_key_with_different_name (0.00s)2818 --- PASS: TestParseSigningKey/wrong_length (0.00s)2819 --- PASS: TestParseSigningKey/invalid_base64 (0.00s)2820 --- PASS: TestParseSigningKey/empty_name (0.00s)2821=== CONT TestExternalSignerErrors/exit_on_request2822=== CONT TestExternalSignerErrors/wrong_signature_name2823=== CONT TestGenerateFingerprint/invalid_reference_prefix2824--- PASS: TestGenerateFingerprint (0.00s)2825 --- PASS: TestGenerateFingerprint/basic_with_references (0.00s)2826 --- PASS: TestGenerateFingerprint/invalid_nar_hash_length (0.00s)2827 --- PASS: TestGenerateFingerprint/invalid_nar_hash_prefix (0.00s)2828 --- PASS: TestGenerateFingerprint/unsorted_references_get_sorted (0.00s)2829 --- PASS: TestGenerateFingerprint/no_references (0.00s)2830 --- PASS: TestGenerateFingerprint/invalid_store_path_prefix (0.00s)2831 --- PASS: TestGenerateFingerprint/invalid_reference_prefix (0.00s)2832=== RUN TestSignErrors/nil_narinfo2833=== PAUSE TestSignErrors/nil_narinfo2834=== CONT TestExternalSignerErrors/invalid_JSON2835=== RUN TestSignErrors/invalid_narinfo2836=== PAUSE TestSignErrors/invalid_narinfo2837=== RUN TestSignErrors/canceled2838=== PAUSE TestSignErrors/canceled2839=== CONT TestSignErrors/nil_key2840=== CONT TestSignErrors/canceled2841=== CONT TestSignErrors/invalid_narinfo2842=== CONT TestSignErrors/nil_narinfo2843--- PASS: TestSignErrors (0.01s)2844 --- PASS: TestSignErrors/nil_key (0.00s)2845 --- PASS: TestSignErrors/canceled (0.00s)2846 --- PASS: TestSignErrors/invalid_narinfo (0.00s)2847 --- PASS: TestSignErrors/nil_narinfo (0.00s)2848--- PASS: TestExternalSignerRestartsAfterCrash (1.09s)2849/private/var/tb/4/scratch/6ba07dd8cd494155/build/TestExternalSignerRestartsAfterCrash1978257009/001/sign program: line 7: /private/var/tb/4/scratch/6ba07dd8cd494155/build/TestExternalSignerRestartsAfterCrash1978257009/001/sign program.starts: No such file or directory2850--- PASS: TestExternalSigner (1.88s)2851--- PASS: TestExternalSignerWrongPublicKey (2.05s)2852--- PASS: TestExternalSignerProgramErrorKeepsProcess (2.42s)2853--- PASS: TestExternalSignerClose (3.56s)2854--- PASS: TestExternalSignerErrors (0.00s)2855 --- PASS: TestExternalSignerErrors/missing_signature_name (0.29s)2856 --- PASS: TestExternalSignerErrors/invalid_signature_base64 (0.47s)2857 --- PASS: TestExternalSignerErrors/wrong_shape (0.68s)2858 --- PASS: TestExternalSignerErrors/missing_signatures (0.87s)2859 --- PASS: TestExternalSignerErrors/wrong_signatures_shape (1.25s)2860 --- PASS: TestExternalSignerErrors/program_error (1.52s)2861 --- PASS: TestExternalSignerErrors/wrong_signature_name (1.66s)2862 --- PASS: TestExternalSignerErrors/null (2.23s)2863 --- PASS: TestExternalSignerErrors/wrong_signature_length (2.61s)2864 --- PASS: TestExternalSignerErrors/exit_at_startup (2.80s)2865 --- PASS: TestExternalSignerErrors/exit_on_request (2.98s)2866 --- PASS: TestExternalSignerErrors/wrong_id (3.17s)2867 --- PASS: TestExternalSignerErrors/too_few_signatures (3.36s)2868 --- PASS: TestExternalSignerErrors/invalid_JSON (3.74s)2869 --- PASS: TestExternalSignerErrors/null_signatures (3.93s)2870 --- PASS: TestExternalSignerErrors/unrequested_key (4.12s)2871--- PASS: TestExternalSignerCancellation (4.33s)2872PASS2873Running OpenBao signer tests...2874=== RUN TestSign2875=== PAUSE TestSign2876=== RUN TestSignErrors2877=== PAUSE TestSignErrors2878=== RUN TestServe2879=== PAUSE TestServe2880=== RUN TestServeRejectsGarbage2881=== PAUSE TestServeRejectsGarbage2882=== CONT TestSign2883=== CONT TestSignErrors2884=== RUN TestSignErrors/http_error2885=== CONT TestServeRejectsGarbage2886=== CONT TestServe2887=== PAUSE TestSignErrors/http_error2888=== RUN TestSignErrors/invalid_json2889=== PAUSE TestSignErrors/invalid_json2890=== RUN TestSignErrors/no_prefix2891=== PAUSE TestSignErrors/no_prefix2892=== RUN TestSignErrors/invalid_base642893=== PAUSE TestSignErrors/invalid_base642894=== CONT TestSignErrors/http_error2895=== CONT TestSignErrors/invalid_json2896--- PASS: TestServeRejectsGarbage (0.00s)2897=== CONT TestSignErrors/invalid_base642898=== CONT TestSignErrors/no_prefix2899--- PASS: TestServe (0.00s)2900--- PASS: TestSign (0.01s)2901--- PASS: TestSignErrors (0.00s)2902 --- PASS: TestSignErrors/http_error (0.01s)2903 --- PASS: TestSignErrors/invalid_base64 (0.01s)2904 --- PASS: TestSignErrors/invalid_json (0.01s)2905 --- PASS: TestSignErrors/no_prefix (0.01s)2906PASS