niks3-go-unit-tests
checks.aarch64-darwin.go-unit-tests
· build #428
· raw
1tribuchet: building on mac022Running client tests...3=== RUN TestDoServerRequestAttachesToken4=== PAUSE TestDoServerRequestAttachesToken5=== RUN TestUploadBuildLog_FileBodyReplayedOnRetry6=== PAUSE TestUploadBuildLog_FileBodyReplayedOnRetry7=== RUN TestRegisterUploadedObjectReusesConnections8=== PAUSE TestRegisterUploadedObjectReusesConnections9=== RUN TestRunGarbageCollection_FinishedOnAnotherReplica10=== PAUSE TestRunGarbageCollection_FinishedOnAnotherReplica11=== RUN TestRunGarbageCollection_NotFoundAfterLocalRun12=== PAUSE TestRunGarbageCollection_NotFoundAfterLocalRun13=== RUN TestCaseHackSuffix14=== PAUSE TestCaseHackSuffix15=== RUN TestFilterOversizedClosures16=== PAUSE TestFilterOversizedClosures17=== RUN TestUploadMultipart_PartsInParallel18=== PAUSE TestUploadMultipart_PartsInParallel19=== RUN TestUploadMultipart_FailedPartBufferNotReused20=== PAUSE TestUploadMultipart_FailedPartBufferNotReused21=== RUN TestPartSizeForNAR22=== PAUSE TestPartSizeForNAR23=== RUN TestUploadMultipart_SupersededByPeer24=== PAUSE TestUploadMultipart_SupersededByPeer25=== RUN TestDumpPathCaseHackMatchesNix26--- PASS: TestDumpPathCaseHackMatchesNix (0.14s)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 TestStreamPushReportsSignatures118=== CONT TestSetClientTLS119=== CONT TestUploadMultipart_PartsInParallel120=== CONT TestFileTokenMissing121=== CONT TestFileTokenEmpty122--- PASS: TestFileTokenMissing (0.00s)123=== CONT TestUploadMultipart_SupersededByPeer124=== RUN TestUploadMultipart_SupersededByPeer/exists125=== PAUSE TestUploadMultipart_SupersededByPeer/exists126=== RUN TestUploadMultipart_SupersededByPeer/missing127=== PAUSE TestUploadMultipart_SupersededByPeer/missing128=== CONT TestPartSizeForNAR129=== CONT TestFileTokenReadsAndCaches130=== CONT TestStaticToken131=== CONT TestScriptTokenEmptyCommand132=== CONT TestSetClientTLSErrors133=== CONT TestScriptTokenScriptFails134=== CONT TestScriptTokenBadJSON135=== CONT TestScriptTokenEmptyToken136=== CONT TestSetClientTLSDoesNotMutateDefaultTransport137=== CONT TestScriptTokenCachesUntilRefresh138=== CONT TestStreamPushIsolatesFailures139=== CONT TestStreamPushStopsWhenCanceled140=== CONT TestClientSignaturesByStorePath141=== CONT TestStreamPushReportsSkippedPaths142=== CONT TestDumpPathSingleFile143=== CONT TestDumpPathMatchesNix144=== CONT TestSupersededNARStillUploadsListing145=== CONT TestUploadMultipart_FailedPartBufferNotReused146=== CONT TestScriptTokenNoExpiryRerunsEveryCall147--- PASS: TestStaticToken (0.00s)1482026/10/25 17:15:35 ERROR Upload failed error=boom count=1149=== CONT TestRunGarbageCollection_NotFoundAfterLocalRun150--- PASS: TestStreamPushReportsSignatures (0.01s)151=== CONT TestFilterOversizedClosures152--- PASS: TestScriptTokenEmptyCommand (0.00s)153=== RUN TestPartSizeForNAR/zero_stays_at_minimum154=== PAUSE TestPartSizeForNAR/zero_stays_at_minimum155=== RUN TestPartSizeForNAR/small_stays_at_minimum156=== PAUSE TestPartSizeForNAR/small_stays_at_minimum157=== RUN TestPartSizeForNAR/80_GiB_fits_at_minimum158=== PAUSE TestPartSizeForNAR/80_GiB_fits_at_minimum159=== RUN TestPartSizeForNAR/115_GiB_needs_larger_parts160=== PAUSE TestPartSizeForNAR/115_GiB_needs_larger_parts161=== RUN TestPartSizeForNAR/1_TiB162=== CONT TestCaseHackSuffix1632026/10/25 17:15:35 ERROR Upload failed error="bad path" count=3164=== CONT TestStreamPushRequestLine165=== CONT TestShellSplitErrors166=== CONT TestStreamPushBatchesUnderLoad167=== CONT TestStreamPushReportsEveryPath1682026/10/25 17:15:35 WARN Rate limiter enabled after throttle name=server-test rate=51692026/10/25 17:15:35 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:51030170=== CONT TestDoWithRetry_FinalResponseBodyReadable171=== RUN TestSupersededNARStillUploadsListing/small_NAR172=== PAUSE TestSupersededNARStillUploadsListing/small_NAR173=== RUN TestSupersededNARStillUploadsListing/dump_cut_short174=== PAUSE TestSupersededNARStillUploadsListing/dump_cut_short175=== RUN TestSupersededNARStillUploadsListing/listing_upload_fails176=== PAUSE TestSupersededNARStillUploadsListing/listing_upload_fails1772026/10/25 17:15:35 ERROR Upload failed error=boom count=11782026/10/25 17:15:35 WARN Rate limiter enabled after throttle name=server-test rate=5179=== CONT TestShellSplit180=== CONT TestStreamPushGivesUpOnDeadServer1812026/10/25 17:15:35 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:510331822026/10/25 17:15:35 ERROR Upload failed error="connection refused" count=201832026/10/25 17:15:35 ERROR Server seems unavailable, giving up on batch untried=17184=== CONT TestParsePathInfoJSONMultiplePaths185=== PAUSE TestPartSizeForNAR/1_TiB186--- PASS: TestStreamPushStopsWhenCanceled (0.00s)187=== CONT TestResolveStorePath1882026/10/25 17:15:35 INFO Garbage collection started189--- PASS: TestStreamPushIsolatesFailures (0.00s)190--- PASS: TestClientSignaturesByStorePath (0.00s)191--- PASS: TestShellSplitErrors (0.00s)192--- PASS: TestStreamPushReportsSkippedPaths (0.00s)193--- PASS: TestStreamPushReportsEveryPath (0.00s)194=== CONT TestRegisterUploadedObject_BoundedAgainstSilentServer195=== RUN TestFilterOversizedClosures/no_limit_keeps_everything196--- PASS: TestShellSplit (0.00s)197--- PASS: TestDoServerRequestAttachesToken (0.01s)198--- PASS: TestStreamPushGivesUpOnDeadServer (0.00s)199--- PASS: TestFileTokenReadsAndCaches (0.00s)200--- PASS: TestResolveStorePath (0.00s)201--- PASS: TestScriptTokenScriptFails (0.01s)202--- PASS: TestSetClientTLSDoesNotMutateDefaultTransport (0.01s)203=== RUN TestPartSizeForNAR/5_TiB_S3_max_object204=== PAUSE TestPartSizeForNAR/5_TiB_S3_max_object205=== RUN TestPartSizeForNAR/capped_at_5_GiB206=== PAUSE TestPartSizeForNAR/capped_at_5_GiB207=== RUN TestSetClientTLS/rejects_connection_without_client_cert208=== PAUSE TestSetClientTLS/rejects_connection_without_client_cert209=== RUN TestSetClientTLS/succeeds_with_client_cert_and_CA210=== PAUSE TestSetClientTLS/succeeds_with_client_cert_and_CA211=== CONT TestGetStorePathHash212=== RUN TestGetStorePathHash/valid_store_path213=== PAUSE TestGetStorePathHash/valid_store_path214=== RUN TestSetClientTLS/preserves_debug_logging_transport215=== RUN TestGetStorePathHash/basename_without_hyphen_should_error216=== PAUSE TestGetStorePathHash/basename_without_hyphen_should_error2172026/10/25 17:15:35 WARN Rate limiter backed off name=server-test rate=52182026/10/25 17:15:35 WARN Request returned retryable status, retrying attempt=2 backoff=0s status=503 url=http://127.0.0.1:51030219=== RUN TestGetStorePathHash/hash_with_invalid_characters_should_error220=== PAUSE TestGetStorePathHash/hash_with_invalid_characters_should_error221=== RUN TestGetStorePathHash/hash_with_wrong_length_should_error222=== PAUSE TestGetStorePathHash/hash_with_wrong_length_should_error223=== PAUSE TestSetClientTLS/preserves_debug_logging_transport224=== CONT TestParsePathInfoJSON225=== RUN TestParsePathInfoJSON/Nix_format226=== PAUSE TestParsePathInfoJSON/Nix_format227=== RUN TestParsePathInfoJSON/Lix_format228=== PAUSE TestParsePathInfoJSON/Lix_format229=== CONT TestPathInfoHashCompatibility230=== RUN TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)231=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)232=== RUN TestParsePathInfoJSON/empty_input233=== PAUSE TestParsePathInfoJSON/empty_input234=== RUN TestParsePathInfoJSON/whitespace_only235=== PAUSE TestParsePathInfoJSON/whitespace_only236=== RUN TestParsePathInfoJSON/invalid_JSON237=== PAUSE TestParsePathInfoJSON/invalid_JSON238=== RUN TestPathInfoHashCompatibility/old_string_format_with_colon239=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_colon240=== RUN TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI241=== PAUSE TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI242=== RUN TestPathInfoHashCompatibility/new_structured_format_with_sha512243=== CONT TestRegisterUploadedObjectReusesConnections244=== RUN TestSetClientTLSErrors/missing_cert_file245=== PAUSE TestSetClientTLSErrors/missing_cert_file246=== RUN TestSetClientTLSErrors/missing_key_file247=== PAUSE TestSetClientTLSErrors/missing_key_file248=== RUN TestSetClientTLSErrors/missing_ca_file249=== PAUSE TestSetClientTLSErrors/missing_ca_file250=== RUN TestSetClientTLSErrors/invalid_ca_file251=== PAUSE TestSetClientTLSErrors/invalid_ca_file252=== PAUSE TestPathInfoHashCompatibility/new_structured_format_with_sha512253=== CONT TestUploadBuildLog_FileBodyReplayedOnRetry254=== CONT TestConvertHashToNix32255=== RUN TestConvertHashToNix32/SRI_format_to_Nix32256=== PAUSE TestConvertHashToNix32/SRI_format_to_Nix32257=== RUN TestConvertHashToNix32/already_Nix32_format258=== PAUSE TestConvertHashToNix32/already_Nix32_format259=== RUN TestConvertHashToNix32/invalid_format260=== PAUSE TestConvertHashToNix32/invalid_format261=== CONT TestEncodeNixBase32262=== RUN TestEncodeNixBase32/test_string_hash263=== PAUSE TestEncodeNixBase32/test_string_hash264=== RUN TestEncodeNixBase32/empty_input265=== PAUSE TestEncodeNixBase32/empty_input266=== CONT TestRetryTimeoutOutlastsMaxRetries267=== CONT TestDumpPathWriterError268--- PASS: TestFileTokenEmpty (0.02s)269--- PASS: TestRunGarbageCollection_NotFoundAfterLocalRun (0.01s)270--- PASS: TestDoWithRetry_BodyReplayedViaGetBody (0.02s)271=== CONT TestEncodeNixBase32WithRealHash272--- PASS: TestEncodeNixBase32WithRealHash (0.00s)273=== CONT TestUploadMultipart_SupersededByPeer/exists274=== CONT TestRunGarbageCollection_FinishedOnAnotherReplica2752026/10/25 17:15:35 WARN Request returned retryable status, retrying attempt=1 backoff=1ms status=502 url=http://127.0.0.1:51049276=== RUN TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths277=== PAUSE TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths278=== RUN TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths279=== PAUSE TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths2802026/10/25 17:15:35 WARN Rate limiter backed off name=server-test rate=52812026/10/25 17:15:35 WARN Rate limiter enabled after throttle name=s3-test rate=52822026/10/25 17:15:35 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:51056283=== CONT TestUploadMultipart_SupersededByPeer/missing284--- PASS: TestDoWithRetry_FinalResponseBodyReadable (0.01s)285=== CONT TestSupersededNARStillUploadsListing/small_NAR286=== PAUSE TestFilterOversizedClosures/no_limit_keeps_everything287=== RUN TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped288=== PAUSE TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped289=== RUN TestFilterOversizedClosures/all_closures_skipped290=== PAUSE TestFilterOversizedClosures/all_closures_skipped291=== CONT TestSupersededNARStillUploadsListing/listing_upload_fails292=== CONT TestRateLimiterFeedback_400DoesNotCountAsSuccess2932026/10/25 17:15:35 WARN Request returned retryable status, retrying attempt=2 backoff=1ms status=502 url=http://127.0.0.1:510492942026/10/25 17:15:35 INFO Garbage collection started295=== CONT TestSupersededNARStillUploadsListing/dump_cut_short296=== CONT TestRateLimiterFeedback297=== RUN TestRateLimiterFeedback/429_enables_limiter298=== PAUSE TestRateLimiterFeedback/429_enables_limiter299=== RUN TestRateLimiterFeedback/503_enables_limiter300=== PAUSE TestRateLimiterFeedback/503_enables_limiter301=== RUN TestRateLimiterFeedback/200_does_not_enable_limiter302=== PAUSE TestRateLimiterFeedback/200_does_not_enable_limiter303=== CONT TestPathInfoCACompatibility304=== RUN TestPathInfoCACompatibility/null_ca_field305=== PAUSE TestPathInfoCACompatibility/null_ca_field306=== RUN TestRateLimiterFeedback/400_does_not_enable_limiter307=== PAUSE TestRateLimiterFeedback/400_does_not_enable_limiter308=== RUN TestPathInfoCACompatibility/old_string_format_-_text309=== PAUSE TestPathInfoCACompatibility/old_string_format_-_text310=== RUN TestPathInfoCACompatibility/old_string_format_-_fixed_recursive311=== PAUSE TestPathInfoCACompatibility/old_string_format_-_fixed_recursive312=== RUN TestPathInfoCACompatibility/new_structured_format_-_text313=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_text314=== RUN TestPathInfoCACompatibility/new_structured_format_-_nar_method315=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_nar_method3162026/10/25 17:15:35 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=0317=== CONT TestPartSizeForNAR/80_GiB_fits_at_minimum318=== CONT TestPartSizeForNAR/small_stays_at_minimum319=== CONT TestPartSizeForNAR/capped_at_5_GiB320=== CONT TestPartSizeForNAR/5_TiB_S3_max_object321=== CONT TestGetStorePathHash/valid_store_path322=== CONT TestSetClientTLS/rejects_connection_without_client_cert3232026/10/25 17:15:35 WARN Request returned retryable status, retrying attempt=1 backoff=1ms status=502 url=http://127.0.0.1:51049324--- PASS: TestScriptTokenEmptyToken (0.02s)325--- PASS: TestUploadMultipart_SupersededByPeer (0.00s)326 --- PASS: TestUploadMultipart_SupersededByPeer/exists (0.00s)327 --- PASS: TestUploadMultipart_SupersededByPeer/missing (0.00s)328=== CONT TestPartSizeForNAR/zero_stays_at_minimum329=== CONT TestPartSizeForNAR/1_TiB330=== CONT TestGetStorePathHash/hash_with_wrong_length_should_error331=== CONT TestPartSizeForNAR/115_GiB_needs_larger_parts332=== CONT TestGetStorePathHash/hash_with_invalid_characters_should_error333=== CONT TestGetStorePathHash/basename_without_hyphen_should_error334=== CONT TestSetClientTLS/preserves_debug_logging_transport335=== CONT TestParsePathInfoJSON/Nix_format336--- PASS: TestPartSizeForNAR (0.02s)337 --- PASS: TestPartSizeForNAR/80_GiB_fits_at_minimum (0.00s)338 --- PASS: TestPartSizeForNAR/small_stays_at_minimum (0.00s)339 --- PASS: TestPartSizeForNAR/capped_at_5_GiB (0.00s)340 --- PASS: TestPartSizeForNAR/5_TiB_S3_max_object (0.00s)341 --- PASS: TestPartSizeForNAR/zero_stays_at_minimum (0.00s)342 --- PASS: TestPartSizeForNAR/1_TiB (0.00s)343 --- PASS: TestPartSizeForNAR/115_GiB_needs_larger_parts (0.00s)344=== CONT TestSetClientTLS/succeeds_with_client_cert_and_CA3452026/10/25 17:15:35 WARN Rate limiter enabled after throttle name=server-test rate=5346--- PASS: TestGetStorePathHash (0.00s)347 --- PASS: TestGetStorePathHash/valid_store_path (0.00s)348 --- PASS: TestGetStorePathHash/hash_with_invalid_characters_should_error (0.00s)349 --- PASS: TestGetStorePathHash/basename_without_hyphen_should_error (0.00s)350 --- PASS: TestGetStorePathHash/hash_with_wrong_length_should_error (0.00s)351=== CONT TestParsePathInfoJSON/whitespace_only352=== CONT TestParsePathInfoJSON/empty_input353=== CONT TestParsePathInfoJSON/Lix_format354=== CONT TestParsePathInfoJSON/invalid_JSON355--- PASS: TestParsePathInfoJSON (0.00s)356 --- PASS: TestParsePathInfoJSON/Nix_format (0.00s)357 --- PASS: TestParsePathInfoJSON/whitespace_only (0.00s)358 --- PASS: TestParsePathInfoJSON/empty_input (0.00s)359 --- PASS: TestParsePathInfoJSON/Lix_format (0.00s)360 --- PASS: TestParsePathInfoJSON/invalid_JSON (0.00s)361=== CONT TestSetClientTLSErrors/missing_cert_file362=== CONT TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)363=== CONT TestConvertHashToNix32/SRI_format_to_Nix32364=== CONT TestEncodeNixBase32/test_string_hash365=== CONT TestConvertHashToNix32/invalid_format366=== CONT TestConvertHashToNix32/already_Nix32_format367--- PASS: TestConvertHashToNix32 (0.00s)368 --- PASS: TestConvertHashToNix32/SRI_format_to_Nix32 (0.00s)369 --- PASS: TestConvertHashToNix32/invalid_format (0.00s)370 --- PASS: TestConvertHashToNix32/already_Nix32_format (0.00s)371=== CONT TestEncodeNixBase32/empty_input372--- PASS: TestEncodeNixBase32 (0.00s)373 --- PASS: TestEncodeNixBase32/test_string_hash (0.00s)374 --- PASS: TestEncodeNixBase32/empty_input (0.00s)375=== CONT TestSetClientTLSErrors/invalid_ca_file3762026/10/25 17:15:35 INFO Uploading abc-hello (1.0GB)3772026/10/25 17:15:35 WARN Request returned retryable status, retrying attempt=2 backoff=1ms status=502 url=http://127.0.0.1:51049378=== CONT TestSetClientTLSErrors/missing_ca_file379=== CONT TestPathInfoHashCompatibility/new_structured_format_with_sha512380=== CONT TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI381=== CONT TestPathInfoHashCompatibility/old_string_format_with_colon382=== CONT TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths383=== CONT TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths384=== CONT TestFilterOversizedClosures/no_limit_keeps_everything385=== CONT TestFilterOversizedClosures/all_closures_skipped3862026/10/25 17:15:35 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=50387=== CONT TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped3882026/10/25 17:15:35 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=2000389=== CONT TestRateLimiterFeedback/429_enables_limiter390--- PASS: TestUploadBuildLog_FileBodyReplayedOnRetry (0.01s)3912026/10/25 17:15:35 INFO Uploading abc-hello (1.0GB)392=== CONT TestSetClientTLSErrors/missing_key_file393=== CONT TestRateLimiterFeedback/400_does_not_enable_limiter394--- PASS: TestScriptTokenBadJSON (0.03s)395--- PASS: TestPathInfoHashCompatibility (0.00s)396 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) (0.00s)397 --- PASS: TestPathInfoHashCompatibility/new_structured_format_with_sha512 (0.00s)398 --- PASS: TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI (0.00s)399 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_colon (0.00s)400=== CONT TestRateLimiterFeedback/200_does_not_enable_limiter401--- PASS: TestParsePathInfoJSONMultiplePaths (0.01s)402 --- PASS: TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths (0.00s)403 --- PASS: TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths (0.00s)404--- PASS: TestFilterOversizedClosures (0.01s)405 --- PASS: TestFilterOversizedClosures/no_limit_keeps_everything (0.00s)406 --- PASS: TestFilterOversizedClosures/all_closures_skipped (0.00s)407 --- PASS: TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped (0.00s)408--- PASS: TestSetClientTLSErrors (0.02s)409 --- PASS: TestSetClientTLSErrors/missing_cert_file (0.00s)410 --- PASS: TestSetClientTLSErrors/invalid_ca_file (0.00s)411 --- PASS: TestSetClientTLSErrors/missing_ca_file (0.00s)412 --- PASS: TestSetClientTLSErrors/missing_key_file (0.00s)4132026/10/25 17:15:35 WARN Request returned retryable status, retrying attempt=3 backoff=1ms status=502 url=http://127.0.0.1:510494142026/10/25 17:15:35 WARN Garbage collection finished on another replica. Its statistics are not available here415--- PASS: TestRunGarbageCollection_FinishedOnAnotherReplica (0.02s)416=== CONT TestRateLimiterFeedback/503_enables_limiter4172026/10/25 17:15:35 WARN Rate limiter enabled after throttle name=server-test rate=54182026/10/25 17:15:35 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:511424192026/10/25 17:15:35 WARN Rate limiter enabled after throttle name=server-test rate=54202026/10/25 17:15:35 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=429 url=http://127.0.0.1:51128421=== CONT TestPathInfoCACompatibility/new_structured_format_-_text422=== CONT TestPathInfoCACompatibility/new_structured_format_-_nar_method423=== CONT TestPathInfoCACompatibility/old_string_format_-_fixed_recursive424=== CONT TestPathInfoCACompatibility/old_string_format_-_text425=== CONT TestPathInfoCACompatibility/null_ca_field4262026/10/25 17:15:35 WARN Rate limiter backed off name=server-test rate=54272026/10/25 17:15:35 WARN Rate limiter backed off name=server-test rate=54282026/10/25 17:15:35 WARN Rate limiter enabled after throttle name=s3-test rate=54292026/10/25 17:15:35 WARN Request returned retryable status, retrying attempt=4 backoff=1ms status=502 url=http://127.0.0.1:510494302026/10/25 17:15:35 WARN Request returned retryable status, retrying attempt=5 backoff=1ms status=502 url=http://127.0.0.1:51049431--- PASS: TestPathInfoCACompatibility (0.00s)432 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_text (0.00s)433 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_nar_method (0.00s)434 --- PASS: TestPathInfoCACompatibility/old_string_format_-_fixed_recursive (0.00s)435 --- PASS: TestPathInfoCACompatibility/old_string_format_-_text (0.00s)436 --- PASS: TestPathInfoCACompatibility/null_ca_field (0.00s)437--- PASS: TestStreamPushRequestLine (0.03s)438--- PASS: TestRateLimiterFeedback (0.00s)439 --- PASS: TestRateLimiterFeedback/400_does_not_enable_limiter (0.01s)440 --- PASS: TestRateLimiterFeedback/503_enables_limiter (0.00s)441 --- PASS: TestRateLimiterFeedback/429_enables_limiter (0.01s)442 --- PASS: TestRateLimiterFeedback/200_does_not_enable_limiter (0.01s)4432026/10/25 17:15:35 WARN Request returned retryable status, retrying attempt=6 backoff=1ms status=502 url=http://127.0.0.1:510494442026/10/25 17:15:35 WARN Request returned retryable status, retrying attempt=7 backoff=1ms status=502 url=http://127.0.0.1:510494452026/10/25 17:15:35 WARN Request returned retryable status, retrying attempt=8 backoff=1ms status=502 url=http://127.0.0.1:510494462026/10/25 17:15:35 WARN Request returned retryable status, retrying attempt=9 backoff=1ms status=502 url=http://127.0.0.1:510494472026/10/25 17:15:35 WARN Request returned retryable status, retrying attempt=10 backoff=1ms status=502 url=http://127.0.0.1:510494482026/10/25 17:15:35 WARN Request returned retryable status, retrying attempt=11 backoff=1ms status=502 url=http://127.0.0.1:510494492026/10/25 17:15:35 WARN Request returned retryable status, retrying attempt=12 backoff=1ms status=502 url=http://127.0.0.1:510494502026/10/25 17:15:35 WARN Request returned retryable status, retrying attempt=13 backoff=1ms status=502 url=http://127.0.0.1:510494512026/10/25 17:15:35 WARN Request returned retryable status, retrying attempt=14 backoff=1ms status=502 url=http://127.0.0.1:51049452--- PASS: TestRegisterUploadedObjectReusesConnections (0.04s)4532026/10/25 17:15:35 http: TLS handshake error from 127.0.0.1:51111: remote error: tls: bad certificate4542026/10/25 17:15:35 WARN Request returned retryable status, retrying attempt=15 backoff=1ms status=502 url=http://127.0.0.1:51049455--- PASS: TestSetClientTLS (0.02s)456 --- PASS: TestSetClientTLS/preserves_debug_logging_transport (0.01s)457 --- PASS: TestSetClientTLS/succeeds_with_client_cert_and_CA (0.01s)458 --- PASS: TestSetClientTLS/rejects_connection_without_client_cert (0.04s)4592026/10/25 17:15:35 WARN Request returned retryable status, retrying attempt=16 backoff=1ms status=502 url=http://127.0.0.1:510494602026/10/25 17:15:35 WARN Request returned retryable status, retrying attempt=17 backoff=1ms status=502 url=http://127.0.0.1:51049461--- PASS: TestRetryTimeoutOutlastsMaxRetries (0.06s)462--- PASS: TestScriptTokenCachesUntilRefresh (0.10s)463--- PASS: TestStreamPushBatchesUnderLoad (0.11s)464--- PASS: TestScriptTokenNoExpiryRerunsEveryCall (0.11s)465--- PASS: TestDumpPathSingleFile (0.12s)466--- PASS: TestDumpPathWriterError (0.12s)4672026/10/25 17:15:35 INFO Uploading abc-hello (1.0GB)4682026/10/25 17:15:35 WARN Request failed, retrying attempt=1 backoff=100ms error="Put \"http://127.0.0.1:51119/part/2\": uploading part 1: server returned 404: no such upload\n" url=http://127.0.0.1:51119/part/24692026/10/25 17:15:35 ERROR Failed to close zstd encoder error="io: read/write on closed pipe"470--- PASS: TestCaseHackSuffix (0.15s)471--- PASS: TestDumpPathMatchesNix (0.21s)472--- PASS: TestUploadMultipart_FailedPartBufferNotReused (0.60s)473--- PASS: TestUploadMultipart_PartsInParallel (0.64s)474--- PASS: TestSupersededNARStillUploadsListing (0.00s)475 --- PASS: TestSupersededNARStillUploadsListing/listing_upload_fails (0.02s)476 --- PASS: TestSupersededNARStillUploadsListing/small_NAR (0.02s)477 --- PASS: TestSupersededNARStillUploadsListing/dump_cut_short (0.63s)4782026/10/25 17:15:36 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:51039/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:51039/api/uploads/complete4792026/10/25 17:15:36 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:51039/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:51039/api/uploads/complete4802026/10/25 17:15:36 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"4812026/10/25 17:15:36 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:51039/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:51039/api/uploads/complete4822026/10/25 17:15:36 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"4832026/10/25 17:15:36 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"484--- PASS: TestRegisterUploadedObject_BoundedAgainstSilentServer (1.01s)485--- PASS: TestRateLimiterFeedback_400DoesNotCountAsSuccess (1.00s)486PASS487Running server tests...488The files belonging to this database system will be owned by user "_tribuchetbld2".489This user must also own the server process.490491The database cluster will be initialized with locale "C".492The default database encoding has accordingly been set to "SQL_ASCII".493The default text search configuration will be set to "english".494495Data page checksums are enabled.496497creating directory /private/var/tb/2/scratch/e6f8f47991d999ee/build/postgres4037693573/data ... ok498creating subdirectories ... ok499selecting dynamic shared memory implementation ... posix500selecting default "max_connections" ... 100501selecting default "shared_buffers" ... 128MB502selecting default time zone ... UTC503creating configuration files ... ok504running bootstrap script ... ok505performing post-bootstrap initialization ... ok506syncing data to disk ... ok507508initdb: warning: enabling "trust" authentication for local connections509initdb: 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.510511Success. You can now start the database server using:512513 pg_ctl -D /private/var/tb/2/scratch/e6f8f47991d999ee/build/postgres4037693573/data -l logfile start514515/private/var/tb/2/scratch/e6f8f47991d999ee/build/postgres4037693573:5432 - no response5162026-10-25 17:15:37.830 UTC [38183] LOG: starting PostgreSQL 18.6 on aarch64-apple-darwin25.6.0, compiled by clang version 21.1.8, 64-bit5172026-10-25 17:15:37.830 UTC [38183] LOG: listening on Unix socket "/private/var/tb/2/scratch/e6f8f47991d999ee/build/postgres4037693573/.s.PGSQL.5432"5182026-10-25 17:15:37.837 UTC [38190] LOG: database system was shut down at 2026-10-25 17:15:37 UTC5192026-10-25 17:15:37.841 UTC [38183] LOG: database system is ready to accept connections520/private/var/tb/2/scratch/e6f8f47991d999ee/build/postgres4037693573:5432 - accepting connections521{"timestamp":"2026-10-25T17:15:38.083503Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"fc9afefb-6a62-41dd-90c2-41078a1e61f4","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":9,"result":"server_error","target":"rustfs::server::http","filename":"rustfs/src/server/layer.rs","line_number":501,"threadName":"rustfs-worker","threadId":"ThreadId(9)"}522{"timestamp":"2026-10-25T17:15:38.188802Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"21117884-7842-4ed1-b823-bc31bf4837f1","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":501,"threadName":"rustfs-worker","threadId":"ThreadId(2)"}523{"timestamp":"2026-10-25T17:15:38.291735Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"cc485355-a092-4c6e-9f91-b6ed7f1763cb","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":501,"threadName":"rustfs-worker","threadId":"ThreadId(8)"}524{"timestamp":"2026-10-25T17:15:38.393662Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"0b9e20c6-e9d7-4c72-92ae-0cbf98928091","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":501,"threadName":"rustfs-worker","threadId":"ThreadId(6)"}525=== RUN TestService_AuthMiddleware526=== PAUSE TestService_AuthMiddleware527=== RUN TestService_AuthMiddleware_MTLSProxyHeader528=== PAUSE TestService_AuthMiddleware_MTLSProxyHeader529=== RUN TestService_AuthMiddleware_MTLSBoundSubjects530=== PAUSE TestService_AuthMiddleware_MTLSBoundSubjects531=== RUN TestService_ReadAuthMiddleware532=== PAUSE TestService_ReadAuthMiddleware533=== RUN TestService_AuthMiddleware_OIDC534=== PAUSE TestService_AuthMiddleware_OIDC535=== RUN TestService_RequireScope_OIDC536=== PAUSE TestService_RequireScope_OIDC537=== RUN TestService_ReadScope_PublicByDefault538=== PAUSE TestService_ReadScope_PublicByDefault539=== RUN TestCacheConfigHandler540=== PAUSE TestCacheConfigHandler541=== RUN TestCacheStatsHandler542=== PAUSE TestCacheStatsHandler543=== RUN TestClientCADerivations544=== PAUSE TestClientCADerivations545=== RUN TestClientErrorHandling546=== PAUSE TestClientErrorHandling547=== RUN TestClientIntegration548=== PAUSE TestClientIntegration549=== RUN TestClientMultipleUploads550=== PAUSE TestClientMultipleUploads551=== RUN TestClientWithDependencies552=== PAUSE TestClientWithDependencies553=== RUN TestClientSharedPathCommittedMidPush554=== PAUSE TestClientSharedPathCommittedMidPush555=== RUN TestPinProtectsFromGC556=== PAUSE TestPinProtectsFromGC557=== RUN TestClientPushesUseOnePush558=== PAUSE TestClientPushesUseOnePush559=== RUN TestClientFallsBackToClosures560=== PAUSE TestClientFallsBackToClosures561=== RUN TestDeleteClosuresRacingPins562=== PAUSE TestDeleteClosuresRacingPins563=== RUN TestConcurrentCommitsSharingObjectsDoNotDeadlock564=== PAUSE TestConcurrentCommitsSharingObjectsDoNotDeadlock565=== RUN TestResolveDBConnectionString566=== PAUSE TestResolveDBConnectionString567=== RUN TestConnectWaitsForAPeerMigration568=== PAUSE TestConnectWaitsForAPeerMigration569=== RUN TestLeadElectsOneAndHandsOver570=== PAUSE TestLeadElectsOneAndHandsOver571=== RUN TestLeadIncumbentWinsAfterRestart5722026/10/25 17:15:38 INFO lead: acquired remote=192.0.2.1:12345732026/10/25 17:15:39 INFO lead: released remote=192.0.2.1:12345742026/10/25 17:15:39 INFO lead: acquired remote=192.0.2.1:12345752026/10/25 17:15:40 INFO lead: released remote=192.0.2.1:1234576--- PASS: TestLeadIncumbentWinsAfterRestart (2.13s)577=== RUN TestLeadIncumbentAnnouncesAtOnce578=== PAUSE TestLeadIncumbentAnnouncesAtOnce579=== RUN TestLeadEndsOnShutdown580=== PAUSE TestLeadEndsOnShutdown581=== RUN TestLeadEndsWhenItsConnectionHangs5822026/10/25 17:15:40 INFO lead: acquired remote=192.0.2.1:12345832026-10-25 17:15:41.982 UTC [38309] FATAL: terminating connection due to administrator command5842026/10/25 17:15:42 INFO lead: acquired remote=192.0.2.1:12345852026/10/25 17:15:43 WARN lead: lock connection lost error="timeout: context deadline exceeded"5862026/10/25 17:15:43 INFO lead: released remote=192.0.2.1:12345872026/10/25 17:15:43 INFO lead: released remote=192.0.2.1:1234588--- PASS: TestLeadEndsWhenItsConnectionHangs (2.75s)589=== RUN TestGCAdvisoryLockBlocksConcurrentRun590=== PAUSE TestGCAdvisoryLockBlocksConcurrentRun591=== RUN TestGCBugBareHashReferences592=== PAUSE TestGCBugBareHashReferences593=== RUN TestGCMetrics594=== PAUSE TestGCMetrics595=== RUN TestPushDedupSurvivesConcurrentGC596=== PAUSE TestPushDedupSurvivesConcurrentGC597=== RUN TestDeduplicatedObjectsRecordedAsPending598=== PAUSE TestDeduplicatedObjectsRecordedAsPending599=== RUN TestGCSweepSkipsPendingObjects600=== PAUSE TestGCSweepSkipsPendingObjects601=== RUN TestTombstonedObjectOfferedWithoutWaiting602=== PAUSE TestTombstonedObjectOfferedWithoutWaiting603=== RUN TestGCSweepDeliversEachKeyOnce604=== PAUSE TestGCSweepDeliversEachKeyOnce605=== RUN TestCreatePendingClosureVerifyS3FailureReleasesConnection606=== PAUSE TestCreatePendingClosureVerifyS3FailureReleasesConnection607=== RUN TestForceGCDuringPushOffersSweptObject608=== PAUSE TestForceGCDuringPushOffersSweptObject609=== RUN TestFailedS3DeleteKeepsTombstone610=== PAUSE TestFailedS3DeleteKeepsTombstone611=== RUN TestSweepSkipsRowsLockedByPush612=== PAUSE TestSweepSkipsRowsLockedByPush613=== RUN TestRegisterCompletedObjectNeedsPendingRow614=== PAUSE TestRegisterCompletedObjectNeedsPendingRow615=== RUN TestGetExistingObjectsLocksRows616=== PAUSE TestGetExistingObjectsLocksRows617=== RUN TestSweepRechecksPendingAfterLocking618=== PAUSE TestSweepRechecksPendingAfterLocking619=== RUN TestPushWaitsForSweepHoldingRow620=== PAUSE TestPushWaitsForSweepHoldingRow621=== RUN TestCommitRacingPendingCleanupKeepsObjects622=== PAUSE TestCommitRacingPendingCleanupKeepsObjects623=== RUN TestGCEndsOnShutdown624=== PAUSE TestGCEndsOnShutdown625=== RUN TestGCTaskStore_StartNew626=== PAUSE TestGCTaskStore_StartNew627=== RUN TestGCTaskStore_DeduplicateSameParams628=== PAUSE TestGCTaskStore_DeduplicateSameParams629=== RUN TestGCTaskStore_ConflictDifferentParams630=== PAUSE TestGCTaskStore_ConflictDifferentParams631=== RUN TestGCTaskStore_GetEmpty632=== PAUSE TestGCTaskStore_GetEmpty633=== RUN TestGCTaskStore_GetReturnsLatest634=== PAUSE TestGCTaskStore_GetReturnsLatest635=== RUN TestGCTaskStore_CompletedAllowsNewTask636=== PAUSE TestGCTaskStore_CompletedAllowsNewTask637=== RUN TestGCTaskStore_PhaseUpdates638=== PAUSE TestGCTaskStore_PhaseUpdates639=== RUN TestGCTaskStore_Fail640=== PAUSE TestGCTaskStore_Fail641=== RUN TestGracefulShutdownDrainsInflight642=== PAUSE TestGracefulShutdownDrainsInflight643=== RUN TestService_healthCheckHandler644=== PAUSE TestService_healthCheckHandler645=== RUN TestService_readinessHandler646=== PAUSE TestService_readinessHandler647=== RUN TestGenerateLandingPage648=== PAUSE TestGenerateLandingPage649=== RUN TestCacheConfigHandlerMaxNarSize650=== PAUSE TestCacheConfigHandlerMaxNarSize651=== RUN TestCreatePendingClosureRejectsOversizedNAR652=== PAUSE TestCreatePendingClosureRejectsOversizedNAR653=== RUN TestNARDeduplicationMetadataUploadBug654=== PAUSE TestNARDeduplicationMetadataUploadBug655=== RUN TestMetricsInventory656=== PAUSE TestMetricsInventory657=== RUN TestMetricsCommit658=== PAUSE TestMetricsCommit659=== RUN TestService_NativeMTLS660=== PAUSE TestService_NativeMTLS661=== RUN TestServerTLSConfig662=== PAUSE TestServerTLSConfig663=== RUN TestMultipartCleanup664=== PAUSE TestMultipartCleanup665=== RUN TestMultipartUploadAbortedWhenCancelledBeforeRecorded666=== PAUSE TestMultipartUploadAbortedWhenCancelledBeforeRecorded667=== RUN TestPendingCleanupUsesOneCutoff668=== PAUSE TestPendingCleanupUsesOneCutoff669=== RUN TestObjectStatsTrigger670=== PAUSE TestObjectStatsTrigger671=== RUN TestObjectStatsUpdatedOncePerCommit672=== PAUSE TestObjectStatsUpdatedOncePerCommit673=== RUN TestOrphanedObjectsGC674=== PAUSE TestOrphanedObjectsGC675=== RUN TestOrphanedObjectsGCStressTest676=== PAUSE TestOrphanedObjectsGCStressTest677=== RUN TestCreatePin_ReservedPins678=== PAUSE TestCreatePin_ReservedPins679=== RUN TestPresentReportsOnlyClosureRoots680=== PAUSE TestPresentReportsOnlyClosureRoots681=== RUN TestPresentRefreshesOnlyStaleClosures682=== PAUSE TestPresentRefreshesOnlyStaleClosures683=== RUN TestPresentNotReportedWhileGCDeletesClosure684=== PAUSE TestPresentNotReportedWhileGCDeletesClosure685=== RUN TestParseSingleRange686=== PAUSE TestParseSingleRange687=== RUN TestProxyHeadersOnlyTrustedOnSocket6882026/10/25 17:15:43 INFO Starting HTTP server address=127.0.0.1:511766892026/10/25 17:15:43 INFO Starting HTTP server address=proxy.sock6902026/10/25 17:15:43 WARN mTLS auth: subject not in bound subjects subject="CN=someone"6912026/10/25 17:15:43 INFO Shutdown signal received, draining in-flight requests timeout=10s692--- PASS: TestProxyHeadersOnlyTrustedOnSocket (0.19s)693=== RUN TestIsValidCachePath694=== PAUSE TestIsValidCachePath695=== RUN TestReadProxyNarinfo696=== PAUSE TestReadProxyNarinfo697=== RUN TestReadProxyNarinfoAlreadyDecompressed698=== PAUSE TestReadProxyNarinfoAlreadyDecompressed699=== RUN TestReadProxyContentNegotiation700=== PAUSE TestReadProxyContentNegotiation701=== RUN TestReadProxyNarStreaming702=== PAUSE TestReadProxyNarStreaming703=== RUN TestReadProxy404704=== PAUSE TestReadProxy404705=== RUN TestReadProxyInvalidPath706=== PAUSE TestReadProxyInvalidPath707=== RUN TestReadProxyHead708=== PAUSE TestReadProxyHead709=== RUN TestReadProxyOutlastsServerWriteTimeout710=== PAUSE TestReadProxyOutlastsServerWriteTimeout711=== RUN TestReadProxyConditionalGet712=== PAUSE TestReadProxyConditionalGet713=== RUN TestReadProxyRootRedirectsToIndexHTML714=== PAUSE TestReadProxyRootRedirectsToIndexHTML715=== RUN TestReadProxyDisabled716=== PAUSE TestReadProxyDisabled717=== RUN TestReadRedirectNar718=== PAUSE TestReadRedirectNar719=== RUN TestReadRedirectKeepsNarinfoProxied720=== PAUSE TestReadRedirectKeepsNarinfoProxied721=== RUN TestReadProxyRangeRequest722=== PAUSE TestReadProxyRangeRequest723=== RUN TestReadRedirectUsesPublicS3URL724=== PAUSE TestReadRedirectUsesPublicS3URL725=== RUN TestPush_OverlappingRootsStoreOneRowPerKey726=== PAUSE TestPush_OverlappingRootsStoreOneRowPerKey727=== RUN TestPush_CompleteCommitsEveryRoot728=== PAUSE TestPush_CompleteCommitsEveryRoot729=== RUN TestPush_RepeatedRootCommitsOnce730=== PAUSE TestPush_RepeatedRootCommitsOnce731=== RUN TestPush_CompleteWaitsForCleanupOfThePush732=== PAUSE TestPush_CompleteWaitsForCleanupOfThePush733=== RUN TestPush_RootsAreLockedInByteOrder734=== PAUSE TestPush_RootsAreLockedInByteOrder735=== RUN TestPush_SkippedKeySurvivesGCBeforeCommit736=== PAUSE TestPush_SkippedKeySurvivesGCBeforeCommit737=== RUN TestPush_RejectsBadRequests738=== PAUSE TestPush_RejectsBadRequests739=== RUN TestPush_SignsNarinfosOfItsPendingObjects740=== PAUSE TestPush_SignsNarinfosOfItsPendingObjects741=== RUN TestRedundantMultipartUpload742=== PAUSE TestRedundantMultipartUpload743=== RUN TestCompleteMultipartUpload_ErrorButObjectExists744=== PAUSE TestCompleteMultipartUpload_ErrorButObjectExists745=== RUN TestCompletedNarNotReofferedAcrossClosures746=== PAUSE TestCompletedNarNotReofferedAcrossClosures747=== RUN TestPresignedUploadRegisteredBeforeCommit748=== PAUSE TestPresignedUploadRegisteredBeforeCommit749=== RUN TestService_Rustfstest750=== PAUSE TestService_Rustfstest751=== RUN TestParseSize752=== PAUSE TestParseSize753=== RUN TestSkippedUploadsHandler754=== PAUSE TestSkippedUploadsHandler755=== RUN TestSystemdListenerNotActivated756--- PASS: TestSystemdListenerNotActivated (0.00s)757=== RUN TestWatchdogBeatsWhenHealthy758--- PASS: TestWatchdogBeatsWhenHealthy (0.03s)759=== RUN TestWatchdogSkipsWhenUnhealthy7602026/10/25 17:15:43 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7612026/10/25 17:15:43 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7622026/10/25 17:15:43 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7632026/10/25 17:15:43 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7642026/10/25 17:15:43 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7652026/10/25 17:15:43 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7662026/10/25 17:15:43 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7672026/10/25 17:15:43 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7682026/10/25 17:15:43 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7692026/10/25 17:15:43 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"770--- PASS: TestWatchdogSkipsWhenUnhealthy (0.20s)771=== RUN TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle772=== PAUSE TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle773=== RUN TestProxyWriteTimeout774=== PAUSE TestProxyWriteTimeout775=== RUN TestPendingClosureWriteTimeout776=== PAUSE TestPendingClosureWriteTimeout777=== RUN TestIsValidUploadKey778=== PAUSE TestIsValidUploadKey779=== RUN TestUploadHandlersRejectInvalidKeys780=== PAUSE TestUploadHandlersRejectInvalidKeys781=== RUN TestUploadHandlersRejectOversizedBody782=== PAUSE TestUploadHandlersRejectOversizedBody783=== RUN TestService_cleanupPendingClosuresHandler784=== PAUSE TestService_cleanupPendingClosuresHandler785=== RUN TestService_createPendingClosureHandler786=== PAUSE TestService_createPendingClosureHandler787=== RUN TestService_verifyS3Integrity788=== PAUSE TestService_verifyS3Integrity789=== RUN TestCompleteMultipartUnregistered790=== PAUSE TestCompleteMultipartUnregistered791=== RUN TestCreatePendingClosure_SmallNARUsesSimplePUT792=== PAUSE TestCreatePendingClosure_SmallNARUsesSimplePUT793=== CONT TestPush_RejectsBadRequests794=== CONT TestGCTaskStore_CompletedAllowsNewTask795--- PASS: TestGCTaskStore_CompletedAllowsNewTask (0.00s)796=== CONT TestClientCADerivations797=== CONT TestGCTaskStore_DeduplicateSameParams798--- PASS: TestGCTaskStore_DeduplicateSameParams (0.00s)799=== CONT TestForceGCDuringPushOffersSweptObject800=== CONT TestGCTaskStore_GetReturnsLatest801--- PASS: TestGCTaskStore_GetReturnsLatest (0.00s)802=== CONT TestClientPushesUseOnePush803=== CONT TestGCTaskStore_GetEmpty804--- PASS: TestGCTaskStore_GetEmpty (0.00s)805=== CONT TestGCTaskStore_ConflictDifferentParams806--- PASS: TestGCTaskStore_ConflictDifferentParams (0.00s)807=== CONT TestPinProtectsFromGC808=== CONT TestLeadElectsOneAndHandsOver809=== CONT TestGCTaskStore_StartNew810--- PASS: TestGCTaskStore_StartNew (0.00s)811=== CONT TestGCEndsOnShutdown812=== RUN TestGCEndsOnShutdown/before_the_run813=== CONT TestCommitRacingPendingCleanupKeepsObjects814=== PAUSE TestGCEndsOnShutdown/before_the_run815=== RUN TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete816=== CONT TestConnectWaitsForAPeerMigration817=== PAUSE TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete818=== CONT TestResolveDBConnectionString819=== RUN TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark820=== PAUSE TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark821=== CONT TestConcurrentCommitsSharingObjectsDoNotDeadlock822=== CONT TestDeleteClosuresRacingPins823=== CONT TestPushWaitsForSweepHoldingRow824=== CONT TestSweepRechecksPendingAfterLocking825=== CONT TestGetExistingObjectsLocksRows826=== CONT TestRegisterCompletedObjectNeedsPendingRow827=== CONT TestClientFallsBackToClosures828=== CONT TestCacheStatsHandler829=== CONT TestSweepSkipsRowsLockedByPush830=== RUN TestResolveDBConnectionString/flag_wins831=== CONT TestCacheConfigHandler832=== PAUSE TestResolveDBConnectionString/flag_wins833=== CONT TestFailedS3DeleteKeepsTombstone834=== RUN TestResolveDBConnectionString/file_when_flag_empty835=== PAUSE TestResolveDBConnectionString/file_when_flag_empty836=== RUN TestResolveDBConnectionString/missing_file_is_an_error837=== PAUSE TestResolveDBConnectionString/missing_file_is_an_error838=== CONT TestService_AuthMiddleware839=== RUN TestCacheConfigHandler/full_config,_no_issuer840=== PAUSE TestCacheConfigHandler/full_config,_no_issuer841=== RUN TestForceGCDuringPushOffersSweptObject/before_pending_rows842=== RUN TestResolveDBConnectionString/PGHOST_allows_empty843=== CONT TestCreatePendingClosureVerifyS3FailureReleasesConnection844=== CONT TestGCSweepDeliversEachKeyOnce845=== CONT TestClientSharedPathCommittedMidPush846=== PAUSE TestForceGCDuringPushOffersSweptObject/before_pending_rows847=== RUN TestForceGCDuringPushOffersSweptObject/after_presence_check848=== PAUSE TestForceGCDuringPushOffersSweptObject/after_presence_check849=== CONT TestTombstonedObjectOfferedWithoutWaiting850=== PAUSE TestResolveDBConnectionString/PGHOST_allows_empty851=== RUN TestResolveDBConnectionString/nothing_configured852=== RUN TestCacheConfigHandler/no_cache_url_configured853=== PAUSE TestCacheConfigHandler/no_cache_url_configured854=== RUN TestCacheConfigHandler/no_signing_keys855=== PAUSE TestCacheConfigHandler/no_signing_keys856=== RUN TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator857=== PAUSE TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator858=== PAUSE TestResolveDBConnectionString/nothing_configured859=== CONT TestGCSweepSkipsPendingObjects860=== CONT TestGCAdvisoryLockBlocksConcurrentRun8612026/10/25 17:15:45 INFO Aborted multipart uploads count=0 kept=08622026/10/25 17:15:45 WARN Force mode enabled - objects will be deleted immediately without grace period8632026/10/25 17:15:45 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=08642026/10/25 17:15:45 INFO Vacuumed table table=pending_closures8652026/10/25 17:15:45 INFO Vacuumed table table=pending_objects8662026/10/25 17:15:45 INFO Vacuumed table table=multipart_uploads8672026/10/25 17:15:45 INFO Vacuumed table table=closures8682026/10/25 17:15:45 INFO Vacuumed table table=objects8692026/10/25 17:15:45 INFO Aborted multipart uploads count=0 kept=08702026/10/25 17:15:45 WARN Force mode enabled - objects will be deleted immediately without grace period871=== NAME TestClientCADerivations872 client_ca_test.go:136: Built CA derivation: /private/var/tb/2/scratch/e6f8f47991d999ee/build/TestClientCADerivations1520435877/001/store/vggv2mlhrz869q6ds1qjcw22gknphvgf-ca-test8732026/10/25 17:15:45 INFO Aborted multipart uploads count=0 kept=08742026/10/25 17:15:45 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=08752026/10/25 17:15:45 WARN Force mode enabled - objects will be deleted immediately without grace period8762026/10/25 17:15:45 INFO Vacuumed table table=pending_closures8772026/10/25 17:15:45 INFO Vacuumed table table=pending_objects878 client_ca_test.go:139: Found 1 dependencies (including self)8792026/10/25 17:15:45 INFO Vacuumed table table=multipart_uploads8802026/10/25 17:15:45 INFO Vacuumed table table=closures8812026/10/25 17:15:45 INFO Vacuumed table table=objects882--- PASS: TestSweepSkipsRowsLockedByPush (1.67s)883=== CONT TestService_ReadScope_PublicByDefault8842026/10/25 17:15:45 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=08852026/10/25 17:15:45 INFO Vacuumed table table=pending_closures8862026/10/25 17:15:45 INFO Vacuumed table table=pending_objects8872026/10/25 17:15:45 INFO Vacuumed table table=multipart_uploads8882026/10/25 17:15:45 INFO Vacuumed table table=closures8892026/10/25 17:15:45 INFO Vacuumed table table=objects890--- PASS: TestSweepRechecksPendingAfterLocking (1.79s)891=== CONT TestLeadEndsOnShutdown8922026/10/25 17:15:45 INFO Received uploads request method=POST path=/api/pending_closures8932026/10/25 17:15:45 INFO Received push request method=POST path=/api/pushes8942026/10/25 17:15:45 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)8952026/10/25 17:15:45 INFO Uploading vggv2mlhrz869q6ds1qjcw22gknphvgf-ca-test (144B)8962026/10/25 17:15:45 WARN Failed to register uploaded object key=vggv2mlhrz869q6ds1qjcw22gknphvgf.ls error="server returned 404: 404 page not found\n"8972026/10/25 17:15:45 WARN Failed to register uploaded object key=nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst error="server returned 404: 404 page not found\n"8982026/10/25 17:15:45 WARN Failed to register uploaded object key=log/ji33dwyjrsbvj8j81cfir832ykgfrxnj-ca-test.drv error="server returned 404: 404 page not found\n"8992026/10/25 17:15:45 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign9002026/10/25 17:15:45 INFO Signed narinfos id=1 count=19012026/10/25 17:15:45 INFO Uploading 1 narinfos9022026/10/25 17:15:45 INFO Received complete push request method=POST path=/api/pushes/1/complete9032026/10/25 17:15:45 WARN Failed to register uploaded object key=vggv2mlhrz869q6ds1qjcw22gknphvgf.narinfo error="server returned 404: 404 page not found\n"9042026/10/25 17:15:45 INFO Completed push id=1 objects=4 duration=14.928333ms9052026/10/25 17:15:45 INFO Upload complete. (370ms)906=== NAME TestClientCADerivations907 client_ca_test.go:180: Narinfo contains CA field: StorePath: /private/var/tb/2/scratch/e6f8f47991d999ee/build/TestClientCADerivations1520435877/001/store/vggv2mlhrz869q6ds1qjcw22gknphvgf-ca-test908 URL: nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst909 Compression: zstd910 NarHash: sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n911 NarSize: 144912 References: 913 Deriver: /private/var/tb/2/scratch/e6f8f47991d999ee/build/TestClientCADerivations1520435877/001/store/ji33dwyjrsbvj8j81cfir832ykgfrxnj-ca-test.drv914 CA: fixed:r:sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n915 client_ca_test.go:185: Checking for realisation files in S3...9162026/10/25 17:15:45 INFO Aborted multipart uploads count=0 kept=0917 client_ca_test.go:207: No realisation files uploaded - this is expected for locally built CA derivations918 client_ca_test.go:208: Locally built CA derivations don't have DrvOutput IDs until they're substituted from a cache9192026/10/25 17:15:45 WARN Force mode enabled - objects will be deleted immediately without grace period9202026/10/25 17:15:45 ERROR failed to remove object object=nar/dddddddddddddddddddddddddddddddddddddddddddddddddddd.nar.zst error="Access Denied."9212026/10/25 17:15:45 ERROR failed to remove object object=dddddddddddddddddddddddddddddddd.narinfo error="Access Denied."922--- PASS: TestFailedS3DeleteKeepsTombstone (2.12s)923=== CONT TestLeadIncumbentAnnouncesAtOnce9242026/10/25 17:15:46 INFO Received uploads request method=POST path=/api/pending_closures925=== NAME TestClientCADerivations926 client_ca_test.go:258: nix copy output: error: binary cache 's3://bucket5?endpoint=http://localhost:51150®ion=eu-west-1' is for Nix stores with prefix '/nix/store', not '/private/var/tb/2/scratch/e6f8f47991d999ee/build/TestClientCADerivations1520435877/001/store'927 client_ca_test.go:259: nix copy failed (might be expected with isolated stores): exit status 1928--- PASS: TestClientCADerivations (2.27s)929=== CONT TestGCBugBareHashReferences930--- PASS: TestConcurrentCommitsSharingObjectsDoNotDeadlock (2.28s)931=== CONT TestDeduplicatedObjectsRecordedAsPending9322026/10/25 17:15:46 INFO Aborted multipart uploads count=0 kept=09332026/10/25 17:15:46 WARN Force mode enabled - objects will be deleted immediately without grace period9342026/10/25 17:15:46 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=09352026/10/25 17:15:46 INFO Vacuumed table table=pending_closures9362026/10/25 17:15:46 INFO Vacuumed table table=pending_objects9372026/10/25 17:15:46 INFO Vacuumed table table=multipart_uploads9382026/10/25 17:15:46 INFO Vacuumed table table=closures9392026/10/25 17:15:46 INFO Vacuumed table table=objects940--- PASS: TestCommitRacingPendingCleanupKeepsObjects (2.60s)941=== CONT TestClientWithDependencies942--- PASS: TestPushWaitsForSweepHoldingRow (2.73s)943=== CONT TestPushDedupSurvivesConcurrentGC944=== NAME TestPinProtectsFromGC945 client_integration_test.go:731: Pinned store path: /private/var/tb/2/scratch/e6f8f47991d999ee/build/TestPinProtectsFromGC2224978147/001/store/67i18pvly0kwimfxb8ikwn2zm6im4310-pinned-file.txt946 client_integration_test.go:732: Unpinned store path: /private/var/tb/2/scratch/e6f8f47991d999ee/build/TestPinProtectsFromGC2224978147/001/store/g2a6fx1w9p1iy2dgif1c4j1v0sn33jk8-unpinned-file.txt9472026/10/25 17:15:46 INFO Received push request method=POST path=/api/pushes9482026/10/25 17:15:46 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)9492026/10/25 17:15:46 INFO Uploading shgp3m7jfihqjxi4j043b5m79hfbs0vj-b (256B)9502026/10/25 17:15:46 INFO Uploading 01l1niyc6rwicajsrav8c09mnasak6nn-shared-dep (136B)9512026/10/25 17:15:46 WARN Failed to register uploaded object key=nrakiqb626fm5rnsbn062d6cr6n6nfja.ls error="server returned 404: 404 page not found\n"9522026/10/25 17:15:46 WARN Failed to register uploaded object key=shgp3m7jfihqjxi4j043b5m79hfbs0vj.ls error="server returned 404: 404 page not found\n"9532026/10/25 17:15:46 INFO Received push request method=POST path=/api/pushes9542026/10/25 17:15:46 WARN Failed to register uploaded object key=01l1niyc6rwicajsrav8c09mnasak6nn.ls error="server returned 404: 404 page not found\n"9552026/10/25 17:15:46 WARN Failed to register uploaded object key=nar/06jspfhgmrlyp1szhkkpphcxql0l7m96lgrw28s0fzzjx6hdzdn7.nar.zst error="server returned 404: 404 page not found\n"9562026/10/25 17:15:46 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign9572026/10/25 17:15:46 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"9582026/10/25 17:15:46 INFO Signed narinfos id=1 count=39592026/10/25 17:15:46 INFO Uploading 3 narinfos9602026/10/25 17:15:47 WARN Failed to register uploaded object key=shgp3m7jfihqjxi4j043b5m79hfbs0vj.narinfo error="server returned 404: 404 page not found\n"9612026/10/25 17:15:47 WARN Failed to register uploaded object key=01l1niyc6rwicajsrav8c09mnasak6nn.narinfo error="server returned 404: 404 page not found\n"9622026/10/25 17:15:47 INFO Received complete push request method=POST path=/api/pushes/1/complete9632026/10/25 17:15:47 WARN Failed to register uploaded object key=nrakiqb626fm5rnsbn062d6cr6n6nfja.narinfo error="server returned 404: 404 page not found\n"9642026/10/25 17:15:47 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)9652026/10/25 17:15:47 INFO Uploading 67i18pvly0kwimfxb8ikwn2zm6im4310-pinned-file.txt (128B)9662026/10/25 17:15:47 INFO Completed push id=1 objects=8 duration=33.577292ms9672026/10/25 17:15:47 INFO Upload complete. (300ms)968=== NAME TestClientPushesUseOnePush969 client_pushes_test.go:97: Retrieved narinfo from S3:970 StorePath: /private/var/tb/2/scratch/e6f8f47991d999ee/build/TestClientPushesUseOnePush956422819/001/store/01l1niyc6rwicajsrav8c09mnasak6nn-shared-dep971 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst972 Compression: zstd973 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82974 NarSize: 136975 References: 976 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n9772026/10/25 17:15:47 WARN Failed to register uploaded object key=67i18pvly0kwimfxb8ikwn2zm6im4310.ls error="server returned 404: 404 page not found\n"978 client_pushes_test.go:97: Retrieved narinfo from S3:979 StorePath: /private/var/tb/2/scratch/e6f8f47991d999ee/build/TestClientPushesUseOnePush956422819/001/store/nrakiqb626fm5rnsbn062d6cr6n6nfja-a980 URL: nar/06jspfhgmrlyp1szhkkpphcxql0l7m96lgrw28s0fzzjx6hdzdn7.nar.zst981 Compression: zstd982 NarHash: sha256:06jspfhgmrlyp1szhkkpphcxql0l7m96lgrw28s0fzzjx6hdzdn7983 NarSize: 256984 References: /private/var/tb/2/scratch/e6f8f47991d999ee/build/TestClientPushesUseOnePush956422819/001/store/01l1niyc6rwicajsrav8c09mnasak6nn-shared-dep985 CA: text:sha256:1yab05nv6c0zaajq9ymy2fz3ad1hzny5qcr54rcvb2kskq3p9jck986 client_pushes_test.go:97: Retrieved narinfo from S3:987 StorePath: /private/var/tb/2/scratch/e6f8f47991d999ee/build/TestClientPushesUseOnePush956422819/001/store/shgp3m7jfihqjxi4j043b5m79hfbs0vj-b988 URL: nar/06jspfhgmrlyp1szhkkpphcxql0l7m96lgrw28s0fzzjx6hdzdn7.nar.zst989 Compression: zstd990 NarHash: sha256:06jspfhgmrlyp1szhkkpphcxql0l7m96lgrw28s0fzzjx6hdzdn7991 NarSize: 256992 References: /private/var/tb/2/scratch/e6f8f47991d999ee/build/TestClientPushesUseOnePush956422819/001/store/01l1niyc6rwicajsrav8c09mnasak6nn-shared-dep993 CA: text:sha256:1yab05nv6c0zaajq9ymy2fz3ad1hzny5qcr54rcvb2kskq3p9jck9942026/10/25 17:15:47 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign9952026/10/25 17:15:47 WARN Failed to register uploaded object key=nar/0qmhsg42pqsz7x6hh02j8gznnac3yi3qpjhrqbwvz88i194jbb5s.nar.zst error="server returned 404: 404 page not found\n"9962026/10/25 17:15:47 INFO Signed narinfos id=1 count=19972026/10/25 17:15:47 INFO Uploading 1 narinfos998--- PASS: TestRegisterCompletedObjectNeedsPendingRow (3.30s)999=== CONT TestClientMultipleUploads10002026/10/25 17:15:47 INFO Received complete push request method=POST path=/api/pushes/1/complete10012026/10/25 17:15:47 WARN Failed to register uploaded object key=67i18pvly0kwimfxb8ikwn2zm6im4310.narinfo error="server returned 404: 404 page not found\n"10022026/10/25 17:15:47 INFO Completed push id=1 objects=3 duration=18.600625ms10032026/10/25 17:15:47 INFO Upload complete. (311ms)1004--- PASS: TestClientPushesUseOnePush (3.35s)1005=== CONT TestGCMetrics10062026/10/25 17:15:47 INFO Received push request method=POST path=/api/pushes10072026/10/25 17:15:47 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)10082026/10/25 17:15:47 INFO Uploading g2a6fx1w9p1iy2dgif1c4j1v0sn33jk8-unpinned-file.txt (128B)10092026/10/25 17:15:47 WARN Failed to register uploaded object key=g2a6fx1w9p1iy2dgif1c4j1v0sn33jk8.ls error="server returned 404: 404 page not found\n"10102026/10/25 17:15:47 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign10112026/10/25 17:15:47 WARN Failed to register uploaded object key=nar/0gh0wdnr6gmk4r5sfzzh12isnl14rgmkrwy1ws41hpsrlndclg5h.nar.zst error="server returned 404: 404 page not found\n"10122026/10/25 17:15:47 INFO Signed narinfos id=2 count=110132026/10/25 17:15:47 INFO Uploading 1 narinfos10142026/10/25 17:15:47 INFO Received complete push request method=POST path=/api/pushes/2/complete10152026/10/25 17:15:47 WARN Failed to register uploaded object key=g2a6fx1w9p1iy2dgif1c4j1v0sn33jk8.narinfo error="server returned 404: 404 page not found\n"10162026/10/25 17:15:47 INFO Completed push id=2 objects=3 duration=1.675792ms10172026/10/25 17:15:47 INFO Upload complete. (174ms)10182026/10/25 17:15:47 INFO lead: acquired remote=192.0.2.1:123410192026/10/25 17:15:47 INFO Starting cleanup of old closures method=DELETE path=/api/closures10202026/10/25 17:15:47 INFO Garbage collection started10212026/10/25 17:15:47 INFO Aborted multipart uploads count=0 kept=010222026/10/25 17:15:47 WARN Force mode enabled - objects will be deleted immediately without grace period10232026/10/25 17:15:47 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=1 objects-marked-for-deletion=3 objects-deleted-after-grace-period=3 objects-failed-to-delete=010242026/10/25 17:15:47 INFO Vacuumed table table=pending_closures10252026/10/25 17:15:47 INFO Vacuumed table table=pending_objects10262026/10/25 17:15:47 INFO Vacuumed table table=multipart_uploads10272026/10/25 17:15:47 INFO Vacuumed table table=closures10282026/10/25 17:15:47 INFO Vacuumed table table=objects1029=== RUN TestPush_RejectsBadRequests/no_objects1030=== PAUSE TestPush_RejectsBadRequests/no_objects1031=== RUN TestPush_RejectsBadRequests/bad_root1032=== PAUSE TestPush_RejectsBadRequests/bad_root1033=== RUN TestPush_RejectsBadRequests/root_not_in_objects1034=== PAUSE TestPush_RejectsBadRequests/root_not_in_objects1035=== RUN TestPush_RejectsBadRequests/no_roots1036=== PAUSE TestPush_RejectsBadRequests/no_roots1037=== CONT TestClientIntegration10382026/10/25 17:15:47 INFO Received push request method=POST path=/api/pushes10392026/10/25 17:15:47 INFO Uploading 2 paths to 127.0.0.1 (0 already cached)10402026/10/25 17:15:47 INFO Uploading kznypyl1rgl693bqp3k3hs0ri1l95aqi-top (264B)10412026/10/25 17:15:47 INFO Uploading mavlb7l6gp1ri44p8iiv1i7ii3w0y0k0-shared-dep (136B)10422026/10/25 17:15:48 WARN Failed to register uploaded object key=kznypyl1rgl693bqp3k3hs0ri1l95aqi.ls error="server returned 404: 404 page not found\n"10432026/10/25 17:15:48 WARN Failed to register uploaded object key=nar/0gg1a0wpy9jy5by22slr6p7klwsplai9msg740q6ii635n80m9j9.nar.zst error="server returned 404: 404 page not found\n"10442026/10/25 17:15:48 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"10452026/10/25 17:15:48 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign10462026/10/25 17:15:48 WARN Failed to register uploaded object key=mavlb7l6gp1ri44p8iiv1i7ii3w0y0k0.ls error="server returned 404: 404 page not found\n"10472026/10/25 17:15:48 INFO Signed narinfos id=1 count=210482026/10/25 17:15:48 INFO Uploading 2 narinfos10492026/10/25 17:15:48 WARN Failed to register uploaded object key=kznypyl1rgl693bqp3k3hs0ri1l95aqi.narinfo error="server returned 404: 404 page not found\n"10502026/10/25 17:15:48 INFO Received complete push request method=POST path=/api/pushes/1/complete10512026/10/25 17:15:48 WARN Failed to register uploaded object key=mavlb7l6gp1ri44p8iiv1i7ii3w0y0k0.narinfo error="server returned 404: 404 page not found\n"10522026/10/25 17:15:48 INFO Completed push id=1 objects=6 duration=31.779542ms10532026/10/25 17:15:48 INFO Upload complete. (219ms)1054--- PASS: TestCacheStatsHandler (4.30s)1055=== CONT TestClientErrorHandling1056=== RUN TestClientErrorHandling/InvalidStorePath1057=== PAUSE TestClientErrorHandling/InvalidStorePath1058=== RUN TestClientErrorHandling/InvalidAuthToken1059=== PAUSE TestClientErrorHandling/InvalidAuthToken1060=== RUN TestClientErrorHandling/ServerNotAvailable1061=== PAUSE TestClientErrorHandling/ServerNotAvailable1062=== CONT TestProxyWriteTimeout1063=== RUN TestProxyWriteTimeout/narinfo1064=== PAUSE TestProxyWriteTimeout/narinfo1065=== RUN TestProxyWriteTimeout/1_GiB_nar1066=== PAUSE TestProxyWriteTimeout/1_GiB_nar1067=== RUN TestProxyWriteTimeout/10_GiB_nar1068=== PAUSE TestProxyWriteTimeout/10_GiB_nar1069=== RUN TestProxyWriteTimeout/unknown_size1070=== PAUSE TestProxyWriteTimeout/unknown_size1071=== CONT TestCreatePendingClosure_SmallNARUsesSimplePUT1072=== NAME TestClientSharedPathCommittedMidPush1073 client_integration_test.go:680: Retrieved narinfo from S3:1074 StorePath: /private/var/tb/2/scratch/e6f8f47991d999ee/build/TestClientSharedPathCommittedMidPush16869687/001/store/mavlb7l6gp1ri44p8iiv1i7ii3w0y0k0-shared-dep1075 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1076 Compression: zstd1077 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821078 NarSize: 1361079 References: 1080 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1081 client_integration_test.go:680: Retrieved narinfo from S3:1082 StorePath: /private/var/tb/2/scratch/e6f8f47991d999ee/build/TestClientSharedPathCommittedMidPush16869687/001/store/kznypyl1rgl693bqp3k3hs0ri1l95aqi-top1083 URL: nar/0gg1a0wpy9jy5by22slr6p7klwsplai9msg740q6ii635n80m9j9.nar.zst1084 Compression: zstd1085 NarHash: sha256:0gg1a0wpy9jy5by22slr6p7klwsplai9msg740q6ii635n80m9j91086 NarSize: 2641087 References: /private/var/tb/2/scratch/e6f8f47991d999ee/build/TestClientSharedPathCommittedMidPush16869687/001/store/mavlb7l6gp1ri44p8iiv1i7ii3w0y0k0-shared-dep1088 CA: text:sha256:1gqh7p60a6vg15zsvqm3sqs85grwvs5fdjg3gr2rprirzid2jaf51089--- PASS: TestClientSharedPathCommittedMidPush (4.35s)1090=== CONT TestCompleteMultipartUnregistered10912026/10/25 17:15:48 INFO Received uploads request method=POST path=/api/pending_closures10922026/10/25 17:15:48 INFO Aborted multipart uploads count=0 kept=010932026/10/25 17:15:48 WARN Force mode enabled - objects will be deleted immediately without grace period10942026/10/25 17:15: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=010952026/10/25 17:15:48 INFO Vacuumed table table=pending_closures10962026/10/25 17:15:48 INFO Vacuumed table table=pending_objects10972026/10/25 17:15:48 INFO Vacuumed table table=multipart_uploads10982026/10/25 17:15:48 INFO Vacuumed table table=closures10992026/10/25 17:15:48 INFO Vacuumed table table=objects1100--- PASS: TestGCSweepSkipsPendingObjects (4.60s)1101=== CONT TestService_verifyS3Integrity11022026/10/25 17:15:48 ERROR failed to check GC advisory lock error="query pg_locks: failed to connect to `user=_tribuchetbld2 database=niks3`: /nonexistent/.s.PGSQL.5432 (/nonexistent): dial error: dial unix /nonexistent/.s.PGSQL.5432: connect: no such file or directory"1103--- PASS: TestGCAdvisoryLockBlocksConcurrentRun (4.65s)1104=== CONT TestService_createPendingClosureHandler1105--- PASS: TestGetExistingObjectsLocksRows (4.82s)1106=== CONT TestService_cleanupPendingClosuresHandler11072026/10/25 17:15:48 INFO lead: released remote=192.0.2.1:123411082026/10/25 17:15:48 INFO lead: acquired remote=192.0.2.1:123411092026/10/25 17:15:48 INFO Aborted multipart uploads count=0 kept=011102026/10/25 17:15:48 WARN Force mode enabled - objects will be deleted immediately without grace period11112026/10/25 17:15:49 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=011122026/10/25 17:15:49 INFO Vacuumed table table=pending_closures11132026/10/25 17:15:49 INFO Vacuumed table table=pending_objects11142026/10/25 17:15:49 INFO Vacuumed table table=multipart_uploads11152026/10/25 17:15:49 INFO Vacuumed table table=closures11162026/10/25 17:15:49 INFO Vacuumed table table=objects1117--- PASS: TestGCSweepDeliversEachKeyOnce (5.30s)1118=== CONT TestUploadHandlersRejectOversizedBody1119=== RUN TestUploadHandlersRejectOversizedBody/create_pending_closure1120=== PAUSE TestUploadHandlersRejectOversizedBody/create_pending_closure1121=== RUN TestUploadHandlersRejectOversizedBody/complete_multipart1122=== PAUSE TestUploadHandlersRejectOversizedBody/complete_multipart1123=== RUN TestUploadHandlersRejectOversizedBody/request_more_parts1124=== PAUSE TestUploadHandlersRejectOversizedBody/request_more_parts1125=== CONT TestUploadHandlersRejectInvalidKeys1126=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info1127=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info1128=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal1129=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal1130=== RUN TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key1131=== PAUSE TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key1132=== RUN TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key1133=== PAUSE TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key1134=== CONT TestIsValidUploadKey1135=== RUN TestIsValidUploadKey/narinfo1136=== PAUSE TestIsValidUploadKey/narinfo1137=== RUN TestIsValidUploadKey/nar_zst1138=== PAUSE TestIsValidUploadKey/nar_zst1139=== RUN TestIsValidUploadKey/nar_xz1140=== PAUSE TestIsValidUploadKey/nar_xz1141=== RUN TestIsValidUploadKey/nar_plain1142=== PAUSE TestIsValidUploadKey/nar_plain1143=== RUN TestIsValidUploadKey/listing1144=== PAUSE TestIsValidUploadKey/listing1145=== RUN TestIsValidUploadKey/build_log1146=== PAUSE TestIsValidUploadKey/build_log1147=== RUN TestIsValidUploadKey/build_log_home-manager_file1148=== PAUSE TestIsValidUploadKey/build_log_home-manager_file1149=== RUN TestIsValidUploadKey/build_log_plus_in_name1150=== PAUSE TestIsValidUploadKey/build_log_plus_in_name1151=== RUN TestIsValidUploadKey/build_log_question_mark1152=== PAUSE TestIsValidUploadKey/build_log_question_mark1153=== RUN TestIsValidUploadKey/build_log_equals1154=== PAUSE TestIsValidUploadKey/build_log_equals1155=== RUN TestIsValidUploadKey/realisation1156=== PAUSE TestIsValidUploadKey/realisation1157=== RUN TestIsValidUploadKey/realisation_plus_in_output1158=== PAUSE TestIsValidUploadKey/realisation_plus_in_output1159=== RUN TestIsValidUploadKey/nix-cache-info1160=== PAUSE TestIsValidUploadKey/nix-cache-info1161=== RUN TestIsValidUploadKey/index.html1162=== PAUSE TestIsValidUploadKey/index.html1163=== RUN TestIsValidUploadKey/narinfo_key,_nar_type1164=== PAUSE TestIsValidUploadKey/narinfo_key,_nar_type1165=== RUN TestIsValidUploadKey/nar_key,_narinfo_type1166=== PAUSE TestIsValidUploadKey/nar_key,_narinfo_type1167=== RUN TestIsValidUploadKey/listing_key,_narinfo_type1168=== PAUSE TestIsValidUploadKey/listing_key,_narinfo_type1169=== RUN TestIsValidUploadKey/traversal1170=== PAUSE TestIsValidUploadKey/traversal1171=== RUN TestIsValidUploadKey/traversal_nar1172=== PAUSE TestIsValidUploadKey/traversal_nar1173=== RUN TestIsValidUploadKey/absolute1174=== PAUSE TestIsValidUploadKey/absolute1175=== RUN TestIsValidUploadKey/empty_key1176=== PAUSE TestIsValidUploadKey/empty_key1177=== RUN TestIsValidUploadKey/unknown_type1178=== PAUSE TestIsValidUploadKey/unknown_type1179=== CONT TestPendingClosureWriteTimeout1180=== RUN TestPendingClosureWriteTimeout/empty1181=== PAUSE TestPendingClosureWriteTimeout/empty1182=== RUN TestPendingClosureWriteTimeout/400_objects1183=== PAUSE TestPendingClosureWriteTimeout/400_objects1184=== RUN TestPendingClosureWriteTimeout/670k_objects1185=== PAUSE TestPendingClosureWriteTimeout/670k_objects1186=== RUN TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline1187=== PAUSE TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline1188=== CONT TestReadProxyRootRedirectsToIndexHTML11892026/10/25 17:15:49 WARN Authentication failed token_preview=wrongtoken token_length=10 reason="static API token mismatch"1190--- PASS: TestService_AuthMiddleware (5.47s)1191=== CONT TestPush_SkippedKeySurvivesGCBeforeCommit11922026/10/25 17:15:49 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=011932026/10/25 17:15:49 INFO Received create pin request method=POST path=/api/pins/myapp11942026/10/25 17:15:49 INFO Received uploads request method=POST path=/api/pending_closures11952026/10/25 17:15:49 INFO Created/updated pin name=myapp store_path=/private/var/tb/2/scratch/e6f8f47991d999ee/build/TestPinProtectsFromGC2224978147/001/store/67i18pvly0kwimfxb8ikwn2zm6im4310-pinned-file.txt narinfo_key=67i18pvly0kwimfxb8ikwn2zm6im4310.narinfo11962026/10/25 17:15:49 INFO Starting cleanup of old closures method=DELETE path=/api/closures11972026/10/25 17:15:49 INFO Garbage collection started11982026/10/25 17:15:49 INFO Received uploads request method=POST path=/api/pending_closures11992026/10/25 17:15:49 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)12002026/10/25 17:15:49 INFO Aborted multipart uploads count=0 kept=012012026/10/25 17:15:49 INFO Uploading qlgwdhsqapmwjxskwh76n11qjx4mk4wj-shared-dep (136B)12022026/10/25 17:15:49 INFO Uploading njr62xpf6zmpbk31v0nlxl55jq66rb9b-b (256B)12032026/10/25 17:15:49 WARN Force mode enabled - objects will be deleted immediately without grace period12042026/10/25 17:15:49 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=012052026/10/25 17:15:49 INFO Vacuumed table table=pending_closures12062026/10/25 17:15:49 INFO Vacuumed table table=pending_objects12072026/10/25 17:15:49 INFO Vacuumed table table=multipart_uploads12082026/10/25 17:15:49 INFO Vacuumed table table=closures12092026/10/25 17:15:49 INFO Vacuumed table table=objects12102026/10/25 17:15:49 WARN Failed to register uploaded object key=brlpgdmwfyrb8w18z0aj2ak4zpvpmdff.ls error="server returned 404: 404 page not found\n"12112026/10/25 17:15:49 WARN Failed to register uploaded object key=njr62xpf6zmpbk31v0nlxl55jq66rb9b.ls error="server returned 404: 404 page not found\n"12122026/10/25 17:15:49 INFO Received uploads request method=POST path=/api/pending_closures12132026/10/25 17:15:49 WARN Failed to register uploaded object key=qlgwdhsqapmwjxskwh76n11qjx4mk4wj.ls error="server returned 404: 404 page not found\n"12142026/10/25 17:15:49 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"12152026/10/25 17:15:49 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign12162026/10/25 17:15:49 WARN Failed to register uploaded object key=nar/17lid4r250g1vkv5lgzaascggc0zhd4045ikzr98a1lyzsz6v2g1.nar.zst error="server returned 404: 404 page not found\n"12172026/10/25 17:15:49 INFO Signed narinfos id=1 count=212182026/10/25 17:15:49 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign12192026/10/25 17:15:49 INFO Signed narinfos id=2 count=212202026/10/25 17:15:49 INFO Uploading 4 narinfos12212026/10/25 17:15:49 WARN Failed to register uploaded object key=brlpgdmwfyrb8w18z0aj2ak4zpvpmdff.narinfo error="server returned 404: 404 page not found\n"12222026/10/25 17:15:49 WARN Failed to register uploaded object key=qlgwdhsqapmwjxskwh76n11qjx4mk4wj.narinfo error="server returned 404: 404 page not found\n"1223--- PASS: TestDeleteClosuresRacingPins (5.84s)1224=== CONT TestPush_RootsAreLockedInByteOrder12252026/10/25 17:15:49 WARN Failed to register uploaded object key=njr62xpf6zmpbk31v0nlxl55jq66rb9b.narinfo error="server returned 404: 404 page not found\n"12262026/10/25 17:15:49 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete12272026/10/25 17:15:49 WARN Failed to register uploaded object key=qlgwdhsqapmwjxskwh76n11qjx4mk4wj.narinfo error="server returned 404: 404 page not found\n"12282026/10/25 17:15:49 INFO Completed upload id=1 objects=6 duration=21.035042ms12292026/10/25 17:15:49 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete12302026/10/25 17:15:49 INFO Completed upload id=2 objects=6 duration=619.5µs12312026/10/25 17:15:49 INFO Upload complete. (361ms)1232=== NAME TestClientFallsBackToClosures1233 client_pushes_test.go:112: Retrieved narinfo from S3:1234 StorePath: /private/var/tb/2/scratch/e6f8f47991d999ee/build/TestClientFallsBackToClosures538599056/001/store/qlgwdhsqapmwjxskwh76n11qjx4mk4wj-shared-dep1235 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1236 Compression: zstd1237 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821238 NarSize: 1361239 References: 1240 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n12412026/10/25 17:15:49 INFO lead: released remote=192.0.2.1:12341242 client_pushes_test.go:112: Retrieved narinfo from S3:1243 StorePath: /private/var/tb/2/scratch/e6f8f47991d999ee/build/TestClientFallsBackToClosures538599056/001/store/brlpgdmwfyrb8w18z0aj2ak4zpvpmdff-a1244 URL: nar/17lid4r250g1vkv5lgzaascggc0zhd4045ikzr98a1lyzsz6v2g1.nar.zst1245 Compression: zstd1246 NarHash: sha256:17lid4r250g1vkv5lgzaascggc0zhd4045ikzr98a1lyzsz6v2g11247 NarSize: 2561248--- PASS: TestLeadElectsOneAndHandsOver (5.94s)1249=== NAME TestClientFallsBackToClosures1250 References: /private/var/tb/2/scratch/e6f8f47991d999ee/build/TestClientFallsBackToClosures538599056/001/store/qlgwdhsqapmwjxskwh76n11qjx4mk4wj-shared-dep1251 CA: text:sha256:102rnjcb1m3ilr9kdb91zq38kky3q1c1p9wfa4s30vsg0li9n8y11252=== CONT TestService_NativeMTLS1253=== NAME TestClientFallsBackToClosures1254 client_pushes_test.go:112: Retrieved narinfo from S3:1255 StorePath: /private/var/tb/2/scratch/e6f8f47991d999ee/build/TestClientFallsBackToClosures538599056/001/store/njr62xpf6zmpbk31v0nlxl55jq66rb9b-b1256 URL: nar/17lid4r250g1vkv5lgzaascggc0zhd4045ikzr98a1lyzsz6v2g1.nar.zst1257 Compression: zstd1258 NarHash: sha256:17lid4r250g1vkv5lgzaascggc0zhd4045ikzr98a1lyzsz6v2g11259 NarSize: 2561260 References: /private/var/tb/2/scratch/e6f8f47991d999ee/build/TestClientFallsBackToClosures538599056/001/store/qlgwdhsqapmwjxskwh76n11qjx4mk4wj-shared-dep1261 CA: text:sha256:102rnjcb1m3ilr9kdb91zq38kky3q1c1p9wfa4s30vsg0li9n8y11262--- PASS: TestCreatePendingClosureVerifyS3FailureReleasesConnection (5.99s)1263=== CONT TestPush_CompleteWaitsForCleanupOfThePush1264--- PASS: TestClientFallsBackToClosures (6.02s)1265=== CONT TestPush_RepeatedRootCommitsOnce12662026/10/25 17:15:49 INFO Received uploads request method=POST path=/api/pending_closures1267--- PASS: TestTombstonedObjectOfferedWithoutWaiting (6.08s)1268=== CONT TestPush_CompleteCommitsEveryRoot1269--- PASS: TestService_ReadScope_PublicByDefault (4.54s)1270=== CONT TestPush_OverlappingRootsStoreOneRowPerKey12712026/10/25 17:15:50 INFO lead: acquired remote=192.0.2.1:123412722026/10/25 17:15:50 INFO lead: acquired remote=192.0.2.1:123412732026/10/25 17:15:50 INFO lead: released remote=192.0.2.1:12341274--- PASS: TestLeadIncumbentAnnouncesAtOnce (4.53s)1275=== CONT TestReadRedirectUsesPublicS3URL12762026/10/25 17:15:50 INFO Received uploads request method=POST path=/api/pending_closures1277--- PASS: TestDeduplicatedObjectsRecordedAsPending (4.73s)1278=== CONT TestReadProxyRangeRequest1279--- PASS: TestConnectWaitsForAPeerMigration (7.36s)1280=== CONT TestReadRedirectKeepsNarinfoProxied12812026/10/25 17:15:51 INFO lead: released remote=192.0.2.1:12341282--- PASS: TestLeadEndsOnShutdown (5.73s)1283=== CONT TestReadRedirectNar1284--- PASS: TestGCBugBareHashReferences (5.35s)1285=== CONT TestReadProxyDisabled1286=== NAME TestPinProtectsFromGC1287 client_integration_test.go:840: Pin successfully protected closure from garbage collection1288--- PASS: TestPinProtectsFromGC (7.75s)1289=== CONT TestPresentNotReportedWhileGCDeletesClosure1290=== RUN TestPresentNotReportedWhileGCDeletesClosure/stale1291=== PAUSE TestPresentNotReportedWhileGCDeletesClosure/stale1292=== RUN TestPresentNotReportedWhileGCDeletesClosure/fresh1293=== PAUSE TestPresentNotReportedWhileGCDeletesClosure/fresh1294=== CONT TestPresignedUploadRegisteredBeforeCommit1295=== NAME TestClientWithDependencies1296 client_integration_test.go:613: Built derivation: /private/var/tb/2/scratch/e6f8f47991d999ee/build/TestClientWithDependencies1918307986/001/store/7lphxp1b0x40m9x0jj00sh35466ybi6c-test-script12972026/10/25 17:15:52 INFO Received uploads request method=POST path=/api/pending_closures1298 client_integration_test.go:615: Found 1 dependencies (including self)12992026/10/25 17:15:52 INFO Aborted multipart uploads count=0 kept=013002026/10/25 17:15:52 WARN Force mode enabled - objects will be deleted immediately without grace period13012026/10/25 17:15:52 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=013022026/10/25 17:15:52 INFO Vacuumed table table=pending_closures13032026/10/25 17:15:52 INFO Vacuumed table table=pending_objects13042026/10/25 17:15:52 INFO Vacuumed table table=multipart_uploads13052026/10/25 17:15:52 INFO Vacuumed table table=closures13062026/10/25 17:15:52 INFO Vacuumed table table=objects1307--- PASS: TestGCMetrics (5.22s)1308=== CONT TestReadProxyConditionalGet13092026/10/25 17:15:52 INFO Received push request method=POST path=/api/pushes13102026/10/25 17:15:52 INFO Aborted multipart uploads count=0 kept=013112026/10/25 17:15:52 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=013122026/10/25 17:15:52 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)13132026/10/25 17:15:52 INFO Uploading 7lphxp1b0x40m9x0jj00sh35466ybi6c-test-script (136B)13142026/10/25 17:15:52 INFO Vacuumed table table=pending_closures13152026/10/25 17:15:52 WARN Failed to register uploaded object key=7lphxp1b0x40m9x0jj00sh35466ybi6c.ls error="server returned 404: 404 page not found\n"13162026/10/25 17:15:52 WARN Failed to register uploaded object key=nar/1s7yghixzpinyqm7g59kyn3sav81pmnsdi5v63m6x4r2vacy907j.nar.zst error="server returned 404: 404 page not found\n"13172026/10/25 17:15:52 WARN Failed to register uploaded object key=log/pvs30rn7ck2hdy7nw2v0znp490gmliq5-test-script.drv error="server returned 404: 404 page not found\n"13182026/10/25 17:15:52 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign13192026/10/25 17:15:52 INFO Vacuumed table table=pending_objects13202026/10/25 17:15:52 INFO Signed narinfos id=1 count=113212026/10/25 17:15:52 INFO Uploading 1 narinfos13222026/10/25 17:15:52 INFO Vacuumed table table=multipart_uploads13232026/10/25 17:15:52 INFO Vacuumed table table=closures13242026/10/25 17:15:52 INFO Received complete push request method=POST path=/api/pushes/1/complete13252026/10/25 17:15:52 WARN Failed to register uploaded object key=7lphxp1b0x40m9x0jj00sh35466ybi6c.narinfo error="server returned 404: 404 page not found\n"13262026/10/25 17:15:52 INFO Vacuumed table table=objects13272026/10/25 17:15:52 INFO Aborted multipart uploads count=0 kept=013282026/10/25 17:15:52 INFO Completed push id=1 objects=4 duration=58.502917ms13292026/10/25 17:15:52 WARN Force mode enabled - objects will be deleted immediately without grace period13302026/10/25 17:15:52 INFO Upload complete. (457ms)13312026/10/25 17:15:52 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=01332=== NAME TestClientWithDependencies1333 client_integration_test.go:617: Skipping nix copy test - isolated store (/private/var/tb/2/scratch/e6f8f47991d999ee/build/TestClientWithDependencies1918307986/001/store) requires matching store prefix13342026/10/25 17:15:52 INFO Vacuumed table table=pending_closures13352026/10/25 17:15:52 INFO Vacuumed table table=pending_objects13362026/10/25 17:15:52 INFO Vacuumed table table=multipart_uploads13372026/10/25 17:15:52 INFO Vacuumed table table=closures13382026/10/25 17:15:52 INFO Vacuumed table table=objects1339--- PASS: TestPushDedupSurvivesConcurrentGC (6.32s)1340=== CONT TestPresentRefreshesOnlyStaleClosures1341--- PASS: TestClientWithDependencies (6.54s)1342=== CONT TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle1343=== NAME TestClientMultipleUploads1344 client_integration_test.go:358: Created store path 0: /private/var/tb/2/scratch/e6f8f47991d999ee/build/TestClientMultipleUploads3155900361/001/store/m890jcd7cdkh6n61rnwcbsfi9dzd1za9-test-file-0.txt1345 client_integration_test.go:358: Created store path 1: /private/var/tb/2/scratch/e6f8f47991d999ee/build/TestClientMultipleUploads3155900361/001/store/vfw3mq067akybm3z8yrkxmrn5igiqk75-test-file-1.txt1346 client_integration_test.go:358: Created store path 2: /private/var/tb/2/scratch/e6f8f47991d999ee/build/TestClientMultipleUploads3155900361/001/store/3sjnb3nhrzjf6h3hlsj68zh11qc3yxzk-test-file-2.txt1347=== NAME TestClientIntegration1348 client_integration_test.go:286: Created store path: /private/var/tb/2/scratch/e6f8f47991d999ee/build/TestClientIntegration2756976180/002/store/5gly22ls5197j53kf9w247y4qs3hbzsw-test-file.txt13492026/10/25 17:15:53 INFO Received uploads request method=POST path=/api/pending_closures13502026/10/25 17:15:53 INFO Received push request method=POST path=/api/pushes13512026/10/25 17:15:53 INFO Uploading 3 paths to 127.0.0.1 (0 already cached)13522026/10/25 17:15:53 INFO Uploading m890jcd7cdkh6n61rnwcbsfi9dzd1za9-test-file-0.txt (160B)13532026/10/25 17:15:53 INFO Uploading 3sjnb3nhrzjf6h3hlsj68zh11qc3yxzk-test-file-2.txt (160B)13542026/10/25 17:15:53 INFO Uploading vfw3mq067akybm3z8yrkxmrn5igiqk75-test-file-1.txt (160B)1355--- PASS: TestCreatePendingClosure_SmallNARUsesSimplePUT (5.50s)1356=== CONT TestReadProxyOutlastsServerWriteTimeout13572026/10/25 17:15:53 WARN Failed to register uploaded object key=3sjnb3nhrzjf6h3hlsj68zh11qc3yxzk.ls error="server returned 404: 404 page not found\n"13582026/10/25 17:15:53 WARN Failed to register uploaded object key=vfw3mq067akybm3z8yrkxmrn5igiqk75.ls error="server returned 404: 404 page not found\n"13592026/10/25 17:15:53 WARN Failed to register uploaded object key=nar/0ahq3izw3h0b0c08p3xdfclh758fwxnp85ccvflasb4vnfsv50ri.nar.zst error="server returned 404: 404 page not found\n"13602026/10/25 17:15:53 INFO Received push request method=POST path=/api/pushes13612026/10/25 17:15:53 WARN Failed to register uploaded object key=nar/1823g6vx4q5zqvr73m7lkq1wpk40fin7bsc792di430yk7sg4lka.nar.zst error="server returned 404: 404 page not found\n"13622026/10/25 17:15:53 WARN Failed to register uploaded object key=m890jcd7cdkh6n61rnwcbsfi9dzd1za9.ls error="server returned 404: 404 page not found\n"13632026/10/25 17:15:53 WARN Failed to register uploaded object key=nar/13p9pqi0ga6fx2apcwls9hjnv7nmf740ggpn5zvfzdsp5vz2bbg4.nar.zst error="server returned 404: 404 page not found\n"13642026/10/25 17:15:53 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign13652026/10/25 17:15:53 INFO Signed narinfos id=1 count=313662026/10/25 17:15:53 INFO Uploading 3 narinfos13672026/10/25 17:15:53 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)13682026/10/25 17:15:53 INFO Uploading 5gly22ls5197j53kf9w247y4qs3hbzsw-test-file.txt (152B)13692026/10/25 17:15:53 WARN Failed to register uploaded object key=m890jcd7cdkh6n61rnwcbsfi9dzd1za9.narinfo error="server returned 404: 404 page not found\n"13702026/10/25 17:15:53 WARN Failed to register uploaded object key=3sjnb3nhrzjf6h3hlsj68zh11qc3yxzk.narinfo error="server returned 404: 404 page not found\n"13712026/10/25 17:15:53 INFO Received complete push request method=POST path=/api/pushes/1/complete13722026/10/25 17:15:53 WARN Failed to register uploaded object key=vfw3mq067akybm3z8yrkxmrn5igiqk75.narinfo error="server returned 404: 404 page not found\n"13732026/10/25 17:15:53 WARN Failed to register uploaded object key=5gly22ls5197j53kf9w247y4qs3hbzsw.ls error="server returned 404: 404 page not found\n"13742026/10/25 17:15:53 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign13752026/10/25 17:15:53 WARN Failed to register uploaded object key=nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst error="server returned 404: 404 page not found\n"13762026/10/25 17:15:53 INFO Signed narinfos id=1 count=113772026/10/25 17:15:53 INFO Uploading 1 narinfos13782026/10/25 17:15:53 INFO Completed push id=1 objects=9 duration=28.980167ms13792026/10/25 17:15:53 INFO Upload complete. (407ms)1380=== NAME TestClientMultipleUploads1381 client_integration_test.go:369: Uploaded 3 paths in 447.974958ms13822026/10/25 17:15:53 INFO Received complete push request method=POST path=/api/pushes/1/complete13832026/10/25 17:15:53 WARN Failed to register uploaded object key=5gly22ls5197j53kf9w247y4qs3hbzsw.narinfo error="server returned 404: 404 page not found\n"13842026/10/25 17:15:53 INFO Completed push id=1 objects=3 duration=45.017667ms13852026/10/25 17:15:53 INFO Upload complete. (409ms)13862026/10/25 17:15:53 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1387--- PASS: TestClientMultipleUploads (6.85s)1388=== CONT TestPresentReportsOnlyClosureRoots13892026/10/25 17:15:53 ERROR Failed to get multipart upload error="no rows in result set" upload_id=does-not-exist object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst1390--- PASS: TestCompleteMultipartUnregistered (5.82s)1391=== CONT TestSkippedUploadsHandler13922026/10/25 17:15:53 INFO Client skipped oversized paths paths=3 nar_bytes=500000000013932026/10/25 17:15:54 INFO All 1 paths already cached1394--- PASS: TestSkippedUploadsHandler (0.01s)1395=== CONT TestReadProxyHead1396=== NAME TestClientIntegration1397 client_integration_test.go:312: Retrieved narinfo from S3:1398 StorePath: /private/var/tb/2/scratch/e6f8f47991d999ee/build/TestClientIntegration2756976180/002/store/5gly22ls5197j53kf9w247y4qs3hbzsw-test-file.txt1399 URL: nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst1400 Compression: zstd1401 NarHash: sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11402 NarSize: 1521403 References: 1404 CA: fixed:r:sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11405 client_integration_test.go:313: Retrieved .ls file from S3 (compressed size: 77 bytes)1406 client_integration_test.go:313: Decompressed .ls content (64 bytes):1407 {"version":1,"root":{"type":"regular","size":39,"narOffset":96}}1408 client_integration_test.go:316: Testing garbage collection...14092026/10/25 17:15:54 INFO Starting cleanup of old closures method=DELETE path=/api/closures14102026/10/25 17:15:54 INFO Garbage collection started14112026/10/25 17:15:54 INFO Aborted multipart uploads count=0 kept=014122026/10/25 17:15:54 WARN Force mode enabled - objects will be deleted immediately without grace period14132026/10/25 17:15:54 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=014142026/10/25 17:15:54 INFO Vacuumed table table=pending_closures14152026/10/25 17:15:54 INFO Vacuumed table table=pending_objects14162026/10/25 17:15:54 INFO Vacuumed table table=multipart_uploads14172026/10/25 17:15:54 INFO Received uploads request method=POST path=/api/pending_closures14182026/10/25 17:15:54 INFO Vacuumed table table=closures14192026/10/25 17:15:54 INFO Vacuumed table table=objects14202026/10/25 17:15:54 INFO Received uploads request method=POST path=/api/pending_closures14212026/10/25 17:15:54 INFO Received uploads request method=POST path=/api/pending_closures14222026/10/25 17:15:54 INFO Received uploads request method=POST path=/api/pending_closures14232026/10/25 17:15:55 INFO Received cleanup request method=DELETE path=/api/pending_closures14242026/10/25 17:15:55 INFO Aborted multipart uploads count=0 kept=014252026/10/25 17:15:55 INFO Received uploads request method=POST path=/api/pending_closures14262026/10/25 17:15:55 INFO Received cleanup request method=DELETE path=/api/pending_closures14272026/10/25 17:15:55 INFO Aborted multipart uploads count=1 kept=014282026/10/25 17:15:55 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete14292026-10-25 17:15:55.427 UTC [38568] ERROR: Closure does not exist: id=114302026-10-25 17:15:55.427 UTC [38568] CONTEXT: PL/pgSQL function commit_pending_closure(bigint) line 13 at RAISE14312026-10-25 17:15:55.427 UTC [38568] STATEMENT: -- name: CommitPendingClosure :one1432 SELECT commit_pending_closure($1::bigint)::bigint1433 1434--- PASS: TestService_cleanupPendingClosuresHandler (6.80s)1435=== CONT TestParseSize1436--- PASS: TestParseSize (0.00s)1437=== CONT TestReadProxyInvalidPath1438--- PASS: TestReadProxyRootRedirectsToIndexHTML (6.56s)1439=== CONT TestService_Rustfstest14402026/10/25 17:15:56 INFO Received push request method=POST path=/api/pushes14412026/10/25 17:15:56 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=01442=== NAME TestClientIntegration1443 client_integration_test.go:323: Objects in database after GC:1444 client_integration_test.go:323: Successfully deleted all objects with GC --force1445--- PASS: TestClientIntegration (8.32s)1446=== CONT TestReadProxy40414472026/10/25 17:15:56 INFO Received complete push request method=POST path=/api/pushes/1/complete14482026/10/25 17:15:56 INFO Completed push id=1 objects=4 duration=56.231958ms14492026/10/25 17:15:56 INFO Received push request method=POST path=/api/pushes14502026/10/25 17:15:56 INFO Aborted multipart uploads count=0 kept=014512026/10/25 17:15:56 INFO Received push request method=POST path=/api/pushes14522026/10/25 17:15:56 WARN Force mode enabled - objects will be deleted immediately without grace period14532026/10/25 17:15:56 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=014542026/10/25 17:15:56 INFO Received complete multipart upload request method=POST path=/api/multipart/complete14552026/10/25 17:15:56 INFO Vacuumed table table=pending_closures14562026/10/25 17:15:56 INFO Vacuumed table table=pending_objects14572026/10/25 17:15:56 INFO Vacuumed table table=multipart_uploads14582026/10/25 17:15:56 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst upload_id=NzcxZGFhOTYtNDA5Zi00NTNkLWEzYmEtMTc5NWY2MjkzMWM3LmM1YTE5YWFiLTMwYjgtNDgxZS05MzdlLTc5MjAwYzE2ZmM5M3gxNzkyOTQ4NTU0NDE2ODQzMDAw parts=1014592026/10/25 17:15:56 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete14602026/10/25 17:15:56 INFO Vacuumed table table=closures14612026/10/25 17:15:56 INFO Completed upload id=1 objects=2 duration=32.092958ms14622026-10-25 17:15:56.700 UTC [38695] ERROR: could not obtain lock on row in relation "closures"14632026-10-25 17:15:56.700 UTC [38695] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT14642026/10/25 17:15:56 INFO Received uploads request method=POST path=/api/pending_closures14652026-10-25 17:15:56.710 UTC [38695] ERROR: could not obtain lock on row in relation "closures"14662026-10-25 17:15:56.710 UTC [38695] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT14672026/10/25 17:15:56 INFO Vacuumed table table=objects14682026/10/25 17:15:56 INFO Received uploads request method=POST path=/api/pending_closures14692026-10-25 17:15:56.718 UTC [38695] ERROR: could not obtain lock on row in relation "closures"14702026-10-25 17:15:56.718 UTC [38695] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT14712026/10/25 17:15:56 INFO Received complete push request method=POST path=/api/pushes/2/complete14722026-10-25 17:15:56.722 UTC [38695] ERROR: could not obtain lock on row in relation "closures"14732026-10-25 17:15:56.722 UTC [38695] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT14742026/10/25 17:15:56 INFO Object in database but missing from S3 key=dadb44fdadb44fdadb44fdadb44f0000.narinfo14752026-10-25 17:15:56.725 UTC [38695] ERROR: could not obtain lock on row in relation "closures"14762026-10-25 17:15:56.725 UTC [38695] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT14772026/10/25 17:15:56 WARN Found objects in DB but missing from S3, will re-upload count=11478--- PASS: TestService_verifyS3Integrity (8.30s)1479=== CONT TestReadProxyNarStreaming14802026/10/25 17:15:56 INFO Completed push id=2 objects=4 duration=10.541875ms1481--- PASS: TestPush_SkippedKeySurvivesGCBeforeCommit (7.45s)1482=== CONT TestObjectStatsTrigger1483--- PASS: TestPush_RootsAreLockedInByteOrder (7.09s)1484=== CONT TestReadProxyContentNegotiation14852026/10/25 17:15:56 WARN mTLS auth: subject not in bound subjects subject="CN=reader"14862026/10/25 17:15:56 WARN mTLS auth: subject not in bound subjects subject="CN=reader"1487--- PASS: TestService_NativeMTLS (7.09s)1488=== CONT TestOrphanedObjectsGCStressTest14892026/10/25 17:15:56 INFO Received complete multipart upload request method=POST path=/api/multipart/complete14902026/10/25 17:15:57 INFO Completed multipart upload object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst upload_id=NzcxZGFhOTYtNDA5Zi00NTNkLWEzYmEtMTc5NWY2MjkzMWM3LmI5YmQyZDJhLWJlOTgtNDBlZC1iY2IzLTQyMzc4MGIzMGMyNHgxNzkyOTQ4NTU0ODIyNDk2MDAw parts=1014912026/10/25 17:15:57 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete14922026/10/25 17:15:57 INFO Completed upload id=1 objects=2 duration=18.358791ms14932026/10/25 17:15:57 INFO Received get closure request method=GET path=/api/closures/0000000000000000000000000000000014942026/10/25 17:15:57 INFO Received uploads request method=POST path=/api/pending_closures14952026/10/25 17:15:57 INFO Starting cleanup of old closures method=DELETE path=/api/closures14962026/10/25 17:15:57 INFO Aborted multipart uploads count=0 kept=014972026/10/25 17:15:57 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=014982026/10/25 17:15:57 INFO Vacuumed table table=pending_closures14992026/10/25 17:15:57 INFO Vacuumed table table=pending_objects15002026/10/25 17:15:57 INFO Received push request method=POST path=/api/pushes15012026/10/25 17:15:57 INFO Vacuumed table table=multipart_uploads15022026/10/25 17:15:57 INFO Vacuumed table table=closures15032026/10/25 17:15:57 INFO Vacuumed table table=objects15042026/10/25 17:15:57 INFO Received get closure request method=GET path=/api/closures/000000000000000000000000000000001505--- PASS: TestService_createPendingClosureHandler (8.80s)1506=== CONT TestReadProxyNarinfoAlreadyDecompressed15072026/10/25 17:15:57 INFO Received complete push request method=POST path=/api/pushes/1/complete15082026/10/25 17:15:57 INFO Completed push id=1 objects=4 duration=29.448584ms1509--- PASS: TestPush_RepeatedRootCommitsOnce (7.51s)1510=== CONT TestReadProxyNarinfo15112026/10/25 17:15:57 INFO Received push request method=POST path=/api/pushes15122026/10/25 17:15:57 INFO Received push request method=POST path=/api/pushes15132026/10/25 17:15:57 INFO Received complete push request method=POST path=/api/pushes/1/complete15142026-10-25 17:15:57.886 UTC [38717] ERROR: Push does not exist: id=115152026-10-25 17:15:57.886 UTC [38717] CONTEXT: PL/pgSQL function commit_push(bigint) line 11 at RAISE15162026-10-25 17:15:57.886 UTC [38717] STATEMENT: SELECT commit_push($1)1517--- PASS: TestPush_CompleteWaitsForCleanupOfThePush (8.06s)1518=== CONT TestIsValidCachePath1519=== RUN TestIsValidCachePath/narinfo1520=== PAUSE TestIsValidCachePath/narinfo1521=== RUN TestIsValidCachePath/narinfo_all_nix_base32_chars1522=== PAUSE TestIsValidCachePath/narinfo_all_nix_base32_chars1523=== RUN TestIsValidCachePath/nar_zst1524=== PAUSE TestIsValidCachePath/nar_zst1525=== RUN TestIsValidCachePath/nar_xz1526=== PAUSE TestIsValidCachePath/nar_xz1527=== RUN TestIsValidCachePath/nar_bz21528=== PAUSE TestIsValidCachePath/nar_bz21529=== RUN TestIsValidCachePath/nar_uncompressed1530=== PAUSE TestIsValidCachePath/nar_uncompressed1531=== RUN TestIsValidCachePath/ls1532=== PAUSE TestIsValidCachePath/ls1533=== RUN TestIsValidCachePath/log1534=== PAUSE TestIsValidCachePath/log1535=== RUN TestIsValidCachePath/realisation1536=== PAUSE TestIsValidCachePath/realisation1537=== RUN TestIsValidCachePath/nix-cache-info1538=== PAUSE TestIsValidCachePath/nix-cache-info1539=== RUN TestIsValidCachePath/index.html1540=== PAUSE TestIsValidCachePath/index.html1541=== RUN TestIsValidCachePath/traversal_parent1542=== PAUSE TestIsValidCachePath/traversal_parent1543=== RUN TestIsValidCachePath/traversal_in_middle1544=== PAUSE TestIsValidCachePath/traversal_in_middle1545=== RUN TestIsValidCachePath/invalid_char_e1546=== PAUSE TestIsValidCachePath/invalid_char_e1547=== RUN TestIsValidCachePath/invalid_char_u1548=== PAUSE TestIsValidCachePath/invalid_char_u1549=== RUN TestIsValidCachePath/random_path1550=== PAUSE TestIsValidCachePath/random_path1551=== RUN TestIsValidCachePath/empty1552=== PAUSE TestIsValidCachePath/empty1553=== RUN TestIsValidCachePath/leading_slash1554=== PAUSE TestIsValidCachePath/leading_slash1555=== RUN TestIsValidCachePath/wrong_extension1556=== PAUSE TestIsValidCachePath/wrong_extension1557=== RUN TestIsValidCachePath/short_hash1558=== PAUSE TestIsValidCachePath/short_hash1559=== CONT TestParseSingleRange1560=== RUN TestParseSingleRange/none1561=== PAUSE TestParseSingleRange/none1562=== RUN TestParseSingleRange/unknown_unit1563=== PAUSE TestParseSingleRange/unknown_unit1564=== RUN TestParseSingleRange/multi-range_ignored1565=== PAUSE TestParseSingleRange/multi-range_ignored1566=== RUN TestParseSingleRange/malformed_no_dash1567=== PAUSE TestParseSingleRange/malformed_no_dash1568=== RUN TestParseSingleRange/malformed_both_empty1569=== PAUSE TestParseSingleRange/malformed_both_empty1570=== RUN TestParseSingleRange/malformed_end_before_start1571=== PAUSE TestParseSingleRange/malformed_end_before_start1572=== RUN TestParseSingleRange/closed1573=== PAUSE TestParseSingleRange/closed1574=== RUN TestParseSingleRange/open-ended1575=== PAUSE TestParseSingleRange/open-ended1576=== RUN TestParseSingleRange/end_clamped_to_size1577=== PAUSE TestParseSingleRange/end_clamped_to_size1578=== RUN TestParseSingleRange/suffix1579=== PAUSE TestParseSingleRange/suffix1580=== RUN TestParseSingleRange/suffix_exceeds_size1581=== PAUSE TestParseSingleRange/suffix_exceeds_size1582=== RUN TestParseSingleRange/single_byte1583=== PAUSE TestParseSingleRange/single_byte1584=== RUN TestParseSingleRange/start_past_EOF1585=== PAUSE TestParseSingleRange/start_past_EOF1586=== RUN TestParseSingleRange/start_far_past_EOF1587=== PAUSE TestParseSingleRange/start_far_past_EOF1588=== CONT TestService_RequireScope_OIDC15892026/10/25 17:15:57 INFO Completed push id=1 objects=6 duration=53.414875ms1590--- PASS: TestPush_CompleteCommitsEveryRoot (8.02s)1591=== CONT TestCreatePin_ReservedPins15922026/10/25 17:15:57 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:51553/oidc15932026/10/25 17:15:57 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:51555/oidc15942026/10/25 17:15:58 INFO Received push request method=POST path=/api/pushes1595--- PASS: TestPush_OverlappingRootsStoreOneRowPerKey (8.19s)1596=== CONT TestService_AuthMiddleware_OIDC15972026/10/25 17:15:58 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:51565/oidc1598--- PASS: TestReadRedirectUsesPublicS3URL (8.02s)1599=== CONT TestMultipartUploadAbortedWhenCancelledBeforeRecorded1600--- PASS: TestReadProxyRangeRequest (8.02s)1601=== CONT TestMultipartCleanup1602--- PASS: TestReadRedirectKeepsNarinfoProxied (7.96s)1603=== CONT TestService_ReadAuthMiddleware1604--- PASS: TestReadRedirectNar (8.06s)1605=== CONT TestOrphanedObjectsGC1606--- PASS: TestReadProxyDisabled (8.18s)1607=== CONT TestPendingCleanupUsesOneCutoff16082026/10/25 17:15:59 INFO Received uploads request method=POST path=/api/pending_closures16092026/10/25 17:15:59 INFO Registered completed upload object_key=nar/jjjjjjjjjjjjjjjjjjjjjjjjjjjjjj0100000000000000000000.nar.zst16102026/10/25 17:15:59 INFO Received uploads request method=POST path=/api/pending_closures1611--- PASS: TestPresignedUploadRegisteredBeforeCommit (8.41s)1612=== CONT TestService_AuthMiddleware_MTLSBoundSubjects1613--- PASS: TestReadProxyConditionalGet (7.82s)1614=== CONT TestObjectStatsUpdatedOncePerCommit1615--- PASS: TestPresentRefreshesOnlyStaleClosures (7.58s)1616=== CONT TestService_AuthMiddleware_MTLSProxyHeader16172026/10/25 17:16:00 INFO Received uploads request method=POST path=/api/pending_closures16182026/10/25 17:16:01 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1619--- PASS: TestReadProxyHead (7.23s)1620=== CONT TestCompleteMultipartUpload_ErrorButObjectExists1621--- PASS: TestPresentReportsOnlyClosureRoots (7.53s)1622=== CONT TestCompletedNarNotReofferedAcrossClosures1623--- PASS: TestService_Rustfstest (5.95s)1624=== CONT TestGracefulShutdownDrainsInflight16252026/10/25 17:16:01 INFO Starting HTTP server address=127.0.0.1:5161816262026/10/25 17:16:01 INFO Shutdown signal received, draining in-flight requests timeout=10s1627--- PASS: TestGracefulShutdownDrainsInflight (0.07s)1628=== CONT TestNARDeduplicationMetadataUploadBug1629--- PASS: TestReadProxyInvalidPath (6.45s)1630=== CONT TestService_readinessHandler1631--- PASS: TestReadProxy404 (6.28s)1632=== CONT TestMetricsCommit1633--- PASS: TestReadProxyNarStreaming (5.95s)1634=== CONT TestService_healthCheckHandler1635--- PASS: TestReadProxyContentNegotiation (6.40s)1636=== CONT TestMetricsInventory1637--- PASS: TestObjectStatsTrigger (6.70s)1638=== CONT TestCreatePendingClosureRejectsOversizedNAR16392026/10/25 17:16:03 INFO Received uploads request method=POST path=/api/pending_closures1640--- PASS: TestCreatePendingClosureRejectsOversizedNAR (0.00s)1641=== CONT TestCacheConfigHandlerMaxNarSize1642--- PASS: TestCacheConfigHandlerMaxNarSize (0.00s)1643=== CONT TestGCTaskStore_PhaseUpdates1644--- PASS: TestGCTaskStore_PhaseUpdates (0.00s)1645=== CONT TestGenerateLandingPage1646--- PASS: TestGenerateLandingPage (0.00s)1647=== CONT TestGCTaskStore_Fail1648--- PASS: TestGCTaskStore_Fail (0.00s)1649=== CONT TestRedundantMultipartUpload1650--- PASS: TestReadProxyNarinfoAlreadyDecompressed (6.83s)1651=== CONT TestPush_SignsNarinfosOfItsPendingObjects16522026/10/25 17:16:04 WARN Rate limiter enabled after throttle name=s3-test rate=516532026/10/25 17:16:04 WARN S3 rate limit hit operation="complete multipart upload" error="Please reduce your request rate."1654=== NAME TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle1655 throttle_test.go:213: Proxy stats: total=13, throttled=10, completeMultipart=101656 throttle_test.go:215: Rate limiter: enabled=true, rate=5.001657--- PASS: TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle (11.19s)1658=== CONT TestServerTLSConfig1659=== RUN TestServerTLSConfig/no_client_CA1660=== PAUSE TestServerTLSConfig/no_client_CA1661=== RUN TestServerTLSConfig/missing_CA_file1662=== PAUSE TestServerTLSConfig/missing_CA_file1663=== RUN TestServerTLSConfig/not_a_PEM_file1664=== PAUSE TestServerTLSConfig/not_a_PEM_file1665=== CONT TestGCEndsOnShutdown/before_the_run16662026/10/25 17:16:04 ERROR Failed to decode narinfo key=3hcdxyjf9yiq7qf3i4548drb6sjmwa1v.narinfo limit=16777216 error=<nil>1667--- PASS: TestReadProxyNarinfo (7.28s)1668=== CONT TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark1669=== RUN TestService_RequireScope_OIDC/builder_may_write1670=== PAUSE TestService_RequireScope_OIDC/builder_may_write1671=== RUN TestService_RequireScope_OIDC/builder_may_not_admin1672=== PAUSE TestService_RequireScope_OIDC/builder_may_not_admin1673=== RUN TestService_RequireScope_OIDC/ops_may_admin1674=== PAUSE TestService_RequireScope_OIDC/ops_may_admin1675=== RUN TestService_RequireScope_OIDC/ops_may_not_write1676=== PAUSE TestService_RequireScope_OIDC/ops_may_not_write1677=== RUN TestService_RequireScope_OIDC/reader_may_not_write1678=== PAUSE TestService_RequireScope_OIDC/reader_may_not_write1679=== RUN TestService_RequireScope_OIDC/static_token_may_admin1680=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin1681=== RUN TestService_RequireScope_OIDC/static_token_may_write1682=== PAUSE TestService_RequireScope_OIDC/static_token_may_write1683=== RUN TestService_RequireScope_OIDC/reader_may_read1684=== PAUSE TestService_RequireScope_OIDC/reader_may_read1685=== RUN TestService_RequireScope_OIDC/writer_implies_read1686=== PAUSE TestService_RequireScope_OIDC/writer_implies_read1687=== RUN TestService_RequireScope_OIDC/anonymous_may_not_read1688=== PAUSE TestService_RequireScope_OIDC/anonymous_may_not_read1689=== RUN TestService_RequireScope_OIDC/reader_may_read_with_netrc1690=== PAUSE TestService_RequireScope_OIDC/reader_may_read_with_netrc1691=== RUN TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1692=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1693=== RUN TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read1694=== PAUSE TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read1695=== RUN TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1696=== PAUSE TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1697=== CONT TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete1698--- PASS: TestReadProxyOutlastsServerWriteTimeout (11.60s)1699=== CONT TestForceGCDuringPushOffersSweptObject/before_pending_rows17002026/10/25 17:16:05 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux17012026/10/25 17:16:05 WARN Refused reserved pin name=worker-x86_64-linux17022026/10/25 17:16:05 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux17032026/10/25 17:16:05 INFO Received create pin request method=POST path=/api/pins/my-app17042026/10/25 17:16:05 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux1705--- PASS: TestCreatePin_ReservedPins (7.68s)1706=== CONT TestForceGCDuringPushOffersSweptObject/after_presence_check1707=== RUN TestService_AuthMiddleware_OIDC/valid_OIDC_token1708=== PAUSE TestService_AuthMiddleware_OIDC/valid_OIDC_token1709=== RUN TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1710=== PAUSE TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1711=== RUN TestService_AuthMiddleware_OIDC/malformed_token_rejected1712=== PAUSE TestService_AuthMiddleware_OIDC/malformed_token_rejected1713=== RUN TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1714=== PAUSE TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1715=== CONT TestCacheConfigHandler/full_config,_no_issuer1716=== CONT TestResolveDBConnectionString/flag_wins1717=== CONT TestCacheConfigHandler/no_signing_keys1718=== CONT TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1719=== CONT TestCacheConfigHandler/no_cache_url_configured1720--- PASS: TestCacheConfigHandler (0.00s)1721 --- PASS: TestCacheConfigHandler/full_config,_no_issuer (0.00s)1722 --- PASS: TestCacheConfigHandler/no_signing_keys (0.00s)1723 --- PASS: TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator (0.00s)1724 --- PASS: TestCacheConfigHandler/no_cache_url_configured (0.00s)1725=== CONT TestResolveDBConnectionString/PGHOST_allows_empty1726=== CONT TestResolveDBConnectionString/nothing_configured1727=== CONT TestResolveDBConnectionString/missing_file_is_an_error1728=== CONT TestResolveDBConnectionString/file_when_flag_empty1729=== CONT TestPush_RejectsBadRequests/no_objects17302026/10/25 17:16:06 INFO Received push request method=POST path=/api/pushes1731=== CONT TestPush_RejectsBadRequests/root_not_in_objects17322026/10/25 17:16:06 INFO Received push request method=POST path=/api/pushes1733=== CONT TestPush_RejectsBadRequests/no_roots17342026/10/25 17:16:06 INFO Received push request method=POST path=/api/pushes1735=== CONT TestPush_RejectsBadRequests/bad_root17362026/10/25 17:16:06 INFO Received push request method=POST path=/api/pushes1737--- PASS: TestResolveDBConnectionString (0.03s)1738 --- PASS: TestResolveDBConnectionString/flag_wins (0.00s)1739 --- PASS: TestResolveDBConnectionString/PGHOST_allows_empty (0.00s)1740 --- PASS: TestResolveDBConnectionString/nothing_configured (0.00s)1741 --- PASS: TestResolveDBConnectionString/missing_file_is_an_error (0.00s)1742 --- PASS: TestResolveDBConnectionString/file_when_flag_empty (0.00s)1743=== CONT TestClientErrorHandling/InvalidStorePath1744--- PASS: TestPush_RejectsBadRequests (4.05s)1745 --- PASS: TestPush_RejectsBadRequests/no_objects (0.00s)1746 --- PASS: TestPush_RejectsBadRequests/root_not_in_objects (0.00s)1747 --- PASS: TestPush_RejectsBadRequests/no_roots (0.00s)1748 --- PASS: TestPush_RejectsBadRequests/bad_root (0.01s)17492026/10/25 17:16:06 INFO Received uploads request method=POST path=/api/pending_closures1750--- PASS: TestMultipartUploadAbortedWhenCancelledBeforeRecorded (8.43s)1751=== CONT TestProxyWriteTimeout/narinfo1752=== CONT TestClientErrorHandling/ServerNotAvailable17532026/10/25 17:16:07 INFO Received uploads request method=POST path=/api/pending_closures17542026/10/25 17:16:07 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/present17552026/10/25 17:16:07 INFO Received cleanup request method=DELETE path=/api/pending_closures17562026/10/25 17:16:07 WARN Failed to abort upload, keeping its closure key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst error="Get \"http://127.0.0.1:1/bucket75/?location=\": dial tcp 127.0.0.1:1: connect: connection refused" code=""17572026/10/25 17:16:07 INFO Aborted multipart uploads count=0 kept=117582026/10/25 17:16:07 INFO Received cleanup request method=DELETE path=/api/pending_closures17592026/10/25 17:16:07 WARN Request failed, retrying attempt=2 backoff=209.783953ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present17602026/10/25 17:16:07 INFO Aborted multipart uploads count=1 kept=01761--- PASS: TestMultipartCleanup (8.92s)1762=== CONT TestClientErrorHandling/InvalidAuthToken17632026/10/25 17:16:07 WARN Request failed, retrying attempt=3 backoff=425.158642ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present1764--- PASS: TestService_ReadAuthMiddleware (8.89s)1765=== CONT TestProxyWriteTimeout/10_GiB_nar1766=== CONT TestProxyWriteTimeout/unknown_size1767=== CONT TestProxyWriteTimeout/1_GiB_nar1768--- PASS: TestProxyWriteTimeout (0.00s)1769 --- PASS: TestProxyWriteTimeout/narinfo (0.00s)1770 --- PASS: TestProxyWriteTimeout/10_GiB_nar (0.00s)1771 --- PASS: TestProxyWriteTimeout/unknown_size (0.00s)1772 --- PASS: TestProxyWriteTimeout/1_GiB_nar (0.00s)1773=== CONT TestUploadHandlersRejectOversizedBody/create_pending_closure17742026/10/25 17:16:08 INFO Received uploads request method=POST path=/17752026/10/25 17:16:08 WARN Request failed, retrying attempt=4 backoff=857.239463ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present1776=== CONT TestUploadHandlersRejectOversizedBody/request_more_parts17772026/10/25 17:16:08 INFO Received request for more parts method=POST path=/1778=== CONT TestUploadHandlersRejectOversizedBody/complete_multipart17792026/10/25 17:16:08 INFO Received complete multipart upload request method=POST path=/1780=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info17812026/10/25 17:16:08 INFO Received uploads request method=POST path=/1782=== CONT TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key17832026/10/25 17:16:08 INFO Received complete multipart upload request method=POST path=/1784=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal17852026/10/25 17:16:08 INFO Received uploads request method=POST path=/1786=== CONT TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key17872026/10/25 17:16:08 INFO Received request for more parts method=POST path=/1788--- PASS: TestUploadHandlersRejectOversizedBody (0.03s)1789 --- PASS: TestUploadHandlersRejectOversizedBody/create_pending_closure (0.34s)1790 --- PASS: TestUploadHandlersRejectOversizedBody/request_more_parts (0.04s)1791 --- PASS: TestUploadHandlersRejectOversizedBody/complete_multipart (0.02s)1792=== CONT TestIsValidUploadKey/narinfo1793=== CONT TestIsValidUploadKey/realisation_plus_in_output1794=== CONT TestIsValidUploadKey/unknown_type1795=== CONT TestIsValidUploadKey/empty_key1796=== CONT TestIsValidUploadKey/absolute1797--- PASS: TestUploadHandlersRejectInvalidKeys (0.00s)1798 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info (0.00s)1799 --- PASS: TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key (0.00s)1800 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal (0.00s)1801 --- PASS: TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key (0.01s)1802=== CONT TestIsValidUploadKey/traversal_nar1803=== CONT TestIsValidUploadKey/traversal1804=== CONT TestIsValidUploadKey/listing_key,_narinfo_type1805=== CONT TestIsValidUploadKey/nar_key,_narinfo_type1806=== CONT TestIsValidUploadKey/narinfo_key,_nar_type1807=== CONT TestIsValidUploadKey/index.html1808=== CONT TestIsValidUploadKey/nix-cache-info1809=== CONT TestIsValidUploadKey/build_log_home-manager_file1810=== CONT TestIsValidUploadKey/realisation1811=== CONT TestIsValidUploadKey/build_log_equals1812=== CONT TestIsValidUploadKey/build_log_question_mark1813=== CONT TestIsValidUploadKey/build_log_plus_in_name1814=== CONT TestIsValidUploadKey/nar_plain1815=== CONT TestIsValidUploadKey/build_log1816=== CONT TestIsValidUploadKey/listing1817=== CONT TestIsValidUploadKey/nar_xz1818=== CONT TestIsValidUploadKey/nar_zst1819--- PASS: TestIsValidUploadKey (0.00s)1820 --- PASS: TestIsValidUploadKey/narinfo (0.00s)1821 --- PASS: TestIsValidUploadKey/realisation_plus_in_output (0.00s)1822 --- PASS: TestIsValidUploadKey/unknown_type (0.00s)1823 --- PASS: TestIsValidUploadKey/empty_key (0.00s)1824 --- PASS: TestIsValidUploadKey/absolute (0.00s)1825 --- PASS: TestIsValidUploadKey/traversal_nar (0.00s)1826 --- PASS: TestIsValidUploadKey/traversal (0.00s)1827 --- PASS: TestIsValidUploadKey/listing_key,_narinfo_type (0.00s)1828 --- PASS: TestIsValidUploadKey/nar_key,_narinfo_type (0.00s)1829 --- PASS: TestIsValidUploadKey/narinfo_key,_nar_type (0.00s)1830 --- PASS: TestIsValidUploadKey/index.html (0.00s)1831 --- PASS: TestIsValidUploadKey/nix-cache-info (0.00s)1832 --- PASS: TestIsValidUploadKey/build_log_home-manager_file (0.00s)1833 --- PASS: TestIsValidUploadKey/realisation (0.00s)1834 --- PASS: TestIsValidUploadKey/build_log_equals (0.00s)1835 --- PASS: TestIsValidUploadKey/build_log_question_mark (0.00s)1836 --- PASS: TestIsValidUploadKey/build_log_plus_in_name (0.00s)1837 --- PASS: TestIsValidUploadKey/nar_plain (0.00s)1838 --- PASS: TestIsValidUploadKey/build_log (0.00s)1839 --- PASS: TestIsValidUploadKey/listing (0.00s)1840 --- PASS: TestIsValidUploadKey/nar_xz (0.00s)1841 --- PASS: TestIsValidUploadKey/nar_zst (0.00s)1842=== CONT TestPendingClosureWriteTimeout/empty1843=== CONT TestPendingClosureWriteTimeout/670k_objects1844=== CONT TestPendingClosureWriteTimeout/400_objects1845=== CONT TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline18462026/10/25 17:16:09 WARN Request failed, retrying attempt=5 backoff=1.525676331s error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present18472026/10/25 17:16:09 INFO Received uploads request method=POST path=/api/pending_closures18482026/10/25 17:16:09 INFO Received uploads request method=POST path=/api/pending_closures18492026/10/25 17:16:09 INFO Received cleanup request method=DELETE path=/api/pending_closures18502026/10/25 17:16:10 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted,O=Other"18512026/10/25 17:16:10 WARN mTLS auth: bound subjects configured but subject DN unavailable18522026/10/25 17:16:10 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted"1853--- PASS: TestService_AuthMiddleware_MTLSBoundSubjects (10.25s)1854=== CONT TestPresentNotReportedWhileGCDeletesClosure/stale18552026/10/25 17:16:10 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-config18562026/10/25 17:16:10 WARN Request failed, retrying attempt=2 backoff=184.503163ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config18572026/10/25 17:16:11 WARN Request failed, retrying attempt=3 backoff=405.670234ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config1858=== NAME TestOrphanedObjectsGC1859 orphaned_objects_gc_test.go:287: GC Test Summary:1860 orphaned_objects_gc_test.go:288: - Kept: 2 objects from closure A1861 orphaned_objects_gc_test.go:289: - Deleted: 2 objects from closure B1862 orphaned_objects_gc_test.go:290: - Deleted: 6 orphaned chain objects (X1->X2->X3)1863 orphaned_objects_gc_test.go:291: - Deleted: 2 orphaned single objects (Y)1864 orphaned_objects_gc_test.go:292: - Total deleted: 10 objects1865--- PASS: TestOrphanedObjectsGC (12.12s)1866=== CONT TestPresentNotReportedWhileGCDeletesClosure/fresh18672026/10/25 17:16:11 WARN Request failed, retrying attempt=4 backoff=801.767095ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config1868--- PASS: TestService_AuthMiddleware_MTLSProxyHeader (11.27s)1869=== CONT TestIsValidCachePath/narinfo1870=== CONT TestIsValidCachePath/short_hash1871--- PASS: TestObjectStatsUpdatedOncePerCommit (11.53s)1872=== CONT TestIsValidCachePath/index.html1873=== CONT TestIsValidCachePath/wrong_extension1874=== CONT TestIsValidCachePath/leading_slash1875=== CONT TestIsValidCachePath/empty1876=== CONT TestIsValidCachePath/random_path1877=== CONT TestIsValidCachePath/invalid_char_u1878=== CONT TestIsValidCachePath/invalid_char_e1879=== CONT TestIsValidCachePath/traversal_parent1880=== CONT TestIsValidCachePath/nar_uncompressed1881=== CONT TestIsValidCachePath/traversal_in_middle1882=== CONT TestIsValidCachePath/realisation1883=== CONT TestIsValidCachePath/log1884=== CONT TestIsValidCachePath/ls1885=== CONT TestIsValidCachePath/nar_xz1886=== CONT TestIsValidCachePath/nar_bz21887=== CONT TestIsValidCachePath/nix-cache-info1888=== CONT TestIsValidCachePath/narinfo_all_nix_base32_chars1889=== CONT TestIsValidCachePath/nar_zst1890=== CONT TestParseSingleRange/none1891--- PASS: TestIsValidCachePath (0.00s)1892 --- PASS: TestIsValidCachePath/narinfo (0.00s)1893 --- PASS: TestIsValidCachePath/index.html (0.00s)1894 --- PASS: TestIsValidCachePath/wrong_extension (0.00s)1895 --- PASS: TestIsValidCachePath/leading_slash (0.00s)1896 --- PASS: TestIsValidCachePath/empty (0.00s)1897 --- PASS: TestIsValidCachePath/random_path (0.00s)1898 --- PASS: TestIsValidCachePath/invalid_char_u (0.00s)1899 --- PASS: TestIsValidCachePath/short_hash (0.00s)1900 --- PASS: TestIsValidCachePath/invalid_char_e (0.00s)1901 --- PASS: TestIsValidCachePath/traversal_parent (0.00s)1902 --- PASS: TestIsValidCachePath/nar_uncompressed (0.00s)1903 --- PASS: TestIsValidCachePath/traversal_in_middle (0.00s)1904 --- PASS: TestIsValidCachePath/realisation (0.00s)1905 --- PASS: TestIsValidCachePath/log (0.00s)1906 --- PASS: TestIsValidCachePath/ls (0.00s)1907 --- PASS: TestIsValidCachePath/nar_xz (0.00s)1908 --- PASS: TestIsValidCachePath/nar_bz2 (0.00s)1909 --- PASS: TestIsValidCachePath/nix-cache-info (0.00s)1910 --- PASS: TestIsValidCachePath/narinfo_all_nix_base32_chars (0.00s)1911 --- PASS: TestIsValidCachePath/nar_zst (0.00s)1912=== CONT TestParseSingleRange/open-ended1913=== CONT TestParseSingleRange/start_past_EOF1914=== CONT TestParseSingleRange/single_byte1915=== CONT TestParseSingleRange/start_far_past_EOF1916=== CONT TestParseSingleRange/suffix_exceeds_size1917=== CONT TestParseSingleRange/suffix1918=== CONT TestParseSingleRange/end_clamped_to_size1919=== CONT TestParseSingleRange/malformed_both_empty1920=== CONT TestParseSingleRange/closed1921=== CONT TestParseSingleRange/malformed_end_before_start1922=== CONT TestParseSingleRange/multi-range_ignored1923=== CONT TestParseSingleRange/malformed_no_dash1924=== CONT TestParseSingleRange/unknown_unit1925=== CONT TestServerTLSConfig/missing_CA_file1926=== CONT TestServerTLSConfig/no_client_CA1927=== CONT TestServerTLSConfig/not_a_PEM_file1928=== CONT TestService_RequireScope_OIDC/builder_may_write1929--- PASS: TestParseSingleRange (0.00s)1930 --- PASS: TestParseSingleRange/none (0.00s)1931 --- PASS: TestParseSingleRange/open-ended (0.00s)1932 --- PASS: TestParseSingleRange/start_past_EOF (0.00s)1933 --- PASS: TestParseSingleRange/start_far_past_EOF (0.00s)1934 --- PASS: TestParseSingleRange/suffix_exceeds_size (0.00s)1935 --- PASS: TestParseSingleRange/suffix (0.00s)1936 --- PASS: TestParseSingleRange/end_clamped_to_size (0.00s)1937 --- PASS: TestParseSingleRange/malformed_both_empty (0.00s)1938 --- PASS: TestParseSingleRange/closed (0.00s)1939 --- PASS: TestParseSingleRange/malformed_end_before_start (0.00s)1940 --- PASS: TestParseSingleRange/multi-range_ignored (0.00s)1941 --- PASS: TestParseSingleRange/single_byte (0.00s)1942 --- PASS: TestParseSingleRange/malformed_no_dash (0.00s)1943 --- PASS: TestParseSingleRange/unknown_unit (0.00s)1944=== CONT TestService_RequireScope_OIDC/reader_may_read1945=== CONT TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1946=== CONT TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read19472026/10/25 17:16:11 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]1948=== CONT TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1949=== CONT TestService_RequireScope_OIDC/reader_may_read_with_netrc1950=== CONT TestService_RequireScope_OIDC/anonymous_may_not_read1951=== CONT TestService_RequireScope_OIDC/writer_implies_read1952=== CONT TestService_RequireScope_OIDC/reader_may_not_write1953=== CONT TestService_RequireScope_OIDC/static_token_may_write1954=== CONT TestService_RequireScope_OIDC/static_token_may_admin1955--- PASS: TestServerTLSConfig (0.00s)1956 --- PASS: TestServerTLSConfig/no_client_CA (0.00s)1957 --- PASS: TestServerTLSConfig/missing_CA_file (0.00s)1958 --- PASS: TestServerTLSConfig/not_a_PEM_file (0.04s)1959=== CONT TestService_RequireScope_OIDC/ops_may_admin1960=== CONT TestService_RequireScope_OIDC/ops_may_not_write1961=== CONT TestService_RequireScope_OIDC/builder_may_not_admin1962=== CONT TestService_AuthMiddleware_OIDC/valid_OIDC_token1963=== CONT TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1964=== CONT TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1965=== CONT TestService_AuthMiddleware_OIDC/malformed_token_rejected19662026/10/25 17:16:11 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]1967--- PASS: TestService_RequireScope_OIDC (7.13s)1968 --- PASS: TestService_RequireScope_OIDC/builder_may_write (0.00s)1969 --- PASS: TestService_RequireScope_OIDC/reader_may_read (0.00s)1970 --- PASS: TestService_RequireScope_OIDC/empty_netrc_password_may_not_read (0.00s)1971 --- PASS: TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read (0.00s)1972 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin_with_netrc (0.00s)1973 --- PASS: TestService_RequireScope_OIDC/reader_may_read_with_netrc (0.00s)1974 --- PASS: TestService_RequireScope_OIDC/anonymous_may_not_read (0.00s)1975 --- PASS: TestService_RequireScope_OIDC/writer_implies_read (0.00s)1976 --- PASS: TestService_RequireScope_OIDC/reader_may_not_write (0.00s)1977 --- PASS: TestService_RequireScope_OIDC/static_token_may_write (0.00s)1978 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin (0.00s)1979 --- PASS: TestService_RequireScope_OIDC/ops_may_admin (0.00s)1980 --- PASS: TestService_RequireScope_OIDC/ops_may_not_write (0.00s)1981 --- PASS: TestService_RequireScope_OIDC/builder_may_not_admin (0.00s)19822026/10/25 17:16:11 WARN Authentication failed token_preview=eyJhbGciOi...kQMCzL29LA token_length=701 oidc_error="no rule matched: claim \"repository_owner\" value [otherorg] not in allowed patterns [myorg]" oidc_provider=test tried_providers=[test]1983--- PASS: TestService_AuthMiddleware_OIDC (7.90s)1984 --- PASS: TestService_AuthMiddleware_OIDC/valid_OIDC_token (0.01s)1985 --- PASS: TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured (0.00s)1986 --- PASS: TestService_AuthMiddleware_OIDC/malformed_token_rejected (0.00s)1987 --- PASS: TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected (0.01s)19882026/10/25 17:16:12 WARN Request failed, retrying attempt=5 backoff=1.515887097s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config19892026/10/25 17:16:12 INFO Received uploads request method=POST path=/api/pending_closures19902026/10/25 17:16:13 INFO Received uploads request method=POST path=/api/pending_closures19912026/10/25 17:16:13 INFO Received complete multipart upload request method=POST path=/api/multipart/complete19922026/10/25 17:16:13 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified key does not exist." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=NzcxZGFhOTYtNDA5Zi00NTNkLWEzYmEtMTc5NWY2MjkzMWM3LmUxYzhmOTY5LTFmZWUtNDc1ZS05ODA3LWNhNzU3NGQ0MWEwYXgxNzkyOTQ4NTcyNjI5MjU3MDAw19932026/10/25 17:16:13 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=NzcxZGFhOTYtNDA5Zi00NTNkLWEzYmEtMTc5NWY2MjkzMWM3LmUxYzhmOTY5LTFmZWUtNDc1ZS05ODA3LWNhNzU3NGQ0MWEwYXgxNzkyOTQ4NTcyNjI5MjU3MDAw parts=11994--- PASS: TestCompleteMultipartUpload_ErrorButObjectExists (12.22s)19952026/10/25 17:16:13 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"19962026/10/25 17:16:13 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-config19972026/10/25 17:16:14 WARN Request failed, retrying attempt=2 backoff=209.640456ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config19982026/10/25 17:16:14 WARN Request failed, retrying attempt=3 backoff=368.573392ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config19992026/10/25 17:16:14 WARN readiness check failed error="closed pool"2000--- PASS: TestService_readinessHandler (12.69s)20012026/10/25 17:16:14 WARN Request failed, retrying attempt=4 backoff=792.576324ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config2002=== NAME TestNARDeduplicationMetadataUploadBug2003 metadata_upload_test.go:48: First store path: /private/var/tb/2/scratch/e6f8f47991d999ee/build/TestNARDeduplicationMetadataUploadBug3510393365/001/store/1ds15ynlglal11wqm9fnfdi1p4xf0zqj-file1.txt20042026/10/25 17:16:15 INFO Received push request method=POST path=/api/pushes20052026/10/25 17:16:15 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)20062026/10/25 17:16:15 INFO Uploading 1ds15ynlglal11wqm9fnfdi1p4xf0zqj-file1.txt (160B)20072026/10/25 17:16:15 WARN Failed to register uploaded object key=1ds15ynlglal11wqm9fnfdi1p4xf0zqj.ls error="server returned 404: 404 page not found\n"20082026/10/25 17:16:15 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign20092026/10/25 17:16:15 WARN Failed to register uploaded object key=nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst error="server returned 404: 404 page not found\n"20102026/10/25 17:16:15 INFO Signed narinfos id=1 count=120112026/10/25 17:16:15 INFO Uploading 1 narinfos20122026/10/25 17:16:15 INFO Received push request method=POST path=/api/pushes20132026/10/25 17:16:15 WARN Request failed, retrying attempt=5 backoff=1.656519847s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config20142026/10/25 17:16:15 INFO Received complete push request method=POST path=/api/pushes/1/complete20152026/10/25 17:16:15 WARN Failed to register uploaded object key=1ds15ynlglal11wqm9fnfdi1p4xf0zqj.narinfo error="server returned 404: 404 page not found\n"20162026/10/25 17:16:15 INFO Completed push id=1 objects=3 duration=73.746375ms20172026/10/25 17:16:15 INFO Upload complete. (522ms)2018 metadata_upload_test.go:54: Retrieved narinfo from S3:2019 StorePath: /private/var/tb/2/scratch/e6f8f47991d999ee/build/TestNARDeduplicationMetadataUploadBug3510393365/001/store/1ds15ynlglal11wqm9fnfdi1p4xf0zqj-file1.txt2020 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst2021 Compression: zstd2022 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf2023 NarSize: 1602024 References: 2025 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf20262026/10/25 17:16:15 INFO Received complete push request method=POST path=/api/pushes/1/complete2027 metadata_upload_test.go:55: Retrieved .ls file from S3 (compressed size: 77 bytes)2028 metadata_upload_test.go:55: Decompressed .ls content (64 bytes):2029 {"version":1,"root":{"type":"regular","size":44,"narOffset":96}}20302026/10/25 17:16:15 INFO Completed push id=1 objects=4 duration=64.644792ms20312026/10/25 17:16:15 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete20322026/10/25 17:16:15 INFO Completed upload id=2 objects=2 duration=2.795791ms2033--- PASS: TestMetricsCommit (13.27s)20342026/10/25 17:16:15 INFO Aborted multipart uploads count=1 kept=02035=== NAME TestNARDeduplicationMetadataUploadBug2036 metadata_upload_test.go:64: Second store path (same content): /private/var/tb/2/scratch/e6f8f47991d999ee/build/TestNARDeduplicationMetadataUploadBug3510393365/001/store/mhpibx4qb1l94643rjfr5ksxnmz4ncfs-file2.txt20372026/10/25 17:16:16 INFO Received cleanup request method=DELETE path=/api/pending_closures20382026/10/25 17:16:16 INFO Aborted multipart uploads count=1 kept=02039--- PASS: TestPendingCleanupUsesOneCutoff (16.43s)2040--- PASS: TestService_healthCheckHandler (13.40s)20412026/10/25 17:16:16 INFO Received push request method=POST path=/api/pushes20422026/10/25 17:16:16 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)20432026/10/25 17:16:16 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign20442026/10/25 17:16:16 WARN Failed to register uploaded object key=mhpibx4qb1l94643rjfr5ksxnmz4ncfs.ls error="server returned 404: 404 page not found\n"20452026/10/25 17:16:16 INFO Signed narinfos id=2 count=120462026/10/25 17:16:16 INFO Uploading 1 narinfos20472026/10/25 17:16:16 INFO Received complete push request method=POST path=/api/pushes/2/complete20482026/10/25 17:16:16 WARN Failed to register uploaded object key=mhpibx4qb1l94643rjfr5ksxnmz4ncfs.narinfo error="server returned 404: 404 page not found\n"20492026/10/25 17:16:16 INFO Completed push id=2 objects=3 duration=2.209416ms20502026/10/25 17:16:16 INFO Upload complete. (377ms)2051=== NAME TestNARDeduplicationMetadataUploadBug2052 metadata_upload_test.go:76: Retrieved narinfo from S3:2053 StorePath: /private/var/tb/2/scratch/e6f8f47991d999ee/build/TestNARDeduplicationMetadataUploadBug3510393365/001/store/mhpibx4qb1l94643rjfr5ksxnmz4ncfs-file2.txt2054 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst2055 Compression: zstd2056 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf2057 NarSize: 1602058 References: 2059 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf2060 metadata_upload_test.go:77: Retrieved .ls file from S3 (compressed size: 62 bytes)2061 metadata_upload_test.go:77: Decompressed .ls content (49 bytes):2062 {"version":1,"root":{"type":"regular","size":44}}2063--- PASS: TestNARDeduplicationMetadataUploadBug (15.05s)2064--- PASS: TestMetricsInventory (13.75s)20652026/10/25 17:16:17 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_closures20662026/10/25 17:16:17 WARN Request failed, retrying attempt=2 backoff=200.756709ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures20672026/10/25 17:16:17 WARN Request failed, retrying attempt=3 backoff=401.972735ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures20682026/10/25 17:16:17 INFO Received complete multipart upload request method=POST path=/api/multipart/complete20692026/10/25 17:16:17 INFO Received uploads request method=POST path=/api/pending_closures20702026/10/25 17:16:17 INFO Completed multipart upload object_key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhh0100000000000000000000.nar.zst upload_id=NzcxZGFhOTYtNDA5Zi00NTNkLWEzYmEtMTc5NWY2MjkzMWM3LmIxY2FmOGViLTZkZDEtNDA4Zi05YTFjLWJlODUxYWZmMDE0MHgxNzkyOTQ4NTczMzU2NzMxMDAw parts=1220712026/10/25 17:16:17 INFO Received uploads request method=POST path=/api/pending_closures2072--- PASS: TestCompletedNarNotReofferedAcrossClosures (16.22s)20732026/10/25 17:16:17 INFO Received uploads request method=POST path=/api/pending_closures20742026/10/25 17:16:17 WARN Request failed, retrying attempt=4 backoff=852.932078ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures20752026/10/25 17:16:18 INFO Received push request method=POST path=/api/pushes20762026/10/25 17:16:18 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign20772026/10/25 17:16:18 INFO Signed narinfos id=1 count=120782026/10/25 17:16:18 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign20792026/10/25 17:16:18 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign20802026/10/25 17:16:18 ERROR Failed to sign narinfos signer="index 1" error="signing key cannot be nil"20812026/10/25 17:16:18 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign20822026/10/25 17:16:18 ERROR Failed to sign narinfos signer=niks3-test-1 error="signer failed"20832026/10/25 17:16:18 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign20842026/10/25 17:16:18 ERROR Signer returned unexpected signature count signer=niks3-test-1 got=0 want=120852026/10/25 17:16:18 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign20862026/10/25 17:16:18 ERROR Signer returned unexpected object key signer=niks3-test-1 object_key=unexpected.narinfo2087--- PASS: TestPush_SignsNarinfosOfItsPendingObjects (14.39s)20882026/10/25 17:16:18 WARN Request failed, retrying attempt=5 backoff=1.482713148s error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures20892026/10/25 17:16:19 INFO Aborted multipart uploads count=0 kept=020902026/10/25 17:16:19 WARN Force mode enabled - objects will be deleted immediately without grace period20912026-10-25 17:16:19.623 UTC [38961] ERROR: canceling statement due to user request20922026-10-25 17:16:19.623 UTC [38961] STATEMENT: -- name: MarkStaleObjects :execrows2093 WITH RECURSIVE ct AS (2094 SELECT timezone('UTC', now()) AS now2095 ),2096 closure_reach AS (2097 -- Start with all closure keys2098 SELECT o.key, o.refs2099 FROM objects o2100 INNER JOIN closures c ON o.key = c.key2101 UNION2102 -- Recursively add all referenced objects2103 SELECT o.key, o.refs2104 FROM objects o2105 INNER JOIN closure_reach cr ON o.key = ANY(cr.refs)2106 ),2107 reachable_objects AS (2108 SELECT DISTINCT key FROM closure_reach2109 ),2110 stale_objects AS (2111 SELECT o.key2112 FROM objects AS o, ct2113 WHERE2114 NOT EXISTS (2115 SELECT 12116 FROM reachable_objects ro2117 WHERE ro.key = o.key2118 )2119 AND NOT EXISTS (2120 SELECT 12121 FROM pending_objects AS po2122 WHERE po.key = o.key2123 )2124 AND o.deleted_at IS NULL -- Only mark fresh objects2125 ORDER BY o.key COLLATE "C" -- lock in key order, like commit_pending_closure2126 FOR UPDATE2127 )2128 UPDATE objects2129 SET2130 deleted_at = ct.now,2131 first_deleted_at = COALESCE(first_deleted_at, ct.now)2132 FROM stale_objects, ct2133 WHERE objects.key = stale_objects.key2134 21352026/10/25 17:16:20 INFO Aborted multipart uploads count=0 kept=021362026/10/25 17:16:20 WARN Force mode enabled - objects will be deleted immediately without grace period21372026/10/25 17:16:20 ERROR failed to remove object object=nar/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa.nar.zst error="Post \"http://localhost:51150/bucket93/?delete=\": context canceled"2138--- PASS: TestGCEndsOnShutdown (0.00s)2139 --- PASS: TestGCEndsOnShutdown/before_the_run (14.87s)2140 --- PASS: TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark (15.00s)2141 --- PASS: TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete (15.18s)21422026/10/25 17:16:20 INFO Received uploads request method=POST path=/api/pending_closures21432026/10/25 17:16:20 INFO Aborted multipart uploads count=0 kept=021442026/10/25 17:16:20 WARN Force mode enabled - objects will be deleted immediately without grace period21452026/10/25 17:16:20 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=021462026/10/25 17:16:20 INFO Vacuumed table table=pending_closures21472026/10/25 17:16:20 INFO Vacuumed table table=pending_objects21482026/10/25 17:16:20 INFO Vacuumed table table=multipart_uploads21492026/10/25 17:16:20 INFO Vacuumed table table=closures21502026/10/25 17:16:20 INFO Vacuumed table table=objects21512026/10/25 17:16:21 INFO Received uploads request method=POST path=/api/pending_closures21522026/10/25 17:16:21 INFO Aborted multipart uploads count=0 kept=021532026/10/25 17:16:21 WARN Force mode enabled - objects will be deleted immediately without grace period21542026/10/25 17:16:21 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=021552026/10/25 17:16:21 INFO Vacuumed table table=pending_closures21562026/10/25 17:16:21 INFO Received complete multipart upload request method=POST path=/api/multipart/complete21572026/10/25 17:16:21 INFO Vacuumed table table=pending_objects21582026/10/25 17:16:21 INFO Vacuumed table table=multipart_uploads21592026/10/25 17:16:21 INFO Vacuumed table table=closures21602026/10/25 17:16:21 INFO Vacuumed table table=objects21612026/10/25 17:16:21 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=NzcxZGFhOTYtNDA5Zi00NTNkLWEzYmEtMTc5NWY2MjkzMWM3Ljg1OWQ2YzAzLWY3ZTQtNDlmMi05YzM0LTVkMTM5M2M4NzViOXgxNzkyOTQ4NTc3NjM5MDAwMDAw parts=1221622026/10/25 17:16:21 INFO Received uploads request method=POST path=/api/pending_closures21632026/10/25 17:16:21 INFO Received uploads request method=POST path=/api/pending_closures2164--- PASS: TestForceGCDuringPushOffersSweptObject (0.00s)2165 --- PASS: TestForceGCDuringPushOffersSweptObject/before_pending_rows (15.81s)2166 --- PASS: TestForceGCDuringPushOffersSweptObject/after_presence_check (16.00s)21672026/10/25 17:16:22 INFO Received uploads request method=POST path=/api/pending_closures21682026/10/25 17:16:22 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"21692026/10/25 17:16:22 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"2170--- PASS: TestClientErrorHandling (0.00s)2171 --- PASS: TestClientErrorHandling/ServerNotAvailable (13.47s)2172 --- PASS: TestClientErrorHandling/InvalidStorePath (15.54s)2173 --- PASS: TestClientErrorHandling/InvalidAuthToken (15.19s)2174--- PASS: TestPendingClosureWriteTimeout (0.00s)2175 --- PASS: TestPendingClosureWriteTimeout/empty (0.00s)2176 --- PASS: TestPendingClosureWriteTimeout/670k_objects (0.00s)2177 --- PASS: TestPendingClosureWriteTimeout/400_objects (0.00s)2178 --- PASS: TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline (14.89s)2179--- PASS: TestPresentNotReportedWhileGCDeletesClosure (0.00s)2180 --- PASS: TestPresentNotReportedWhileGCDeletesClosure/stale (13.27s)2181 --- PASS: TestPresentNotReportedWhileGCDeletesClosure/fresh (12.55s)21822026/10/25 17:16:24 INFO Received complete multipart upload request method=POST path=/api/multipart/complete21832026/10/25 17:16:24 WARN Failed to abort redundant multipart upload, keeping its row object_key=nar/gggggggggggggggggggggggggggggg0200000000000000000000.nar.zst upload_id=NzcxZGFhOTYtNDA5Zi00NTNkLWEzYmEtMTc5NWY2MjkzMWM3LjFmZjE1Yzc2LThjYWEtNGU3ZC1iYjQ4LWVlOGJlODlhMWMxMngxNzkyOTQ4NTgxNTY0NjI2MDAw error="Get \"http://127.0.0.1:1/bucket89/?location=\": dial tcp 127.0.0.1:1: connect: connection refused"21842026/10/25 17:16:24 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0200000000000000000000.nar.zst upload_id=NzcxZGFhOTYtNDA5Zi00NTNkLWEzYmEtMTc5NWY2MjkzMWM3LjkyZjZlNmI1LWFhMDctNDIyYy05N2FjLTYzYzA1OTIwMWYyOHgxNzkyOTQ4NTgxNDkyMDQ4MDAw parts=1221852026/10/25 17:16:24 INFO Received cleanup request method=DELETE path=/api/pending_closures21862026/10/25 17:16:24 INFO Aborted multipart uploads count=1 kept=02187--- PASS: TestRedundantMultipartUpload (21.17s)2188=== NAME TestOrphanedObjectsGCStressTest2189 orphaned_objects_gc_test.go:422: Created 10 active closures, 5 to-delete closures, 20 orphaned chains2190 orphaned_objects_gc_test.go:440: Marked 210 objects for deletion2191 orphaned_objects_gc_test.go:503: Stress test completed successfully:2192 orphaned_objects_gc_test.go:504: - Active objects preserved: 202193 orphaned_objects_gc_test.go:505: - Objects deleted: 2102194 orphaned_objects_gc_test.go:506: - Total GC'd: 2102195--- PASS: TestOrphanedObjectsGCStressTest (30.73s)2196PASS2197{"timestamp":"2026-10-25T17:16:27.592732Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:51536","error_kind":"io_error","error":"Cancelled","result":"transport_error","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":2386,"threadName":"rustfs-worker","threadId":"ThreadId(9)"}21982026-10-25 17:16:29.259 UTC [38183] LOG: received smart shutdown request21992026-10-25 17:16:29.266 UTC [38183] LOG: background worker "logical replication launcher" (PID 38193) exited with exit code 122002026-10-25 17:16:29.447 UTC [38188] LOG: shutting down22012026-10-25 17:16:29.448 UTC [38188] LOG: checkpoint starting: shutdown immediate22022026/10/25 17:16:39 INFO killed process group pgid=3818322032026/10/25 17:16:39 ERROR failed to wait for process error="signal: killed"22042026-10-25 17:16:39.546 UTC [38188] PANIC: could not fsync file "pg_multixact/offsets/0000": No such file or directory2205Running OIDC tests...2206=== RUN TestAudienceForIssuer2207=== PAUSE TestAudienceForIssuer2208=== RUN TestGlobMatch2209=== PAUSE TestGlobMatch2210=== RUN TestValidateToken_ValidToken2211=== PAUSE TestValidateToken_ValidToken2212=== RUN TestValidateToken_WrongAudience2213=== PAUSE TestValidateToken_WrongAudience2214=== RUN TestValidateToken_Expired2215=== PAUSE TestValidateToken_Expired2216=== RUN TestValidateToken_BoundClaimsMismatch2217=== PAUSE TestValidateToken_BoundClaimsMismatch2218=== RUN TestValidateToken_BoundSubjectMismatch2219=== PAUSE TestValidateToken_BoundSubjectMismatch2220=== RUN TestValidateToken_MultipleProviders2221=== PAUSE TestValidateToken_MultipleProviders2222=== RUN TestValidateToken_NoMatchingProvider2223=== PAUSE TestValidateToken_NoMatchingProvider2224=== RUN TestValidateToken_KubernetesServiceAccount2225=== PAUSE TestValidateToken_KubernetesServiceAccount2226=== RUN TestNewValidator_KubernetesRequiresCA2227=== PAUSE TestNewValidator_KubernetesRequiresCA2228=== RUN TestValidateToken_KubernetesIssuerFromOwnToken2229=== PAUSE TestValidateToken_KubernetesIssuerFromOwnToken2230=== RUN TestPins_ReservedForMatchingRule2231=== PAUSE TestPins_ReservedForMatchingRule2232=== RUN TestPins_TopLevelShorthand2233=== PAUSE TestPins_TopLevelShorthand2234=== RUN TestPins_ConfigValidation2235=== PAUSE TestPins_ConfigValidation2236=== RUN TestScopes_LegacyProviderDefaultsToWrite2237=== PAUSE TestScopes_LegacyProviderDefaultsToWrite2238=== RUN TestScopes_Rules2239=== PAUSE TestScopes_Rules2240=== RUN TestScopes_ConfigValidation2241=== PAUSE TestScopes_ConfigValidation2242=== CONT TestAudienceForIssuer2243--- PASS: TestAudienceForIssuer (0.00s)2244=== CONT TestValidateToken_Expired2245=== CONT TestValidateToken_BoundSubjectMismatch2246=== CONT TestPins_ConfigValidation2247=== CONT TestValidateToken_BoundClaimsMismatch2248=== CONT TestValidateToken_NoMatchingProvider2249=== CONT TestValidateToken_MultipleProviders2250--- PASS: TestPins_ConfigValidation (0.00s)2251=== CONT TestValidateToken_KubernetesServiceAccount2252=== CONT TestPins_TopLevelShorthand2253=== CONT TestPins_ReservedForMatchingRule2254=== CONT TestValidateToken_KubernetesIssuerFromOwnToken2255=== CONT TestNewValidator_KubernetesRequiresCA2256=== CONT TestValidateToken_ValidToken2257=== CONT TestValidateToken_WrongAudience2258=== CONT TestScopes_Rules2259=== CONT TestScopes_ConfigValidation2260=== CONT TestGlobMatch2261=== RUN TestGlobMatch/foo_foo22622026/10/25 17:17:00 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:52276/oidc2263=== CONT TestScopes_LegacyProviderDefaultsToWrite22642026/10/25 17:17:00 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:52278/oidc2265=== PAUSE TestGlobMatch/foo_foo2266--- PASS: TestPins_TopLevelShorthand (0.06s)2267--- PASS: TestScopes_ConfigValidation (0.03s)2268=== RUN TestGlobMatch/foo_bar2269=== PAUSE TestGlobMatch/foo_bar2270=== RUN TestGlobMatch/*_2271=== PAUSE TestGlobMatch/*_2272=== RUN TestGlobMatch/*_anything2273=== PAUSE TestGlobMatch/*_anything2274=== RUN TestGlobMatch/foo*_foo2275=== PAUSE TestGlobMatch/foo*_foo2276=== RUN TestGlobMatch/foo*_foobar2277=== PAUSE TestGlobMatch/foo*_foobar2278=== RUN TestGlobMatch/foo*_bar2279=== PAUSE TestGlobMatch/foo*_bar2280=== RUN TestGlobMatch/*bar_bar2281=== PAUSE TestGlobMatch/*bar_bar2282=== RUN TestGlobMatch/*bar_foobar2283=== PAUSE TestGlobMatch/*bar_foobar2284=== RUN TestGlobMatch/*bar_foo2285=== PAUSE TestGlobMatch/*bar_foo2286=== RUN TestGlobMatch/foo*bar_foobar2287=== PAUSE TestGlobMatch/foo*bar_foobar2288=== RUN TestGlobMatch/foo*bar_foo123bar2289=== PAUSE TestGlobMatch/foo*bar_foo123bar2290=== RUN TestGlobMatch/foo*bar_foobarbaz2291=== PAUSE TestGlobMatch/foo*bar_foobarbaz2292=== RUN TestGlobMatch/*/*_foo/bar2293=== PAUSE TestGlobMatch/*/*_foo/bar2294=== RUN TestGlobMatch/*/*_foo2295=== PAUSE TestGlobMatch/*/*_foo2296=== RUN TestGlobMatch/refs/heads/*_refs/heads/main2297=== PAUSE TestGlobMatch/refs/heads/*_refs/heads/main2298=== RUN TestGlobMatch/refs/heads/*_refs/tags/v1.02299=== PAUSE TestGlobMatch/refs/heads/*_refs/tags/v1.02300=== RUN TestGlobMatch/refs/*/main_refs/heads/main2301=== PAUSE TestGlobMatch/refs/*/main_refs/heads/main2302=== RUN TestGlobMatch/fo?_foo2303=== PAUSE TestGlobMatch/fo?_foo2304=== RUN TestGlobMatch/fo?_fo2305=== PAUSE TestGlobMatch/fo?_fo2306=== RUN TestGlobMatch/fo?_fooo2307=== PAUSE TestGlobMatch/fo?_fooo2308=== RUN TestGlobMatch/?oo_foo2309=== PAUSE TestGlobMatch/?oo_foo2310=== RUN TestGlobMatch/?oo_boo2311=== PAUSE TestGlobMatch/?oo_boo2312=== RUN TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2313=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2314=== RUN TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2315=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2316=== CONT TestGlobMatch/foo_foo23172026/10/25 17:17:00 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:52280/oidc2318=== CONT TestGlobMatch/*/*_foo/bar2319=== CONT TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2320=== CONT TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2321=== CONT TestGlobMatch/?oo_boo2322=== CONT TestGlobMatch/?oo_foo2323=== CONT TestGlobMatch/fo?_fooo2324=== CONT TestGlobMatch/fo?_fo2325=== CONT TestGlobMatch/fo?_foo2326=== CONT TestGlobMatch/refs/*/main_refs/heads/main2327=== CONT TestGlobMatch/refs/heads/*_refs/tags/v1.02328=== CONT TestGlobMatch/refs/heads/*_refs/heads/main2329=== CONT TestGlobMatch/*/*_foo2330=== CONT TestGlobMatch/*bar_bar2331=== CONT TestGlobMatch/foo*bar_foobarbaz2332=== CONT TestGlobMatch/foo*bar_foo123bar2333=== CONT TestGlobMatch/foo*bar_foobar2334=== CONT TestGlobMatch/*bar_foo2335=== CONT TestGlobMatch/*bar_foobar2336=== CONT TestGlobMatch/foo*_foo2337=== CONT TestGlobMatch/foo*_bar2338=== CONT TestGlobMatch/foo*_foobar2339=== CONT TestGlobMatch/*_2340=== CONT TestGlobMatch/*_anything2341=== CONT TestGlobMatch/foo_bar2342--- PASS: TestGlobMatch (0.03s)2343 --- PASS: TestGlobMatch/foo_foo (0.00s)2344 --- PASS: TestGlobMatch/*/*_foo/bar (0.00s)2345 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main (0.00s)2346 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main (0.00s)2347 --- PASS: TestGlobMatch/?oo_boo (0.00s)2348 --- PASS: TestGlobMatch/?oo_foo (0.00s)2349 --- PASS: TestGlobMatch/fo?_fooo (0.00s)2350 --- PASS: TestGlobMatch/fo?_fo (0.00s)2351 --- PASS: TestGlobMatch/fo?_foo (0.00s)2352 --- PASS: TestGlobMatch/refs/*/main_refs/heads/main (0.00s)2353 --- PASS: TestGlobMatch/refs/heads/*_refs/tags/v1.0 (0.00s)2354 --- PASS: TestGlobMatch/refs/heads/*_refs/heads/main (0.00s)2355 --- PASS: TestGlobMatch/*/*_foo (0.00s)2356 --- PASS: TestGlobMatch/*bar_bar (0.00s)2357 --- PASS: TestGlobMatch/foo*bar_foobarbaz (0.00s)2358 --- PASS: TestGlobMatch/foo*bar_foo123bar (0.00s)2359 --- PASS: TestGlobMatch/foo*bar_foobar (0.00s)2360 --- PASS: TestGlobMatch/*bar_foo (0.00s)2361 --- PASS: TestGlobMatch/*bar_foobar (0.00s)2362 --- PASS: TestGlobMatch/foo*_foo (0.00s)2363 --- PASS: TestGlobMatch/foo*_bar (0.00s)2364 --- PASS: TestGlobMatch/foo*_foobar (0.00s)2365 --- PASS: TestGlobMatch/*_ (0.00s)2366 --- PASS: TestGlobMatch/*_anything (0.00s)2367 --- PASS: TestGlobMatch/foo_bar (0.00s)2368--- PASS: TestScopes_Rules (0.05s)2369--- PASS: TestValidateToken_BoundSubjectMismatch (0.08s)23702026/10/25 17:17:00 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:52282/oidc23712026/10/25 17:17:00 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:52284/oidc2372--- PASS: TestPins_ReservedForMatchingRule (0.11s)23732026/10/25 17:17:00 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:52287/oidc2374--- PASS: TestValidateToken_ValidToken (0.11s)2375--- PASS: TestValidateToken_WrongAudience (0.11s)23762026/10/25 17:17:00 INFO OIDC provider initialized name=kubernetes issuer=https://127.0.0.1:522892377--- PASS: TestValidateToken_KubernetesServiceAccount (0.15s)23782026/10/25 17:17:00 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:52286/oidc23792026/10/25 17:17:00 INFO OIDC provider initialized name=provider2 issuer=http://127.0.0.1:52291/oidc2380--- PASS: TestValidateToken_MultipleProviders (0.16s)23812026/10/25 17:17:00 INFO OIDC provider initialized name=kubernetes issuer=https://oidc.eks.invalid/id/ABC12323822026/10/25 17:17:00 http: TLS handshake error from 127.0.0.1:52295: read tcp 127.0.0.1:52293->127.0.0.1:52295: use of closed network connection2383--- PASS: TestNewValidator_KubernetesRequiresCA (0.15s)2384--- PASS: TestValidateToken_KubernetesIssuerFromOwnToken (0.15s)23852026/10/25 17:17:00 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:52298/oidc2386--- PASS: TestScopes_LegacyProviderDefaultsToWrite (0.12s)23872026/10/25 17:17:00 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:52301/oidc23882026/10/25 17:17:00 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:52302/oidc23892026/10/25 17:17:00 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:52275/oidc2390--- PASS: TestValidateToken_BoundClaimsMismatch (0.21s)2391--- PASS: TestValidateToken_Expired (0.21s)2392--- PASS: TestValidateToken_NoMatchingProvider (0.21s)2393PASS2394Running hook tests...2395=== RUN TestSendPathsEmpty2396=== PAUSE TestSendPathsEmpty2397=== RUN TestQueueEnqueueAndFetch2398=== PAUSE TestQueueEnqueueAndFetch2399=== RUN TestQueueDeduplication2400=== PAUSE TestQueueDeduplication2401=== RUN TestQueueRemove2402=== PAUSE TestQueueRemove2403=== RUN TestQueueFetchBatchLimit2404=== PAUSE TestQueueFetchBatchLimit2405=== RUN TestQueueRetryMovesToBack2406=== PAUSE TestQueueRetryMovesToBack2407=== RUN TestQueueFetchRemoveLifecycle2408=== PAUSE TestQueueFetchRemoveLifecycle2409=== RUN TestQueueConcurrentWriters2410=== PAUSE TestQueueConcurrentWriters2411=== RUN TestQueueRemoveLargeClosure2412=== PAUSE TestQueueRemoveLargeClosure2413=== RUN TestServerClientIntegration2414--- PASS: TestServerClientIntegration (0.00s)2415=== RUN TestServerQueueError24162026/10/25 17:17:00 ERROR Failed to queue paths error="permission denied" count=12417--- PASS: TestServerQueueError (0.00s)2418=== RUN TestGetListenerSocketActivation2419 server_test.go:146: systemd socket activation does not exist on darwin2420--- SKIP: TestGetListenerSocketActivation (0.00s)2421=== RUN TestDrainIsolatesPoisonPath2422=== PAUSE TestDrainIsolatesPoisonPath2423=== RUN TestRunNotBlockedByPoisonHead2424=== PAUSE TestRunNotBlockedByPoisonHead2425=== RUN TestDrainGivesUpWhenServerDown2426=== PAUSE TestDrainGivesUpWhenServerDown2427=== RUN TestFailedPathPrunedByLaterClosure2428=== PAUSE TestFailedPathPrunedByLaterClosure2429=== RUN TestWorkerUploadsAndRemoves2430=== PAUSE TestWorkerUploadsAndRemoves2431=== RUN TestWorkerSkipsGCdPaths2432=== PAUSE TestWorkerSkipsGCdPaths2433=== RUN TestWorkerPrunesClosureDeps2434=== PAUSE TestWorkerPrunesClosureDeps2435=== RUN TestDrainTimeout2436=== PAUSE TestDrainTimeout2437=== RUN TestWorkerRemoveFailureIsNotProgress2438=== PAUSE TestWorkerRemoveFailureIsNotProgress2439=== RUN TestWorkerKeepsPathItCannotStat2440=== PAUSE TestWorkerKeepsPathItCannotStat2441=== CONT TestSendPathsEmpty2442--- PASS: TestSendPathsEmpty (0.00s)2443=== CONT TestRunNotBlockedByPoisonHead2444=== CONT TestWorkerKeepsPathItCannotStat2445=== CONT TestWorkerRemoveFailureIsNotProgress2446=== CONT TestQueueRetryMovesToBack2447=== CONT TestDrainTimeout2448=== CONT TestWorkerPrunesClosureDeps2449=== CONT TestDrainIsolatesPoisonPath2450=== CONT TestWorkerSkipsGCdPaths2451=== CONT TestWorkerUploadsAndRemoves2452=== CONT TestQueueDeduplication2453=== CONT TestFailedPathPrunedByLaterClosure2454=== CONT TestDrainGivesUpWhenServerDown2455=== CONT TestQueueFetchBatchLimit2456=== CONT TestQueueConcurrentWriters2457=== CONT TestQueueRemove2458=== CONT TestQueueRemoveLargeClosure2459=== CONT TestQueueFetchRemoveLifecycle2460=== CONT TestQueueEnqueueAndFetch2461--- PASS: TestQueueRemove (0.01s)24622026/10/25 17:17:00 INFO Uploading batch count=124632026/10/25 17:17:00 ERROR Upload failed error="upload failed" count=124642026/10/25 17:17:00 INFO Upload queue status pending=224652026/10/25 17:17:00 INFO Uploading batch count=224662026/10/25 17:17:00 INFO Uploading batch count=124672026/10/25 17:17:00 INFO Upload queue status pending=324682026/10/25 17:17:00 INFO Uploading batch count=124692026/10/25 17:17:00 INFO Uploading batch count=12470--- PASS: TestQueueEnqueueAndFetch (0.01s)2471--- PASS: TestQueueRetryMovesToBack (0.02s)24722026/10/25 17:17:00 WARN Cannot stat store path, will retry later path=/private/var/tb/2/scratch/e6f8f47991d999ee/build/TestWorkerKeepsPathItCannotStat681557368/002/locked/aaa error="stat /private/var/tb/2/scratch/e6f8f47991d999ee/build/TestWorkerKeepsPathItCannotStat681557368/002/locked/aaa: permission denied"24732026/10/25 17:17:00 INFO Upload queue status pending=224742026/10/25 17:17:00 INFO Uploading batch count=224752026/10/25 17:17:00 ERROR Upload failed error="upload failed" count=224762026/10/25 17:17:00 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/2/scratch/e6f8f47991d999ee/build/TestDrainGivesUpWhenServerDown3712932505/002/a24772026/10/25 17:17:00 WARN Store path no longer exists (garbage collected?), removing from queue path=/private/var/tb/2/scratch/e6f8f47991d999ee/build/TestWorkerSkipsGCdPaths804565849/002/nonexistent24782026/10/25 17:17:00 INFO Uploading batch count=124792026/10/25 17:17:00 ERROR Upload failed error="upload failed" count=124802026/10/25 17:17:00 INFO Uploading batch count=424812026/10/25 17:17:00 ERROR Upload failed error="upload failed" count=424822026/10/25 17:17:00 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/2/scratch/e6f8f47991d999ee/build/TestDrainGivesUpWhenServerDown3712932505/002/b2483--- PASS: TestQueueDeduplication (0.02s)24842026/10/25 17:17:00 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/2/scratch/e6f8f47991d999ee/build/TestDrainIsolatesPoisonPath2632051983/002/bbb2485--- PASS: TestQueueFetchBatchLimit (0.02s)24862026/10/25 17:17:00 INFO Upload queue status pending=224872026/10/25 17:17:00 INFO Uploading batch count=224882026/10/25 17:17:00 INFO Uploading batch count=124892026/10/25 17:17:00 WARN Cannot stat store path, will retry later path=/private/var/tb/2/scratch/e6f8f47991d999ee/build/TestWorkerKeepsPathItCannotStat681557368/002/locked/aaa error="stat /private/var/tb/2/scratch/e6f8f47991d999ee/build/TestWorkerKeepsPathItCannotStat681557368/002/locked/aaa: permission denied"24902026/10/25 17:17:00 INFO Uploading batch count=124912026/10/25 17:17:00 ERROR Upload failed error="upload failed" count=124922026/10/25 17:17:00 INFO Uploading batch count=224932026/10/25 17:17:00 ERROR Upload failed error="upload failed" count=224942026/10/25 17:17:00 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/2/scratch/e6f8f47991d999ee/build/TestDrainGivesUpWhenServerDown3712932505/002/c2495--- PASS: TestQueueFetchRemoveLifecycle (0.01s)24962026/10/25 17:17:00 INFO Uploading batch count=124972026/10/25 17:17:00 ERROR Upload failed error="upload failed" count=124982026/10/25 17:17:00 WARN Cannot stat store path, will retry later path=/private/var/tb/2/scratch/e6f8f47991d999ee/build/TestWorkerKeepsPathItCannotStat681557368/002/locked/aaa error="stat /private/var/tb/2/scratch/e6f8f47991d999ee/build/TestWorkerKeepsPathItCannotStat681557368/002/locked/aaa: permission denied"24992026/10/25 17:17:00 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/2/scratch/e6f8f47991d999ee/build/TestDrainGivesUpWhenServerDown3712932505/002/d25002026/10/25 17:17:00 ERROR Drain finished with paths left in queue remaining=125012026/10/25 17:17:00 INFO Uploading batch count=125022026/10/25 17:17:00 ERROR Upload failed error="upload failed" count=125032026/10/25 17:17:00 INFO Uploading batch count=225042026/10/25 17:17:00 ERROR Upload failed error="upload failed" count=225052026/10/25 17:17:00 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/2/scratch/e6f8f47991d999ee/build/TestDrainGivesUpWhenServerDown3712932505/002/e25062026/10/25 17:17:00 WARN Store path no longer exists (garbage collected?), removing from queue path=/private/var/tb/2/scratch/e6f8f47991d999ee/build/TestWorkerRemoveFailureIsNotProgress3221125074/002/nonexistent25072026/10/25 17:17:00 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=125082026/10/25 17:17:00 ERROR Drain finished with paths left in queue remaining=125092026/10/25 17:17:00 WARN Store path no longer exists (garbage collected?), removing from queue path=/private/var/tb/2/scratch/e6f8f47991d999ee/build/TestWorkerRemoveFailureIsNotProgress3221125074/002/nonexistent25102026/10/25 17:17:00 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=125112026/10/25 17:17:00 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/2/scratch/e6f8f47991d999ee/build/TestDrainGivesUpWhenServerDown3712932505/002/f2512--- PASS: TestFailedPathPrunedByLaterClosure (0.02s)25132026/10/25 17:17:00 WARN Store path no longer exists (garbage collected?), removing from queue path=/private/var/tb/2/scratch/e6f8f47991d999ee/build/TestWorkerRemoveFailureIsNotProgress3221125074/002/nonexistent25142026/10/25 17:17:00 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=125152026/10/25 17:17:00 ERROR Drain finished with paths left in queue remaining=125162026/10/25 17:17:00 ERROR Drain finished with paths left in queue remaining=102517--- PASS: TestWorkerKeepsPathItCannotStat (0.02s)2518--- PASS: TestDrainIsolatesPoisonPath (0.02s)2519--- PASS: TestWorkerRemoveFailureIsNotProgress (0.02s)2520--- PASS: TestDrainGivesUpWhenServerDown (0.02s)2521--- PASS: TestWorkerPrunesClosureDeps (0.03s)2522--- PASS: TestWorkerUploadsAndRemoves (0.04s)2523--- PASS: TestWorkerSkipsGCdPaths (0.04s)2524--- PASS: TestQueueRemoveLargeClosure (0.04s)2525--- PASS: TestQueueConcurrentWriters (0.10s)25262026/10/25 17:17:01 ERROR Upload failed error="context deadline exceeded" count=225272026/10/25 17:17:01 ERROR Drain finished with paths left in queue remaining=42528--- PASS: TestDrainTimeout (0.22s)25292026/10/25 17:17:01 INFO Uploading batch count=125302026/10/25 17:17:01 INFO Uploading batch count=125312026/10/25 17:17:01 INFO Uploading batch count=125322026/10/25 17:17:01 ERROR Upload failed error="upload failed" count=125332026/10/25 17:17:01 INFO Uploading batch count=125342026/10/25 17:17:01 ERROR Upload failed error="upload failed" count=125352026/10/25 17:17:01 INFO Uploading batch count=125362026/10/25 17:17:01 ERROR Upload failed error="upload failed" count=125372026/10/25 17:17:01 INFO Uploading batch count=125382026/10/25 17:17:01 ERROR Upload failed error="upload failed" count=125392026/10/25 17:17:01 ERROR Drain finished with paths left in queue remaining=12540--- PASS: TestRunNotBlockedByPoisonHead (1.04s)2541PASS2542Running signing tests...2543=== RUN TestExternalSigner2544=== PAUSE TestExternalSigner2545=== RUN TestExternalSignerWrongPublicKey2546=== PAUSE TestExternalSignerWrongPublicKey2547=== RUN TestExternalSignerErrors2548=== PAUSE TestExternalSignerErrors2549=== RUN TestExternalSignerRestartsAfterCrash2550=== PAUSE TestExternalSignerRestartsAfterCrash2551=== RUN TestExternalSignerProgramErrorKeepsProcess2552=== PAUSE TestExternalSignerProgramErrorKeepsProcess2553=== RUN TestExternalSignerClose2554=== PAUSE TestExternalSignerClose2555=== RUN TestExternalSignerRejectsInvalidPublicKey2556=== PAUSE TestExternalSignerRejectsInvalidPublicKey2557=== RUN TestExternalSignerCancellation2558=== PAUSE TestExternalSignerCancellation2559=== RUN TestGenerateFingerprint2560=== PAUSE TestGenerateFingerprint2561=== RUN TestParseSigningKey2562=== PAUSE TestParseSigningKey2563=== RUN TestSign2564=== PAUSE TestSign2565=== RUN TestSignBatch2566=== PAUSE TestSignBatch2567=== RUN TestNilKeyPublicKey2568=== PAUSE TestNilKeyPublicKey2569=== RUN TestSignErrors2570=== PAUSE TestSignErrors2571=== CONT TestExternalSigner2572=== CONT TestExternalSignerCancellation2573=== CONT TestNilKeyPublicKey2574=== CONT TestExternalSignerProgramErrorKeepsProcess2575=== CONT TestSign2576=== CONT TestParseSigningKey2577=== RUN TestParseSigningKey/valid_32-byte_key2578=== CONT TestExternalSignerRejectsInvalidPublicKey2579=== PAUSE TestParseSigningKey/valid_32-byte_key2580=== RUN TestParseSigningKey/valid_32-byte_key_with_different_name2581=== PAUSE TestParseSigningKey/valid_32-byte_key_with_different_name2582=== RUN TestExternalSignerRejectsInvalidPublicKey/#002583=== PAUSE TestExternalSignerRejectsInvalidPublicKey/#002584=== CONT TestSignErrors2585=== RUN TestExternalSignerRejectsInvalidPublicKey/no-colon2586=== CONT TestGenerateFingerprint2587=== RUN TestGenerateFingerprint/basic_with_references2588=== CONT TestExternalSignerErrors2589=== RUN TestExternalSignerErrors/exit_on_request2590=== PAUSE TestExternalSignerErrors/exit_on_request2591=== RUN TestExternalSignerErrors/invalid_JSON2592=== PAUSE TestExternalSignerErrors/invalid_JSON2593=== CONT TestExternalSignerRestartsAfterCrash2594=== CONT TestExternalSignerWrongPublicKey2595--- PASS: TestNilKeyPublicKey (0.00s)2596=== CONT TestExternalSignerClose2597=== CONT TestSignBatch2598=== RUN TestParseSigningKey/no_colon2599=== PAUSE TestParseSigningKey/no_colon2600=== PAUSE TestExternalSignerRejectsInvalidPublicKey/no-colon2601=== RUN TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2602=== PAUSE TestGenerateFingerprint/basic_with_references2603=== RUN TestGenerateFingerprint/no_references2604=== RUN TestExternalSignerErrors/wrong_id2605=== PAUSE TestGenerateFingerprint/no_references2606=== PAUSE TestExternalSignerErrors/wrong_id2607=== RUN TestGenerateFingerprint/unsorted_references_get_sorted2608=== RUN TestExternalSignerErrors/null_signatures2609=== PAUSE TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2610=== PAUSE TestExternalSignerErrors/null_signatures2611=== RUN TestExternalSignerErrors/program_error2612=== RUN TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2613=== PAUSE TestExternalSignerErrors/program_error2614=== RUN TestExternalSignerErrors/missing_signatures2615=== PAUSE TestExternalSignerErrors/missing_signatures2616=== PAUSE TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2617=== RUN TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2618=== PAUSE TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2619=== CONT TestExternalSignerRejectsInvalidPublicKey/#002620=== RUN TestParseSigningKey/empty_name2621=== PAUSE TestParseSigningKey/empty_name2622=== RUN TestParseSigningKey/invalid_base642623=== PAUSE TestParseSigningKey/invalid_base642624=== RUN TestParseSigningKey/wrong_length2625=== PAUSE TestParseSigningKey/wrong_length2626=== CONT TestParseSigningKey/valid_32-byte_key2627=== RUN TestExternalSignerErrors/wrong_signatures_shape2628=== PAUSE TestExternalSignerErrors/wrong_signatures_shape2629=== RUN TestExternalSignerErrors/too_few_signatures2630=== PAUSE TestExternalSignerErrors/too_few_signatures2631=== RUN TestExternalSignerErrors/unrequested_key2632=== PAUSE TestExternalSignerErrors/unrequested_key2633=== RUN TestExternalSignerErrors/missing_signature_name2634=== PAUSE TestExternalSignerErrors/missing_signature_name2635=== RUN TestExternalSignerErrors/exit_at_startup2636=== PAUSE TestExternalSignerErrors/exit_at_startup2637=== CONT TestParseSigningKey/wrong_length2638=== PAUSE TestGenerateFingerprint/unsorted_references_get_sorted2639=== RUN TestGenerateFingerprint/invalid_nar_hash_prefix2640=== PAUSE TestGenerateFingerprint/invalid_nar_hash_prefix2641=== RUN TestExternalSignerErrors/wrong_signature_name2642=== CONT TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2643=== CONT TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2644=== CONT TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2645=== CONT TestExternalSignerRejectsInvalidPublicKey/no-colon2646=== CONT TestParseSigningKey/empty_name2647=== CONT TestParseSigningKey/no_colon2648=== CONT TestParseSigningKey/invalid_base642649=== CONT TestParseSigningKey/valid_32-byte_key_with_different_name2650=== RUN TestGenerateFingerprint/invalid_nar_hash_length2651=== PAUSE TestGenerateFingerprint/invalid_nar_hash_length2652=== RUN TestGenerateFingerprint/invalid_store_path_prefix2653=== PAUSE TestGenerateFingerprint/invalid_store_path_prefix2654=== PAUSE TestExternalSignerErrors/wrong_signature_name2655--- PASS: TestExternalSignerRejectsInvalidPublicKey (0.00s)2656 --- PASS: TestExternalSignerRejectsInvalidPublicKey/#00 (0.00s)2657 --- PASS: TestExternalSignerRejectsInvalidPublicKey/test-key:YQ== (0.00s)2658 --- PASS: TestExternalSignerRejectsInvalidPublicKey/test-key:invalid! (0.00s)2659 --- PASS: TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA= (0.00s)2660 --- PASS: TestExternalSignerRejectsInvalidPublicKey/no-colon (0.00s)2661=== RUN TestGenerateFingerprint/invalid_reference_prefix2662=== PAUSE TestGenerateFingerprint/invalid_reference_prefix2663=== CONT TestGenerateFingerprint/basic_with_references2664=== CONT TestGenerateFingerprint/invalid_nar_hash_length2665=== RUN TestExternalSignerErrors/wrong_shape2666=== CONT TestGenerateFingerprint/invalid_nar_hash_prefix2667=== CONT TestGenerateFingerprint/unsorted_references_get_sorted2668=== CONT TestGenerateFingerprint/no_references2669=== CONT TestGenerateFingerprint/invalid_reference_prefix2670=== CONT TestGenerateFingerprint/invalid_store_path_prefix2671--- PASS: TestGenerateFingerprint (0.00s)2672 --- PASS: TestGenerateFingerprint/basic_with_references (0.00s)2673 --- PASS: TestGenerateFingerprint/invalid_nar_hash_length (0.00s)2674 --- PASS: TestGenerateFingerprint/invalid_nar_hash_prefix (0.00s)2675 --- PASS: TestGenerateFingerprint/unsorted_references_get_sorted (0.00s)2676 --- PASS: TestGenerateFingerprint/no_references (0.00s)2677 --- PASS: TestGenerateFingerprint/invalid_reference_prefix (0.00s)2678 --- PASS: TestGenerateFingerprint/invalid_store_path_prefix (0.00s)2679=== PAUSE TestExternalSignerErrors/wrong_shape2680=== RUN TestExternalSignerErrors/null2681=== PAUSE TestExternalSignerErrors/null2682=== RUN TestExternalSignerErrors/invalid_signature_base642683=== PAUSE TestExternalSignerErrors/invalid_signature_base642684=== RUN TestExternalSignerErrors/wrong_signature_length2685=== PAUSE TestExternalSignerErrors/wrong_signature_length2686=== CONT TestExternalSignerErrors/exit_on_request2687=== RUN TestSignErrors/nil_key2688=== CONT TestExternalSignerErrors/wrong_shape2689=== PAUSE TestSignErrors/nil_key2690--- PASS: TestSign (0.00s)2691=== RUN TestSignErrors/nil_narinfo2692=== PAUSE TestSignErrors/nil_narinfo2693=== RUN TestSignErrors/invalid_narinfo2694=== PAUSE TestSignErrors/invalid_narinfo2695=== CONT TestExternalSignerErrors/exit_at_startup2696=== RUN TestSignErrors/canceled2697=== PAUSE TestSignErrors/canceled2698=== CONT TestExternalSignerErrors/too_few_signatures2699=== CONT TestSignErrors/nil_key2700=== CONT TestExternalSignerErrors/invalid_signature_base642701=== CONT TestExternalSignerErrors/unrequested_key2702=== CONT TestExternalSignerErrors/wrong_signature_length2703=== CONT TestExternalSignerErrors/wrong_signature_name2704=== CONT TestExternalSignerErrors/wrong_signatures_shape2705=== CONT TestExternalSignerErrors/null2706=== CONT TestSignErrors/invalid_narinfo2707=== CONT TestExternalSignerErrors/missing_signatures2708=== CONT TestExternalSignerErrors/null_signatures2709=== CONT TestExternalSignerErrors/missing_signature_name2710--- PASS: TestSignBatch (0.00s)2711=== CONT TestSignErrors/nil_narinfo2712=== CONT TestExternalSignerErrors/wrong_id2713--- PASS: TestParseSigningKey (0.00s)2714 --- PASS: TestParseSigningKey/wrong_length (0.00s)2715 --- PASS: TestParseSigningKey/empty_name (0.00s)2716 --- PASS: TestParseSigningKey/no_colon (0.00s)2717 --- PASS: TestParseSigningKey/invalid_base64 (0.00s)2718 --- PASS: TestParseSigningKey/valid_32-byte_key (0.00s)2719 --- PASS: TestParseSigningKey/valid_32-byte_key_with_different_name (0.00s)2720=== CONT TestExternalSignerErrors/invalid_JSON2721=== CONT TestExternalSignerErrors/program_error2722=== CONT TestSignErrors/canceled2723--- PASS: TestSignErrors (0.00s)2724 --- PASS: TestSignErrors/nil_key (0.00s)2725 --- PASS: TestSignErrors/invalid_narinfo (0.00s)2726 --- PASS: TestSignErrors/nil_narinfo (0.00s)2727 --- PASS: TestSignErrors/canceled (0.00s)2728--- PASS: TestExternalSignerCancellation (0.22s)2729--- PASS: TestExternalSignerClose (0.38s)2730--- PASS: TestExternalSignerRestartsAfterCrash (0.58s)2731/private/var/tb/2/scratch/e6f8f47991d999ee/build/TestExternalSignerRestartsAfterCrash3628632064/001/sign program: line 7: /private/var/tb/2/scratch/e6f8f47991d999ee/build/TestExternalSignerRestartsAfterCrash3628632064/001/sign program.starts: No such file or directory2732--- PASS: TestExternalSignerWrongPublicKey (1.29s)2733--- PASS: TestExternalSignerProgramErrorKeepsProcess (2.02s)2734--- PASS: TestExternalSigner (2.22s)2735--- PASS: TestExternalSignerErrors (0.00s)2736 --- PASS: TestExternalSignerErrors/invalid_JSON (0.74s)2737 --- PASS: TestExternalSignerErrors/missing_signatures (0.92s)2738 --- PASS: TestExternalSignerErrors/exit_at_startup (1.11s)2739 --- PASS: TestExternalSignerErrors/null (1.47s)2740 --- PASS: TestExternalSignerErrors/wrong_signature_length (1.65s)2741 --- PASS: TestExternalSignerErrors/wrong_id (1.84s)2742 --- PASS: TestExternalSignerErrors/wrong_signatures_shape (2.38s)2743 --- PASS: TestExternalSignerErrors/missing_signature_name (2.56s)2744 --- PASS: TestExternalSignerErrors/unrequested_key (2.74s)2745 --- PASS: TestExternalSignerErrors/program_error (2.92s)2746 --- PASS: TestExternalSignerErrors/null_signatures (3.10s)2747 --- PASS: TestExternalSignerErrors/exit_on_request (3.28s)2748 --- PASS: TestExternalSignerErrors/too_few_signatures (3.47s)2749 --- PASS: TestExternalSignerErrors/invalid_signature_base64 (3.65s)2750 --- PASS: TestExternalSignerErrors/wrong_signature_name (3.83s)2751 --- PASS: TestExternalSignerErrors/wrong_shape (4.01s)2752PASS2753Running OpenBao signer tests...2754=== RUN TestSign2755=== PAUSE TestSign2756=== RUN TestSignErrors2757=== PAUSE TestSignErrors2758=== RUN TestServe2759=== PAUSE TestServe2760=== RUN TestServeRejectsGarbage2761=== PAUSE TestServeRejectsGarbage2762=== CONT TestSign2763=== CONT TestServeRejectsGarbage2764=== CONT TestSignErrors2765=== RUN TestSignErrors/http_error2766=== CONT TestServe2767--- PASS: TestServeRejectsGarbage (0.00s)2768=== PAUSE TestSignErrors/http_error2769=== RUN TestSignErrors/invalid_json2770=== PAUSE TestSignErrors/invalid_json2771=== RUN TestSignErrors/no_prefix2772=== PAUSE TestSignErrors/no_prefix2773=== RUN TestSignErrors/invalid_base642774=== PAUSE TestSignErrors/invalid_base642775=== CONT TestSignErrors/http_error2776=== CONT TestSignErrors/no_prefix2777=== CONT TestSignErrors/invalid_json2778=== CONT TestSignErrors/invalid_base642779--- PASS: TestServe (0.00s)2780--- PASS: TestSign (0.00s)2781--- PASS: TestSignErrors (0.00s)2782 --- PASS: TestSignErrors/no_prefix (0.00s)2783 --- PASS: TestSignErrors/http_error (0.00s)2784 --- PASS: TestSignErrors/invalid_json (0.00s)2785 --- PASS: TestSignErrors/invalid_base64 (0.00s)2786PASS