niks3-go-unit-tests
checks.aarch64-darwin.go-unit-tests
· build #411
· 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 TestPartSizeForNAR20=== PAUSE TestPartSizeForNAR21=== RUN TestUploadMultipart_SupersededByPeer22=== PAUSE TestUploadMultipart_SupersededByPeer23=== RUN TestDumpPathCaseHackMatchesNix24--- PASS: TestDumpPathCaseHackMatchesNix (0.03s)25=== RUN TestDumpPathCaseHackCollision26--- PASS: TestDumpPathCaseHackCollision (0.00s)27=== RUN TestSupersededNARStillUploadsListing28=== PAUSE TestSupersededNARStillUploadsListing29=== RUN TestDumpPathMatchesNix30=== PAUSE TestDumpPathMatchesNix31=== RUN TestDumpPathSingleFile32=== PAUSE TestDumpPathSingleFile33=== RUN TestDumpPathWriterError34=== PAUSE TestDumpPathWriterError35=== RUN TestEncodeNixBase3236=== PAUSE TestEncodeNixBase3237=== RUN TestEncodeNixBase32WithRealHash38=== PAUSE TestEncodeNixBase32WithRealHash39=== RUN TestConvertHashToNix3240=== PAUSE TestConvertHashToNix3241=== RUN TestGetStorePathHash42=== PAUSE TestGetStorePathHash43=== RUN TestPathInfoHashCompatibility44=== PAUSE TestPathInfoHashCompatibility45=== RUN TestParsePathInfoJSON46=== PAUSE TestParsePathInfoJSON47=== RUN TestParsePathInfoJSONMultiplePaths48=== PAUSE TestParsePathInfoJSONMultiplePaths49=== RUN TestPathInfoCACompatibility50=== PAUSE TestPathInfoCACompatibility51=== RUN TestRateLimiterFeedback52=== PAUSE TestRateLimiterFeedback53=== RUN TestRateLimiterFeedback_400DoesNotCountAsSuccess54=== PAUSE TestRateLimiterFeedback_400DoesNotCountAsSuccess55=== RUN TestRegisterUploadedObject_BoundedAgainstSilentServer56=== PAUSE TestRegisterUploadedObject_BoundedAgainstSilentServer57=== RUN TestResolveStorePath58=== PAUSE TestResolveStorePath59=== RUN TestDoWithRetry_BodyReplayedViaGetBody60=== PAUSE TestDoWithRetry_BodyReplayedViaGetBody61=== RUN TestRetryTimeoutOutlastsMaxRetries62=== PAUSE TestRetryTimeoutOutlastsMaxRetries63=== RUN TestDoWithRetry_FinalResponseBodyReadable64=== PAUSE TestDoWithRetry_FinalResponseBodyReadable65=== RUN TestShellSplit66=== PAUSE TestShellSplit67=== RUN TestShellSplitErrors68=== PAUSE TestShellSplitErrors69=== RUN TestStreamPushReportsEveryPath70=== PAUSE TestStreamPushReportsEveryPath71=== RUN TestStreamPushBatchesUnderLoad72=== PAUSE TestStreamPushBatchesUnderLoad73=== RUN TestStreamPushIsolatesFailures74=== PAUSE TestStreamPushIsolatesFailures75=== RUN TestStreamPushGivesUpOnDeadServer76=== PAUSE TestStreamPushGivesUpOnDeadServer77=== RUN TestStreamPushRequestLine78=== PAUSE TestStreamPushRequestLine79=== RUN TestStreamPushReportsSignatures80=== PAUSE TestStreamPushReportsSignatures81=== RUN TestStreamPushReportsSkippedPaths82=== PAUSE TestStreamPushReportsSkippedPaths83=== RUN TestClientSignaturesByStorePath84=== PAUSE TestClientSignaturesByStorePath85=== RUN TestStreamPushStopsWhenCanceled86=== PAUSE TestStreamPushStopsWhenCanceled87=== RUN TestSetClientTLS88=== PAUSE TestSetClientTLS89=== RUN TestSetClientTLSDoesNotMutateDefaultTransport90=== PAUSE TestSetClientTLSDoesNotMutateDefaultTransport91=== RUN TestSetClientTLSErrors92=== PAUSE TestSetClientTLSErrors93=== RUN TestStaticToken94=== PAUSE TestStaticToken95=== RUN TestFileTokenReadsAndCaches96=== PAUSE TestFileTokenReadsAndCaches97=== RUN TestFileTokenMissing98=== PAUSE TestFileTokenMissing99=== RUN TestFileTokenEmpty100=== PAUSE TestFileTokenEmpty101=== RUN TestScriptTokenNoExpiryRerunsEveryCall102=== PAUSE TestScriptTokenNoExpiryRerunsEveryCall103=== RUN TestScriptTokenCachesUntilRefresh104=== PAUSE TestScriptTokenCachesUntilRefresh105=== RUN TestScriptTokenEmptyToken106=== PAUSE TestScriptTokenEmptyToken107=== RUN TestScriptTokenBadJSON108=== PAUSE TestScriptTokenBadJSON109=== RUN TestScriptTokenScriptFails110=== PAUSE TestScriptTokenScriptFails111=== RUN TestScriptTokenEmptyCommand112=== PAUSE TestScriptTokenEmptyCommand113=== CONT TestDoServerRequestAttachesToken114=== CONT TestRetryTimeoutOutlastsMaxRetries115=== CONT TestEncodeNixBase32116=== RUN TestEncodeNixBase32/test_string_hash117=== PAUSE TestEncodeNixBase32/test_string_hash118=== RUN TestEncodeNixBase32/empty_input119=== PAUSE TestEncodeNixBase32/empty_input120=== CONT TestFileTokenReadsAndCaches121=== CONT TestDoWithRetry_BodyReplayedViaGetBody122=== CONT TestResolveStorePath123=== CONT TestRegisterUploadedObject_BoundedAgainstSilentServer124=== CONT TestRateLimiterFeedback_400DoesNotCountAsSuccess125=== CONT TestRateLimiterFeedback1262026/10/11 05:57:15 WARN Rate limiter enabled after throttle name=server-test rate=5127=== CONT TestPathInfoCACompatibility128--- PASS: TestFileTokenReadsAndCaches (0.00s)129=== CONT TestParsePathInfoJSONMultiplePaths130=== CONT TestParsePathInfoJSON131=== CONT TestPathInfoHashCompatibility132=== CONT TestStaticToken133--- PASS: TestStaticToken (0.00s)134=== CONT TestSetClientTLSErrors135=== RUN TestPathInfoCACompatibility/null_ca_field136=== CONT TestGetStorePathHash137=== CONT TestConvertHashToNix32138=== CONT TestEncodeNixBase32WithRealHash139=== CONT TestSetClientTLS140=== CONT TestScriptTokenEmptyCommand141=== CONT TestScriptTokenScriptFails142=== CONT TestScriptTokenBadJSON143=== CONT TestScriptTokenEmptyToken144=== CONT TestScriptTokenCachesUntilRefresh145=== CONT TestScriptTokenNoExpiryRerunsEveryCall146=== CONT TestFileTokenEmpty147=== CONT TestFileTokenMissing148=== RUN TestRateLimiterFeedback/429_enables_limiter149=== RUN TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths150=== RUN TestParsePathInfoJSON/Nix_format151=== RUN TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)152=== PAUSE TestParsePathInfoJSON/Nix_format153=== RUN TestParsePathInfoJSON/Lix_format154=== PAUSE TestParsePathInfoJSON/Lix_format155=== RUN TestParsePathInfoJSON/empty_input156=== PAUSE TestParsePathInfoJSON/empty_input157=== RUN TestGetStorePathHash/valid_store_path158--- PASS: TestEncodeNixBase32WithRealHash (0.00s)159=== PAUSE TestGetStorePathHash/valid_store_path160=== RUN TestGetStorePathHash/basename_without_hyphen_should_error161=== RUN TestParsePathInfoJSON/whitespace_only162--- PASS: TestScriptTokenEmptyCommand (0.00s)163=== CONT TestRunGarbageCollection_NotFoundAfterLocalRun164=== RUN TestConvertHashToNix32/SRI_format_to_Nix32165=== PAUSE TestParsePathInfoJSON/whitespace_only166=== RUN TestParsePathInfoJSON/invalid_JSON167=== PAUSE TestParsePathInfoJSON/invalid_JSON168=== PAUSE TestGetStorePathHash/basename_without_hyphen_should_error169--- PASS: TestResolveStorePath (0.00s)170=== CONT TestSetClientTLSDoesNotMutateDefaultTransport171=== RUN TestGetStorePathHash/hash_with_invalid_characters_should_error172=== PAUSE TestGetStorePathHash/hash_with_invalid_characters_should_error173=== RUN TestGetStorePathHash/hash_with_wrong_length_should_error174=== PAUSE TestGetStorePathHash/hash_with_wrong_length_should_error175=== PAUSE TestPathInfoCACompatibility/null_ca_field176=== PAUSE TestRateLimiterFeedback/429_enables_limiter177=== PAUSE TestConvertHashToNix32/SRI_format_to_Nix32178=== RUN TestRateLimiterFeedback/503_enables_limiter179=== RUN TestConvertHashToNix32/already_Nix32_format180=== CONT TestFilterOversizedClosures181=== CONT TestCaseHackSuffix182=== CONT TestDumpPathMatchesNix183=== RUN TestPathInfoCACompatibility/old_string_format_-_text184=== RUN TestFilterOversizedClosures/no_limit_keeps_everything185=== PAUSE TestFilterOversizedClosures/no_limit_keeps_everything186=== RUN TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped187=== PAUSE TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped188=== RUN TestFilterOversizedClosures/all_closures_skipped189=== PAUSE TestFilterOversizedClosures/all_closures_skipped190=== CONT TestDumpPathWriterError191=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)192=== RUN TestPathInfoHashCompatibility/old_string_format_with_colon193=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_colon194=== RUN TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI195=== PAUSE TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI196=== RUN TestPathInfoHashCompatibility/new_structured_format_with_sha512197=== PAUSE TestPathInfoHashCompatibility/new_structured_format_with_sha512198=== CONT TestDumpPathSingleFile1992026/10/11 05:57:15 WARN Request returned retryable status, retrying attempt=1 backoff=1ms status=502 url=http://127.0.0.1:59562200=== PAUSE TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths201=== RUN TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths202=== PAUSE TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths203=== CONT TestRegisterUploadedObjectReusesConnections204=== PAUSE TestRateLimiterFeedback/503_enables_limiter205=== RUN TestRateLimiterFeedback/200_does_not_enable_limiter206=== PAUSE TestRateLimiterFeedback/200_does_not_enable_limiter207=== RUN TestRateLimiterFeedback/400_does_not_enable_limiter208=== PAUSE TestRateLimiterFeedback/400_does_not_enable_limiter209=== PAUSE TestConvertHashToNix32/already_Nix32_format210=== RUN TestConvertHashToNix32/invalid_format211=== PAUSE TestConvertHashToNix32/invalid_format212=== CONT TestRunGarbageCollection_FinishedOnAnotherReplica213=== CONT TestUploadMultipart_SupersededByPeer214=== RUN TestUploadMultipart_SupersededByPeer/exists215=== PAUSE TestUploadMultipart_SupersededByPeer/exists216=== RUN TestUploadMultipart_SupersededByPeer/missing217=== PAUSE TestUploadMultipart_SupersededByPeer/missing218=== CONT TestSupersededNARStillUploadsListing219=== RUN TestSupersededNARStillUploadsListing/small_NAR220=== PAUSE TestSupersededNARStillUploadsListing/small_NAR221=== RUN TestSupersededNARStillUploadsListing/dump_cut_short222=== PAUSE TestSupersededNARStillUploadsListing/dump_cut_short223=== RUN TestSupersededNARStillUploadsListing/listing_upload_fails224=== PAUSE TestSupersededNARStillUploadsListing/listing_upload_fails225=== CONT TestStreamPushGivesUpOnDeadServer226--- PASS: TestFileTokenEmpty (0.00s)227=== CONT TestStreamPushStopsWhenCanceled228=== CONT TestClientSignaturesByStorePath229--- PASS: TestClientSignaturesByStorePath (0.00s)230=== CONT TestStreamPushReportsSignatures231=== PAUSE TestPathInfoCACompatibility/old_string_format_-_text232=== RUN TestPathInfoCACompatibility/old_string_format_-_fixed_recursive233=== PAUSE TestPathInfoCACompatibility/old_string_format_-_fixed_recursive234=== RUN TestPathInfoCACompatibility/new_structured_format_-_text235=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_text236=== RUN TestPathInfoCACompatibility/new_structured_format_-_nar_method237=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_nar_method238=== CONT TestStreamPushRequestLine239--- PASS: TestScriptTokenScriptFails (0.00s)240=== CONT TestUploadBuildLog_FileBodyReplayedOnRetry2412026/10/11 05:57:15 WARN Rate limiter enabled after throttle name=server-test rate=52422026/10/11 05:57:15 ERROR Upload failed error=boom count=1243--- PASS: TestStreamPushReportsSignatures (0.00s)2442026/10/11 05:57:15 ERROR Upload failed error=boom count=12452026/10/11 05:57:15 ERROR Upload failed error="connection refused" count=20246=== CONT TestUploadMultipart_PartsInParallel2472026/10/11 05:57:15 ERROR Server seems unavailable, giving up on batch untried=172482026/10/11 05:57:15 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:59565249=== CONT TestStreamPushReportsSkippedPaths250=== CONT TestPartSizeForNAR251=== RUN TestPartSizeForNAR/zero_stays_at_minimum252=== PAUSE TestPartSizeForNAR/zero_stays_at_minimum253=== RUN TestPartSizeForNAR/small_stays_at_minimum254=== PAUSE TestPartSizeForNAR/small_stays_at_minimum255=== CONT TestShellSplit2562026/10/11 05:57:15 WARN Request returned retryable status, retrying attempt=2 backoff=1ms status=502 url=http://127.0.0.1:59562257=== RUN TestSetClientTLS/rejects_connection_without_client_cert258=== RUN TestPartSizeForNAR/80_GiB_fits_at_minimum259=== CONT TestStreamPushReportsEveryPath260=== PAUSE TestSetClientTLS/rejects_connection_without_client_cert261--- PASS: TestSetClientTLSDoesNotMutateDefaultTransport (0.00s)262--- PASS: TestStreamPushGivesUpOnDeadServer (0.00s)263--- PASS: TestStreamPushReportsSkippedPaths (0.00s)264--- PASS: TestShellSplit (0.00s)265--- PASS: TestDoServerRequestAttachesToken (0.01s)266=== RUN TestSetClientTLSErrors/missing_cert_file267=== RUN TestSetClientTLS/succeeds_with_client_cert_and_CA268=== PAUSE TestPartSizeForNAR/80_GiB_fits_at_minimum269=== RUN TestPartSizeForNAR/115_GiB_needs_larger_parts270=== PAUSE TestPartSizeForNAR/115_GiB_needs_larger_parts271=== RUN TestPartSizeForNAR/1_TiB272=== PAUSE TestPartSizeForNAR/1_TiB273=== RUN TestPartSizeForNAR/5_TiB_S3_max_object274=== PAUSE TestPartSizeForNAR/5_TiB_S3_max_object275=== RUN TestPartSizeForNAR/capped_at_5_GiB276=== PAUSE TestPartSizeForNAR/capped_at_5_GiB277--- PASS: TestStreamPushStopsWhenCanceled (0.01s)278=== CONT TestStreamPushIsolatesFailures2792026/10/11 05:57:15 INFO Garbage collection started2802026/10/11 05:57:15 INFO Garbage collection started2812026/10/11 05:57:15 WARN Request returned retryable status, retrying attempt=1 backoff=1ms status=502 url=http://127.0.0.1:595622822026/10/11 05:57:15 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=02832026/10/11 05:57:15 WARN Request returned retryable status, retrying attempt=2 backoff=1ms status=502 url=http://127.0.0.1:595622842026/10/11 05:57:15 ERROR Upload failed error="bad path" count=32852026/10/11 05:57:15 WARN Garbage collection finished on another replica. Its statistics are not available here286=== PAUSE TestSetClientTLSErrors/missing_cert_file2872026/10/11 05:57:15 WARN Rate limiter backed off name=server-test rate=5288=== PAUSE TestSetClientTLS/succeeds_with_client_cert_and_CA289=== CONT TestShellSplitErrors290--- PASS: TestRunGarbageCollection_NotFoundAfterLocalRun (0.02s)291--- PASS: TestStreamPushIsolatesFailures (0.01s)292=== CONT TestStreamPushBatchesUnderLoad293=== CONT TestDoWithRetry_FinalResponseBodyReadable2942026/10/11 05:57:15 WARN Request returned retryable status, retrying attempt=2 backoff=0s status=503 url=http://127.0.0.1:59565295=== CONT TestEncodeNixBase32/test_string_hash296=== CONT TestParsePathInfoJSON/invalid_JSON297=== CONT TestParsePathInfoJSON/empty_input298=== CONT TestParsePathInfoJSON/whitespace_only299=== CONT TestParsePathInfoJSON/Lix_format300=== CONT TestEncodeNixBase32/empty_input301=== RUN TestSetClientTLSErrors/missing_key_file302=== PAUSE TestSetClientTLSErrors/missing_key_file303=== RUN TestSetClientTLS/preserves_debug_logging_transport304=== RUN TestSetClientTLSErrors/missing_ca_file305=== CONT TestGetStorePathHash/hash_with_invalid_characters_should_error306=== CONT TestGetStorePathHash/basename_without_hyphen_should_error307=== CONT TestGetStorePathHash/valid_store_path308=== CONT TestFilterOversizedClosures/no_limit_keeps_everything309=== CONT TestFilterOversizedClosures/all_closures_skipped3102026/10/11 05:57:15 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=50311=== CONT TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped3122026/10/11 05:57:15 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=2000313=== CONT TestPathInfoHashCompatibility/new_structured_format_with_sha512314=== PAUSE TestSetClientTLS/preserves_debug_logging_transport315=== PAUSE TestSetClientTLSErrors/missing_ca_file316=== RUN TestSetClientTLSErrors/invalid_ca_file317=== PAUSE TestSetClientTLSErrors/invalid_ca_file318=== CONT TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)319--- PASS: TestRunGarbageCollection_FinishedOnAnotherReplica (0.02s)320=== CONT TestGetStorePathHash/hash_with_wrong_length_should_error321=== CONT TestPathInfoHashCompatibility/old_string_format_with_colon322=== CONT TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths323=== CONT TestRateLimiterFeedback/429_enables_limiter324=== CONT TestConvertHashToNix32/SRI_format_to_Nix32325=== CONT TestConvertHashToNix32/invalid_format326=== CONT TestUploadMultipart_SupersededByPeer/exists327=== CONT TestSupersededNARStillUploadsListing/small_NAR328=== CONT TestParsePathInfoJSON/Nix_format329--- PASS: TestFileTokenMissing (0.02s)330--- PASS: TestScriptTokenEmptyToken (0.02s)331=== CONT TestConvertHashToNix32/already_Nix32_format332=== CONT TestSupersededNARStillUploadsListing/listing_upload_fails333=== CONT TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI334=== CONT TestSupersededNARStillUploadsListing/dump_cut_short335=== CONT TestUploadMultipart_SupersededByPeer/missing336--- PASS: TestStreamPushReportsEveryPath (0.01s)337--- PASS: TestShellSplitErrors (0.00s)338--- PASS: TestScriptTokenBadJSON (0.02s)339=== CONT TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths340--- PASS: TestParsePathInfoJSONMultiplePaths (0.00s)341 --- PASS: TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths (0.00s)342 --- PASS: TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths (0.00s)343=== CONT TestRateLimiterFeedback/503_enables_limiter3442026/10/11 05:57:15 INFO Uploading abc-hello (1.0GB)3452026/10/11 05:57:15 INFO Uploading abc-hello (1.0GB)346--- PASS: TestParsePathInfoJSON (0.00s)347 --- PASS: TestParsePathInfoJSON/invalid_JSON (0.00s)348 --- PASS: TestParsePathInfoJSON/empty_input (0.00s)349 --- PASS: TestParsePathInfoJSON/whitespace_only (0.00s)350 --- PASS: TestParsePathInfoJSON/Lix_format (0.00s)351 --- PASS: TestParsePathInfoJSON/Nix_format (0.00s)352=== CONT TestRateLimiterFeedback/400_does_not_enable_limiter353--- PASS: TestDoWithRetry_BodyReplayedViaGetBody (0.03s)354=== CONT TestRateLimiterFeedback/200_does_not_enable_limiter355--- PASS: TestConvertHashToNix32 (0.00s)356 --- PASS: TestConvertHashToNix32/SRI_format_to_Nix32 (0.00s)357 --- PASS: TestConvertHashToNix32/invalid_format (0.00s)358 --- PASS: TestConvertHashToNix32/already_Nix32_format (0.00s)359--- PASS: TestEncodeNixBase32 (0.00s)360 --- PASS: TestEncodeNixBase32/test_string_hash (0.00s)361 --- PASS: TestEncodeNixBase32/empty_input (0.00s)362--- PASS: TestFilterOversizedClosures (0.00s)363 --- PASS: TestFilterOversizedClosures/no_limit_keeps_everything (0.00s)364 --- PASS: TestFilterOversizedClosures/all_closures_skipped (0.00s)365 --- PASS: TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped (0.00s)3662026/10/11 05:57:15 WARN Rate limiter enabled after throttle name=server-test rate=53672026/10/11 05:57:15 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:59656368=== CONT TestPathInfoCACompatibility/null_ca_field369=== CONT TestPathInfoCACompatibility/new_structured_format_-_nar_method370=== CONT TestPathInfoCACompatibility/new_structured_format_-_text371=== CONT TestPathInfoCACompatibility/old_string_format_-_fixed_recursive372=== CONT TestPathInfoCACompatibility/old_string_format_-_text373--- PASS: TestPathInfoCACompatibility (0.01s)374 --- PASS: TestPathInfoCACompatibility/null_ca_field (0.00s)375 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_nar_method (0.00s)376 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_text (0.00s)377 --- PASS: TestPathInfoCACompatibility/old_string_format_-_fixed_recursive (0.00s)378 --- PASS: TestPathInfoCACompatibility/old_string_format_-_text (0.00s)379=== CONT TestPartSizeForNAR/zero_stays_at_minimum380=== CONT TestPartSizeForNAR/capped_at_5_GiB381=== CONT TestPartSizeForNAR/small_stays_at_minimum382=== CONT TestPartSizeForNAR/1_TiB383=== CONT TestPartSizeForNAR/115_GiB_needs_larger_parts384=== CONT TestPartSizeForNAR/80_GiB_fits_at_minimum385=== CONT TestPartSizeForNAR/5_TiB_S3_max_object386--- PASS: TestPartSizeForNAR (0.00s)387 --- PASS: TestPartSizeForNAR/zero_stays_at_minimum (0.00s)388 --- PASS: TestPartSizeForNAR/capped_at_5_GiB (0.00s)389 --- PASS: TestPartSizeForNAR/small_stays_at_minimum (0.00s)390 --- PASS: TestPartSizeForNAR/1_TiB (0.00s)391 --- PASS: TestPartSizeForNAR/115_GiB_needs_larger_parts (0.00s)392 --- PASS: TestPartSizeForNAR/80_GiB_fits_at_minimum (0.00s)393 --- PASS: TestPartSizeForNAR/5_TiB_S3_max_object (0.00s)3942026/10/11 05:57:15 WARN Rate limiter enabled after throttle name=server-test rate=53952026/10/11 05:57:15 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=429 url=http://127.0.0.1:596493962026/10/11 05:57:15 WARN Rate limiter backed off name=server-test rate=53972026/10/11 05:57:15 WARN Request returned retryable status, retrying attempt=3 backoff=1ms status=502 url=http://127.0.0.1:59562398=== CONT TestSetClientTLS/rejects_connection_without_client_cert3992026/10/11 05:57:15 WARN Rate limiter backed off name=server-test rate=54002026/10/11 05:57:15 WARN Rate limiter enabled after throttle name=s3-test rate=54012026/10/11 05:57:15 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:59642402=== CONT TestSetClientTLS/preserves_debug_logging_transport403=== CONT TestSetClientTLSErrors/missing_cert_file404=== CONT TestSetClientTLSErrors/invalid_ca_file405--- PASS: TestRateLimiterFeedback (0.00s)406 --- PASS: TestRateLimiterFeedback/400_does_not_enable_limiter (0.00s)407 --- PASS: TestRateLimiterFeedback/200_does_not_enable_limiter (0.00s)408 --- PASS: TestRateLimiterFeedback/503_enables_limiter (0.00s)409 --- PASS: TestRateLimiterFeedback/429_enables_limiter (0.00s)410--- PASS: TestPathInfoHashCompatibility (0.01s)411 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_colon (0.00s)412 --- PASS: TestPathInfoHashCompatibility/new_structured_format_with_sha512 (0.00s)413 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) (0.00s)414 --- PASS: TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI (0.00s)415=== CONT TestSetClientTLS/succeeds_with_client_cert_and_CA416--- PASS: TestGetStorePathHash (0.00s)417 --- PASS: TestGetStorePathHash/hash_with_invalid_characters_should_error (0.00s)418 --- PASS: TestGetStorePathHash/basename_without_hyphen_should_error (0.00s)419 --- PASS: TestGetStorePathHash/valid_store_path (0.00s)420 --- PASS: TestGetStorePathHash/hash_with_wrong_length_should_error (0.00s)421=== CONT TestSetClientTLSErrors/missing_ca_file422=== CONT TestSetClientTLSErrors/missing_key_file4232026/10/11 05:57:15 WARN Rate limiter enabled after throttle name=server-test rate=54242026/10/11 05:57:15 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:596474252026/10/11 05:57:15 WARN Request returned retryable status, retrying attempt=4 backoff=1ms status=502 url=http://127.0.0.1:595624262026/10/11 05:57:15 WARN Rate limiter backed off name=server-test rate=5427--- PASS: TestSetClientTLSErrors (0.02s)428 --- PASS: TestSetClientTLSErrors/missing_cert_file (0.00s)429 --- PASS: TestSetClientTLSErrors/invalid_ca_file (0.00s)430 --- PASS: TestSetClientTLSErrors/missing_ca_file (0.00s)431 --- PASS: TestSetClientTLSErrors/missing_key_file (0.00s)432--- PASS: TestStreamPushRequestLine (0.02s)433--- PASS: TestUploadBuildLog_FileBodyReplayedOnRetry (0.02s)434--- PASS: TestUploadMultipart_SupersededByPeer (0.00s)435 --- PASS: TestUploadMultipart_SupersededByPeer/missing (0.00s)436 --- PASS: TestUploadMultipart_SupersededByPeer/exists (0.01s)437--- PASS: TestDoWithRetry_FinalResponseBodyReadable (0.01s)4382026/10/11 05:57:15 WARN Request returned retryable status, retrying attempt=5 backoff=1ms status=502 url=http://127.0.0.1:595624392026/10/11 05:57:15 WARN Request returned retryable status, retrying attempt=6 backoff=1ms status=502 url=http://127.0.0.1:595624402026/10/11 05:57:15 WARN Request returned retryable status, retrying attempt=7 backoff=1ms status=502 url=http://127.0.0.1:595624412026/10/11 05:57:15 WARN Request returned retryable status, retrying attempt=8 backoff=1ms status=502 url=http://127.0.0.1:595624422026/10/11 05:57:15 WARN Request returned retryable status, retrying attempt=9 backoff=1ms status=502 url=http://127.0.0.1:59562443--- PASS: TestScriptTokenCachesUntilRefresh (0.04s)4442026/10/11 05:57:15 WARN Request returned retryable status, retrying attempt=10 backoff=1ms status=502 url=http://127.0.0.1:595624452026/10/11 05:57:15 http: TLS handshake error from 127.0.0.1:59664: read tcp 127.0.0.1:59577->127.0.0.1:59664: use of closed network connection446--- PASS: TestSetClientTLS (0.02s)447 --- PASS: TestSetClientTLS/succeeds_with_client_cert_and_CA (0.01s)448 --- PASS: TestSetClientTLS/preserves_debug_logging_transport (0.01s)449 --- PASS: TestSetClientTLS/rejects_connection_without_client_cert (0.02s)4502026/10/11 05:57:15 WARN Request returned retryable status, retrying attempt=11 backoff=1ms status=502 url=http://127.0.0.1:595624512026/10/11 05:57:15 WARN Request returned retryable status, retrying attempt=12 backoff=1ms status=502 url=http://127.0.0.1:59562452--- PASS: TestRegisterUploadedObjectReusesConnections (0.05s)4532026/10/11 05:57:15 WARN Request returned retryable status, retrying attempt=13 backoff=1ms status=502 url=http://127.0.0.1:59562454--- PASS: TestScriptTokenNoExpiryRerunsEveryCall (0.06s)4552026/10/11 05:57:15 WARN Request returned retryable status, retrying attempt=14 backoff=1ms status=502 url=http://127.0.0.1:595624562026/10/11 05:57:15 WARN Request returned retryable status, retrying attempt=15 backoff=1ms status=502 url=http://127.0.0.1:595624572026/10/11 05:57:15 WARN Request returned retryable status, retrying attempt=16 backoff=1ms status=502 url=http://127.0.0.1:595624582026/10/11 05:57:15 WARN Request returned retryable status, retrying attempt=17 backoff=1ms status=502 url=http://127.0.0.1:59562459--- PASS: TestRetryTimeoutOutlastsMaxRetries (0.06s)460--- PASS: TestDumpPathWriterError (0.06s)4612026/10/11 05:57:15 INFO Uploading abc-hello (1.0GB)462--- PASS: TestDumpPathSingleFile (0.07s)4632026/10/11 05:57:15 WARN Request failed, retrying attempt=1 backoff=100ms error="Put \"http://127.0.0.1:59654/part/2\": uploading part 1: server returned 404: no such upload\n" url=http://127.0.0.1:59654/part/24642026/10/11 05:57:15 ERROR Failed to close zstd encoder error="io: read/write on closed pipe"465--- PASS: TestCaseHackSuffix (0.08s)466--- PASS: TestDumpPathMatchesNix (0.10s)467--- PASS: TestStreamPushBatchesUnderLoad (0.10s)468--- PASS: TestSupersededNARStillUploadsListing (0.00s)469 --- PASS: TestSupersededNARStillUploadsListing/listing_upload_fails (0.01s)470 --- PASS: TestSupersededNARStillUploadsListing/small_NAR (0.01s)471 --- PASS: TestSupersededNARStillUploadsListing/dump_cut_short (0.55s)472--- PASS: TestUploadMultipart_PartsInParallel (0.61s)4732026/10/11 05:57:16 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:59567/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:59567/api/uploads/complete4742026/10/11 05:57:16 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"4752026/10/11 05:57:16 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:59567/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:59567/api/uploads/complete4762026/10/11 05:57:16 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"4772026/10/11 05:57:16 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:59567/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:59567/api/uploads/complete4782026/10/11 05:57:16 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"479--- PASS: TestRegisterUploadedObject_BoundedAgainstSilentServer (1.00s)480--- PASS: TestRateLimiterFeedback_400DoesNotCountAsSuccess (1.00s)481PASS482Running server tests...483The files belonging to this database system will be owned by user "_tribuchetbld3".484This user must also own the server process.485486The database cluster will be initialized with locale "C".487The default database encoding has accordingly been set to "SQL_ASCII".488The default text search configuration will be set to "english".489490Data page checksums are enabled.491492creating directory /private/var/tb/3/scratch/7155a60ad86daa12/build/postgres1925003058/data ... ok493creating subdirectories ... ok494selecting dynamic shared memory implementation ... posix495selecting default "max_connections" ... 100496selecting default "shared_buffers" ... 128MB497selecting default time zone ... UTC498creating configuration files ... ok499running bootstrap script ... ok500performing post-bootstrap initialization ... ok501syncing data to disk ... ok502503initdb: warning: enabling "trust" authentication for local connections504initdb: 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.505506Success. You can now start the database server using:507508 pg_ctl -D /private/var/tb/3/scratch/7155a60ad86daa12/build/postgres1925003058/data -l logfile start509510/private/var/tb/3/scratch/7155a60ad86daa12/build/postgres1925003058:5432 - no response5112026-10-11 05:57:16.733 UTC [91848] LOG: starting PostgreSQL 18.6 on aarch64-apple-darwin25.6.0, compiled by clang version 21.1.8, 64-bit5122026-10-11 05:57:16.733 UTC [91848] LOG: listening on Unix socket "/private/var/tb/3/scratch/7155a60ad86daa12/build/postgres1925003058/.s.PGSQL.5432"5132026-10-11 05:57:16.735 UTC [91855] LOG: database system was shut down at 2026-10-11 05:57:16 UTC5142026-10-11 05:57:16.736 UTC [91848] LOG: database system is ready to accept connections515/private/var/tb/3/scratch/7155a60ad86daa12/build/postgres1925003058:5432 - accepting connections516=== RUN TestService_AuthMiddleware517=== PAUSE TestService_AuthMiddleware518=== RUN TestService_AuthMiddleware_MTLSProxyHeader519=== PAUSE TestService_AuthMiddleware_MTLSProxyHeader520=== RUN TestService_AuthMiddleware_MTLSBoundSubjects521=== PAUSE TestService_AuthMiddleware_MTLSBoundSubjects522=== RUN TestService_ReadAuthMiddleware523=== PAUSE TestService_ReadAuthMiddleware524=== RUN TestService_AuthMiddleware_OIDC525=== PAUSE TestService_AuthMiddleware_OIDC526=== RUN TestService_RequireScope_OIDC527=== PAUSE TestService_RequireScope_OIDC528=== RUN TestService_ReadScope_PublicByDefault529=== PAUSE TestService_ReadScope_PublicByDefault530=== RUN TestCacheConfigHandler531=== PAUSE TestCacheConfigHandler532=== RUN TestCacheStatsHandler533=== PAUSE TestCacheStatsHandler534=== RUN TestClientCADerivations535=== PAUSE TestClientCADerivations536=== RUN TestClientErrorHandling537=== PAUSE TestClientErrorHandling538=== RUN TestClientIntegration539=== PAUSE TestClientIntegration540=== RUN TestClientMultipleUploads541=== PAUSE TestClientMultipleUploads542=== RUN TestClientWithDependencies543=== PAUSE TestClientWithDependencies544=== RUN TestClientSharedPathCommittedMidPush545=== PAUSE TestClientSharedPathCommittedMidPush546=== RUN TestPinProtectsFromGC547=== PAUSE TestPinProtectsFromGC548=== RUN TestClientPushesUseOnePush549=== PAUSE TestClientPushesUseOnePush550=== RUN TestClientFallsBackToClosures551=== PAUSE TestClientFallsBackToClosures552=== RUN TestDeleteClosuresRacingPins553=== PAUSE TestDeleteClosuresRacingPins554=== RUN TestConcurrentCommitsSharingObjectsDoNotDeadlock555=== PAUSE TestConcurrentCommitsSharingObjectsDoNotDeadlock556=== RUN TestResolveDBConnectionString557=== PAUSE TestResolveDBConnectionString558=== RUN TestConnectWaitsForAPeerMigration559=== PAUSE TestConnectWaitsForAPeerMigration560=== RUN TestLeadElectsOneAndHandsOver561=== PAUSE TestLeadElectsOneAndHandsOver562=== RUN TestLeadIncumbentWinsAfterRestart5632026/10/11 05:57:17 INFO lead: acquired remote=192.0.2.1:12345642026/10/11 05:57:17 INFO lead: released remote=192.0.2.1:12345652026/10/11 05:57:17 INFO lead: acquired remote=192.0.2.1:12345662026/10/11 05:57:18 INFO lead: released remote=192.0.2.1:1234567--- PASS: TestLeadIncumbentWinsAfterRestart (2.02s)568=== RUN TestLeadIncumbentAnnouncesAtOnce569=== PAUSE TestLeadIncumbentAnnouncesAtOnce570=== RUN TestLeadEndsOnShutdown571=== PAUSE TestLeadEndsOnShutdown572=== RUN TestLeadEndsWhenItsConnectionHangs5732026/10/11 05:57:19 INFO lead: acquired remote=192.0.2.1:12345742026-10-11 05:57:20.343 UTC [91890] FATAL: terminating connection due to administrator command5752026/10/11 05:57:20 INFO lead: acquired remote=192.0.2.1:12345762026/10/11 05:57:21 WARN lead: lock connection lost error="timeout: context deadline exceeded"5772026/10/11 05:57:21 INFO lead: released remote=192.0.2.1:12345782026/10/11 05:57:21 INFO lead: released remote=192.0.2.1:1234579--- PASS: TestLeadEndsWhenItsConnectionHangs (2.77s)580=== RUN TestGCAdvisoryLockBlocksConcurrentRun581=== PAUSE TestGCAdvisoryLockBlocksConcurrentRun582=== RUN TestGCBugBareHashReferences583=== PAUSE TestGCBugBareHashReferences584=== RUN TestGCMetrics585=== PAUSE TestGCMetrics586=== RUN TestPushDedupSurvivesConcurrentGC587=== PAUSE TestPushDedupSurvivesConcurrentGC588=== RUN TestDeduplicatedObjectsRecordedAsPending589=== PAUSE TestDeduplicatedObjectsRecordedAsPending590=== RUN TestGCSweepSkipsPendingObjects591=== PAUSE TestGCSweepSkipsPendingObjects592=== RUN TestTombstonedObjectOfferedWithoutWaiting593=== PAUSE TestTombstonedObjectOfferedWithoutWaiting594=== RUN TestGCSweepDeliversEachKeyOnce595=== PAUSE TestGCSweepDeliversEachKeyOnce596=== RUN TestCreatePendingClosureVerifyS3FailureReleasesConnection597=== PAUSE TestCreatePendingClosureVerifyS3FailureReleasesConnection598=== RUN TestForceGCDuringPushOffersSweptObject599=== PAUSE TestForceGCDuringPushOffersSweptObject600=== RUN TestFailedS3DeleteKeepsTombstone601=== PAUSE TestFailedS3DeleteKeepsTombstone602=== RUN TestSweepSkipsRowsLockedByPush603=== PAUSE TestSweepSkipsRowsLockedByPush604=== RUN TestRegisterCompletedObjectNeedsPendingRow605=== PAUSE TestRegisterCompletedObjectNeedsPendingRow606=== RUN TestGetExistingObjectsLocksRows607=== PAUSE TestGetExistingObjectsLocksRows608=== RUN TestSweepRechecksPendingAfterLocking609=== PAUSE TestSweepRechecksPendingAfterLocking610=== RUN TestPushWaitsForSweepHoldingRow611=== PAUSE TestPushWaitsForSweepHoldingRow612=== RUN TestCommitRacingPendingCleanupKeepsObjects613=== PAUSE TestCommitRacingPendingCleanupKeepsObjects614=== RUN TestGCEndsOnShutdown615=== PAUSE TestGCEndsOnShutdown616=== RUN TestGCTaskStore_StartNew617=== PAUSE TestGCTaskStore_StartNew618=== RUN TestGCTaskStore_DeduplicateSameParams619=== PAUSE TestGCTaskStore_DeduplicateSameParams620=== RUN TestGCTaskStore_ConflictDifferentParams621=== PAUSE TestGCTaskStore_ConflictDifferentParams622=== RUN TestGCTaskStore_GetEmpty623=== PAUSE TestGCTaskStore_GetEmpty624=== RUN TestGCTaskStore_GetReturnsLatest625=== PAUSE TestGCTaskStore_GetReturnsLatest626=== RUN TestGCTaskStore_CompletedAllowsNewTask627=== PAUSE TestGCTaskStore_CompletedAllowsNewTask628=== RUN TestGCTaskStore_PhaseUpdates629=== PAUSE TestGCTaskStore_PhaseUpdates630=== RUN TestGCTaskStore_Fail631=== PAUSE TestGCTaskStore_Fail632=== RUN TestGracefulShutdownDrainsInflight633=== PAUSE TestGracefulShutdownDrainsInflight634=== RUN TestService_healthCheckHandler635=== PAUSE TestService_healthCheckHandler636=== RUN TestService_readinessHandler637=== PAUSE TestService_readinessHandler638=== RUN TestGenerateLandingPage639=== PAUSE TestGenerateLandingPage640=== RUN TestCacheConfigHandlerMaxNarSize641=== PAUSE TestCacheConfigHandlerMaxNarSize642=== RUN TestCreatePendingClosureRejectsOversizedNAR643=== PAUSE TestCreatePendingClosureRejectsOversizedNAR644=== RUN TestNARDeduplicationMetadataUploadBug645=== PAUSE TestNARDeduplicationMetadataUploadBug646=== RUN TestMetricsInventory647=== PAUSE TestMetricsInventory648=== RUN TestMetricsCommit649=== PAUSE TestMetricsCommit650=== RUN TestService_NativeMTLS651=== PAUSE TestService_NativeMTLS652=== RUN TestServerTLSConfig653=== PAUSE TestServerTLSConfig654=== RUN TestMultipartCleanup655=== PAUSE TestMultipartCleanup656=== RUN TestMultipartUploadAbortedWhenCancelledBeforeRecorded657=== PAUSE TestMultipartUploadAbortedWhenCancelledBeforeRecorded658=== RUN TestPendingCleanupUsesOneCutoff659=== PAUSE TestPendingCleanupUsesOneCutoff660=== RUN TestObjectStatsTrigger661=== PAUSE TestObjectStatsTrigger662=== RUN TestObjectStatsLargeCommit663=== PAUSE TestObjectStatsLargeCommit664=== RUN TestOrphanedObjectsGC665=== PAUSE TestOrphanedObjectsGC666=== RUN TestOrphanedObjectsGCStressTest667=== PAUSE TestOrphanedObjectsGCStressTest668=== RUN TestCreatePin_ReservedPins669=== PAUSE TestCreatePin_ReservedPins670=== RUN TestPresentReportsOnlyClosureRoots671=== PAUSE TestPresentReportsOnlyClosureRoots672=== RUN TestPresentRefreshesOnlyStaleClosures673=== PAUSE TestPresentRefreshesOnlyStaleClosures674=== RUN TestPresentNotReportedWhileGCDeletesClosure675=== PAUSE TestPresentNotReportedWhileGCDeletesClosure676=== RUN TestParseSingleRange677=== PAUSE TestParseSingleRange678=== RUN TestProxyHeadersOnlyTrustedOnSocket6792026/10/11 05:57:21 INFO Starting HTTP server address=127.0.0.1:596926802026/10/11 05:57:21 INFO Starting HTTP server address=proxy.sock6812026/10/11 05:57:21 WARN mTLS auth: subject not in bound subjects subject="CN=someone"6822026/10/11 05:57:21 INFO Shutdown signal received, draining in-flight requests timeout=10s683--- PASS: TestProxyHeadersOnlyTrustedOnSocket (0.16s)684=== RUN TestIsValidCachePath685=== PAUSE TestIsValidCachePath686=== RUN TestReadProxyNarinfo687=== PAUSE TestReadProxyNarinfo688=== RUN TestReadProxyNarinfoAlreadyDecompressed689=== PAUSE TestReadProxyNarinfoAlreadyDecompressed690=== RUN TestReadProxyContentNegotiation691=== PAUSE TestReadProxyContentNegotiation692=== RUN TestReadProxyNarStreaming693=== PAUSE TestReadProxyNarStreaming694=== RUN TestReadProxy404695=== PAUSE TestReadProxy404696=== RUN TestReadProxyInvalidPath697=== PAUSE TestReadProxyInvalidPath698=== RUN TestReadProxyHead699=== PAUSE TestReadProxyHead700=== RUN TestReadProxyOutlastsServerWriteTimeout701=== PAUSE TestReadProxyOutlastsServerWriteTimeout702=== RUN TestReadProxyConditionalGet703=== PAUSE TestReadProxyConditionalGet704=== RUN TestReadProxyRootRedirectsToIndexHTML705=== PAUSE TestReadProxyRootRedirectsToIndexHTML706=== RUN TestReadProxyDisabled707=== PAUSE TestReadProxyDisabled708=== RUN TestReadRedirectNar709=== PAUSE TestReadRedirectNar710=== RUN TestReadRedirectKeepsNarinfoProxied711=== PAUSE TestReadRedirectKeepsNarinfoProxied712=== RUN TestReadProxyRangeRequest713=== PAUSE TestReadProxyRangeRequest714=== RUN TestReadRedirectUsesPublicS3URL715=== PAUSE TestReadRedirectUsesPublicS3URL716=== RUN TestPush_OverlappingRootsStoreOneRowPerKey717=== PAUSE TestPush_OverlappingRootsStoreOneRowPerKey718=== RUN TestPush_CompleteCommitsEveryRoot719=== PAUSE TestPush_CompleteCommitsEveryRoot720=== RUN TestPush_RepeatedRootCommitsOnce721=== PAUSE TestPush_RepeatedRootCommitsOnce722=== RUN TestPush_CompleteWaitsForCleanupOfThePush723=== PAUSE TestPush_CompleteWaitsForCleanupOfThePush724=== RUN TestPush_RootsAreLockedInByteOrder725=== PAUSE TestPush_RootsAreLockedInByteOrder726=== RUN TestPush_SkippedKeySurvivesGCBeforeCommit727=== PAUSE TestPush_SkippedKeySurvivesGCBeforeCommit728=== RUN TestPush_RejectsBadRequests729=== PAUSE TestPush_RejectsBadRequests730=== RUN TestPush_SignsNarinfosOfItsPendingObjects731=== PAUSE TestPush_SignsNarinfosOfItsPendingObjects732=== RUN TestRedundantMultipartUpload733=== PAUSE TestRedundantMultipartUpload734=== RUN TestCompleteMultipartUpload_ErrorButObjectExists735=== PAUSE TestCompleteMultipartUpload_ErrorButObjectExists736=== RUN TestCompletedNarNotReofferedAcrossClosures737=== PAUSE TestCompletedNarNotReofferedAcrossClosures738=== RUN TestPresignedUploadRegisteredBeforeCommit739=== PAUSE TestPresignedUploadRegisteredBeforeCommit740=== RUN TestService_Rustfstest741=== PAUSE TestService_Rustfstest742=== RUN TestParseSize743=== PAUSE TestParseSize744=== RUN TestSkippedUploadsHandler745=== PAUSE TestSkippedUploadsHandler746=== RUN TestSystemdListenerNotActivated747--- PASS: TestSystemdListenerNotActivated (0.00s)748=== RUN TestWatchdogBeatsWhenHealthy749--- PASS: TestWatchdogBeatsWhenHealthy (0.03s)750=== RUN TestWatchdogSkipsWhenUnhealthy7512026/10/11 05:57:21 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7522026/10/11 05:57:21 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7532026/10/11 05:57:22 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7542026/10/11 05:57:22 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7552026/10/11 05:57:22 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7562026/10/11 05:57:22 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7572026/10/11 05:57:22 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7582026/10/11 05:57:22 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7592026/10/11 05:57:22 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7602026/10/11 05:57:22 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"761--- PASS: TestWatchdogSkipsWhenUnhealthy (0.20s)762=== RUN TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle763=== PAUSE TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle764=== RUN TestProxyWriteTimeout765=== PAUSE TestProxyWriteTimeout766=== RUN TestPendingClosureWriteTimeout767=== PAUSE TestPendingClosureWriteTimeout768=== RUN TestIsValidUploadKey769=== PAUSE TestIsValidUploadKey770=== RUN TestUploadHandlersRejectInvalidKeys771=== PAUSE TestUploadHandlersRejectInvalidKeys772=== RUN TestUploadHandlersRejectOversizedBody773=== PAUSE TestUploadHandlersRejectOversizedBody774=== RUN TestService_cleanupPendingClosuresHandler775=== PAUSE TestService_cleanupPendingClosuresHandler776=== RUN TestService_createPendingClosureHandler777=== PAUSE TestService_createPendingClosureHandler778=== RUN TestService_verifyS3Integrity779=== PAUSE TestService_verifyS3Integrity780=== RUN TestCompleteMultipartUnregistered781=== PAUSE TestCompleteMultipartUnregistered782=== RUN TestCreatePendingClosure_SmallNARUsesSimplePUT783=== PAUSE TestCreatePendingClosure_SmallNARUsesSimplePUT784=== CONT TestPush_RootsAreLockedInByteOrder785=== CONT TestReadProxyRootRedirectsToIndexHTML786=== CONT TestGCEndsOnShutdown787=== RUN TestGCEndsOnShutdown/before_the_run788=== PAUSE TestGCEndsOnShutdown/before_the_run789=== CONT TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle790=== CONT TestPush_CompleteWaitsForCleanupOfThePush791=== CONT TestPush_RepeatedRootCommitsOnce792=== CONT TestPush_CompleteCommitsEveryRoot793=== CONT TestPush_OverlappingRootsStoreOneRowPerKey794=== CONT TestReadRedirectUsesPublicS3URL795=== CONT TestReadProxyRangeRequest796=== CONT TestReadRedirectKeepsNarinfoProxied797=== CONT TestReadRedirectNar798=== CONT TestReadProxyDisabled799=== CONT TestCreatePendingClosure_SmallNARUsesSimplePUT800=== CONT TestCompleteMultipartUnregistered801=== CONT TestService_verifyS3Integrity802=== CONT TestService_createPendingClosureHandler803=== CONT TestService_cleanupPendingClosuresHandler804=== CONT TestUploadHandlersRejectOversizedBody805=== CONT TestUploadHandlersRejectInvalidKeys806=== CONT TestIsValidUploadKey807=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info808=== CONT TestPendingClosureWriteTimeout809=== CONT TestProxyWriteTimeout810=== CONT TestService_AuthMiddleware811=== RUN TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete812=== RUN TestIsValidUploadKey/narinfo813=== RUN TestPendingClosureWriteTimeout/empty814=== RUN TestProxyWriteTimeout/narinfo815=== PAUSE TestIsValidUploadKey/narinfo816=== PAUSE TestPendingClosureWriteTimeout/empty817=== RUN TestIsValidUploadKey/nar_zst818=== PAUSE TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete819=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info820=== PAUSE TestProxyWriteTimeout/narinfo821=== PAUSE TestIsValidUploadKey/nar_zst822=== RUN TestProxyWriteTimeout/1_GiB_nar823=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal824=== RUN TestPendingClosureWriteTimeout/400_objects825=== RUN TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark826=== PAUSE TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark827=== PAUSE TestProxyWriteTimeout/1_GiB_nar828=== RUN TestProxyWriteTimeout/10_GiB_nar829=== PAUSE TestPendingClosureWriteTimeout/400_objects830=== RUN TestIsValidUploadKey/nar_xz831=== RUN TestPendingClosureWriteTimeout/670k_objects832=== PAUSE TestProxyWriteTimeout/10_GiB_nar833=== CONT TestConnectWaitsForAPeerMigration834=== RUN TestProxyWriteTimeout/unknown_size835=== PAUSE TestIsValidUploadKey/nar_xz836=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal837=== RUN TestIsValidUploadKey/nar_plain838=== PAUSE TestPendingClosureWriteTimeout/670k_objects839=== PAUSE TestIsValidUploadKey/nar_plain840=== RUN TestIsValidUploadKey/listing841=== RUN TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline842=== PAUSE TestProxyWriteTimeout/unknown_size843=== RUN TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key844=== PAUSE TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key845=== RUN TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key846=== PAUSE TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key847=== CONT TestGCSweepDeliversEachKeyOnce848=== CONT TestTombstonedObjectOfferedWithoutWaiting849=== PAUSE TestIsValidUploadKey/listing850=== RUN TestIsValidUploadKey/build_log851=== PAUSE TestIsValidUploadKey/build_log852=== RUN TestIsValidUploadKey/build_log_home-manager_file853=== PAUSE TestIsValidUploadKey/build_log_home-manager_file854=== RUN TestIsValidUploadKey/build_log_plus_in_name855=== PAUSE TestIsValidUploadKey/build_log_plus_in_name856=== RUN TestIsValidUploadKey/build_log_question_mark857=== PAUSE TestIsValidUploadKey/build_log_question_mark858=== RUN TestIsValidUploadKey/build_log_equals859=== PAUSE TestIsValidUploadKey/build_log_equals860=== RUN TestIsValidUploadKey/realisation861=== PAUSE TestIsValidUploadKey/realisation862=== RUN TestIsValidUploadKey/realisation_plus_in_output863=== PAUSE TestIsValidUploadKey/realisation_plus_in_output864=== RUN TestIsValidUploadKey/nix-cache-info865=== PAUSE TestIsValidUploadKey/nix-cache-info866=== RUN TestIsValidUploadKey/index.html867=== PAUSE TestIsValidUploadKey/index.html868=== RUN TestIsValidUploadKey/narinfo_key,_nar_type869=== PAUSE TestIsValidUploadKey/narinfo_key,_nar_type870=== RUN TestIsValidUploadKey/nar_key,_narinfo_type871=== PAUSE TestIsValidUploadKey/nar_key,_narinfo_type872=== RUN TestIsValidUploadKey/listing_key,_narinfo_type873=== PAUSE TestIsValidUploadKey/listing_key,_narinfo_type874=== RUN TestIsValidUploadKey/traversal875=== PAUSE TestIsValidUploadKey/traversal876=== RUN TestIsValidUploadKey/traversal_nar877=== PAUSE TestIsValidUploadKey/traversal_nar878=== RUN TestIsValidUploadKey/absolute879=== PAUSE TestIsValidUploadKey/absolute880=== RUN TestIsValidUploadKey/empty_key881=== PAUSE TestIsValidUploadKey/empty_key882=== RUN TestIsValidUploadKey/unknown_type883=== PAUSE TestIsValidUploadKey/unknown_type884=== PAUSE TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline885=== CONT TestGCSweepSkipsPendingObjects886=== CONT TestDeduplicatedObjectsRecordedAsPending887=== RUN TestUploadHandlersRejectOversizedBody/create_pending_closure888=== PAUSE TestUploadHandlersRejectOversizedBody/create_pending_closure889=== RUN TestUploadHandlersRejectOversizedBody/complete_multipart890=== PAUSE TestUploadHandlersRejectOversizedBody/complete_multipart891=== RUN TestUploadHandlersRejectOversizedBody/request_more_parts892=== PAUSE TestUploadHandlersRejectOversizedBody/request_more_parts893=== CONT TestCommitRacingPendingCleanupKeepsObjects8942026/10/11 05:57:22 INFO Received uploads request method=POST path=/api/pending_closures895--- PASS: TestReadProxyRootRedirectsToIndexHTML (1.08s)896=== CONT TestPushDedupSurvivesConcurrentGC8972026/10/11 05:57:23 INFO Received complete multipart upload request method=POST path=/api/multipart/complete8982026/10/11 05:57:23 INFO Received push request method=POST path=/api/pushes8992026/10/11 05:57:23 INFO Received push request method=POST path=/api/pushes9002026-10-11 05:57:23.970 UTC [91954] ERROR: Push does not exist: id=19012026-10-11 05:57:23.970 UTC [91954] CONTEXT: PL/pgSQL function commit_push(bigint) line 11 at RAISE9022026-10-11 05:57:23.970 UTC [91954] STATEMENT: SELECT commit_push($1)903--- PASS: TestPush_CompleteWaitsForCleanupOfThePush (1.82s)904=== CONT TestGCMetrics9052026-10-11 05:57:24.124 UTC [91970] ERROR: could not obtain lock on row in relation "closures"9062026-10-11 05:57:24.124 UTC [91970] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT9072026-10-11 05:57:24.127 UTC [91970] ERROR: could not obtain lock on row in relation "closures"9082026-10-11 05:57:24.127 UTC [91970] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT9092026-10-11 05:57:24.136 UTC [91970] ERROR: could not obtain lock on row in relation "closures"9102026-10-11 05:57:24.136 UTC [91970] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT9112026-10-11 05:57:24.140 UTC [91970] ERROR: could not obtain lock on row in relation "closures"9122026-10-11 05:57:24.140 UTC [91970] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT9132026-10-11 05:57:24.143 UTC [91970] ERROR: could not obtain lock on row in relation "closures"9142026-10-11 05:57:24.143 UTC [91970] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT915--- PASS: TestPush_RootsAreLockedInByteOrder (2.01s)916=== CONT TestGCBugBareHashReferences9172026/10/11 05:57:24 INFO Received push request method=POST path=/api/pushes9182026/10/11 05:57:24 INFO Received complete push request method=POST path=/api/pushes/1/complete9192026/10/11 05:57:24 INFO Completed push id=1 objects=4 duration=21.294667ms920--- PASS: TestPush_RepeatedRootCommitsOnce (2.25s)921=== CONT TestGCAdvisoryLockBlocksConcurrentRun922--- PASS: TestReadRedirectUsesPublicS3URL (2.41s)923=== CONT TestLeadEndsOnShutdown924--- PASS: TestReadProxyRangeRequest (2.58s)925=== CONT TestPushWaitsForSweepHoldingRow9262026/10/11 05:57:24 INFO Received push request method=POST path=/api/pushes9272026/10/11 05:57:25 INFO Received complete push request method=POST path=/api/pushes/1/complete9282026/10/11 05:57:25 INFO Completed push id=1 objects=6 duration=26.357708ms929--- PASS: TestPush_CompleteCommitsEveryRoot (2.91s)930=== CONT TestLeadIncumbentAnnouncesAtOnce9312026/10/11 05:57:25 INFO Received uploads request method=POST path=/api/pending_closures932--- PASS: TestCreatePendingClosure_SmallNARUsesSimplePUT (3.06s)933=== CONT TestSweepRechecksPendingAfterLocking9342026/10/11 05:57:25 INFO Received push request method=POST path=/api/pushes935--- PASS: TestPush_OverlappingRootsStoreOneRowPerKey (3.28s)936=== CONT TestLeadElectsOneAndHandsOver9372026/10/11 05:57:25 INFO Aborted multipart uploads count=0 kept=09382026/10/11 05:57:25 WARN Force mode enabled - objects will be deleted immediately without grace period9392026/10/11 05:57:25 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=09402026/10/11 05:57:25 INFO Vacuumed table table=pending_closures9412026/10/11 05:57:25 INFO Vacuumed table table=pending_objects9422026/10/11 05:57:25 INFO Vacuumed table table=multipart_uploads9432026/10/11 05:57:25 INFO Vacuumed table table=closures9442026/10/11 05:57:25 INFO Received cleanup request method=DELETE path=/api/pending_closures9452026/10/11 05:57:25 INFO Vacuumed table table=objects9462026/10/11 05:57:25 INFO Aborted multipart uploads count=0 kept=0947--- PASS: TestGCSweepDeliversEachKeyOnce (3.66s)948=== CONT TestGetExistingObjectsLocksRows9492026/10/11 05:57:25 INFO Received uploads request method=POST path=/api/pending_closures9502026/10/11 05:57:25 INFO Received cleanup request method=DELETE path=/api/pending_closures9512026/10/11 05:57:25 INFO Aborted multipart uploads count=1 kept=09522026/10/11 05:57:25 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete9532026-10-11 05:57:25.949 UTC [91959] ERROR: Closure does not exist: id=19542026-10-11 05:57:25.949 UTC [91959] CONTEXT: PL/pgSQL function commit_pending_closure(bigint) line 13 at RAISE9552026-10-11 05:57:25.949 UTC [91959] STATEMENT: -- name: CommitPendingClosure :one956 SELECT commit_pending_closure($1::bigint)::bigint957 958--- PASS: TestService_cleanupPendingClosuresHandler (3.80s)959=== CONT TestClientIntegration960--- PASS: TestReadRedirectNar (3.94s)961=== CONT TestRegisterCompletedObjectNeedsPendingRow9622026/10/11 05:57:26 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9632026/10/11 05:57:26 ERROR Failed to get multipart upload error="no rows in result set" upload_id=does-not-exist object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst964--- PASS: TestCompleteMultipartUnregistered (4.13s)965=== CONT TestResolveDBConnectionString966=== RUN TestResolveDBConnectionString/flag_wins967=== PAUSE TestResolveDBConnectionString/flag_wins968=== RUN TestResolveDBConnectionString/file_when_flag_empty969=== PAUSE TestResolveDBConnectionString/file_when_flag_empty970=== RUN TestResolveDBConnectionString/missing_file_is_an_error971=== PAUSE TestResolveDBConnectionString/missing_file_is_an_error972=== RUN TestResolveDBConnectionString/PGHOST_allows_empty973=== PAUSE TestResolveDBConnectionString/PGHOST_allows_empty974=== RUN TestResolveDBConnectionString/nothing_configured975=== PAUSE TestResolveDBConnectionString/nothing_configured976=== CONT TestSweepSkipsRowsLockedByPush977--- PASS: TestReadProxyDisabled (4.30s)978=== CONT TestMultipartUploadAbortedWhenCancelledBeforeRecorded979--- PASS: TestReadRedirectKeepsNarinfoProxied (4.51s)980=== CONT TestFailedS3DeleteKeepsTombstone9812026/10/11 05:57:26 INFO Received uploads request method=POST path=/api/pending_closures9822026/10/11 05:57:26 INFO Received uploads request method=POST path=/api/pending_closures9832026/10/11 05:57:26 INFO Received uploads request method=POST path=/api/pending_closures9842026/10/11 05:57:27 INFO Received uploads request method=POST path=/api/pending_closures9852026/10/11 05:57:27 INFO Received uploads request method=POST path=/api/pending_closures986--- PASS: TestTombstonedObjectOfferedWithoutWaiting (5.20s)987=== CONT TestReadProxyConditionalGet9882026/10/11 05:57:27 INFO Received uploads request method=POST path=/api/pending_closures989--- PASS: TestDeduplicatedObjectsRecordedAsPending (5.45s)990=== CONT TestReadProxyOutlastsServerWriteTimeout9912026/10/11 05:57:27 INFO Received uploads request method=POST path=/api/pending_closures9922026/10/11 05:57:27 INFO Aborted multipart uploads count=0 kept=09932026/10/11 05:57:27 WARN Force mode enabled - objects will be deleted immediately without grace period9942026/10/11 05:57:27 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=09952026/10/11 05:57:28 INFO Vacuumed table table=pending_closures9962026/10/11 05:57:28 WARN Rate limiter enabled after throttle name=s3-test rate=59972026/10/11 05:57:28 WARN S3 rate limit hit operation="complete multipart upload" error="Please reduce your request rate."998=== NAME TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle999 throttle_test.go:213: Proxy stats: total=13, throttled=10, completeMultipart=101000 throttle_test.go:215: Rate limiter: enabled=true, rate=5.001001--- PASS: TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle (5.89s)1002=== CONT TestReadProxyHead10032026/10/11 05:57:28 INFO Vacuumed table table=pending_objects10042026/10/11 05:57:28 INFO Vacuumed table table=multipart_uploads10052026/10/11 05:57:28 INFO Vacuumed table table=closures10062026/10/11 05:57:28 INFO Vacuumed table table=objects1007--- PASS: TestGCSweepSkipsPendingObjects (5.91s)1008=== CONT TestReadProxyInvalidPath10092026/10/11 05:57:28 INFO Received complete multipart upload request method=POST path=/api/multipart/complete10102026/10/11 05:57:28 INFO Completed multipart upload object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst upload_id=Y2JhY2NlNmQtMWQ5My00ZmEwLTljNTktYTJmNWJhNGU5ZTAxLmUzZGZmYzQyLWJiODktNGMxZC04Yjc5LWU1MjY2MmQyMjhjNHgxNzkxNjk4MjQ2ODU2MTg5MDAw parts=1010112026/10/11 05:57:28 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete10122026/10/11 05:57:28 INFO Completed upload id=1 objects=2 duration=16.372084ms10132026/10/11 05:57:28 INFO Received get closure request method=GET path=/api/closures/0000000000000000000000000000000010142026/10/11 05:57:28 INFO Received uploads request method=POST path=/api/pending_closures10152026/10/11 05:57:28 INFO Starting cleanup of old closures method=DELETE path=/api/closures10162026/10/11 05:57:28 INFO Aborted multipart uploads count=0 kept=010172026/10/11 05:57:28 INFO Aborted multipart uploads count=0 kept=010182026/10/11 05:57:28 WARN Force mode enabled - objects will be deleted immediately without grace period10192026/10/11 05:57:28 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=010202026/10/11 05:57:28 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=010212026/10/11 05:57:28 INFO Vacuumed table table=pending_closures10222026/10/11 05:57:28 INFO Vacuumed table table=pending_closures10232026/10/11 05:57:28 INFO Vacuumed table table=pending_objects10242026/10/11 05:57:28 INFO Vacuumed table table=pending_objects10252026/10/11 05:57:28 INFO Vacuumed table table=multipart_uploads10262026/10/11 05:57:28 INFO Vacuumed table table=closures10272026/10/11 05:57:28 INFO Vacuumed table table=multipart_uploads10282026/10/11 05:57:28 INFO Vacuumed table table=objects10292026/10/11 05:57:28 WARN Authentication failed token_preview=wrongtoken token_length=10 reason="static API token mismatch"1030--- PASS: TestCommitRacingPendingCleanupKeepsObjects (6.24s)1031=== CONT TestReadProxy4041032--- PASS: TestService_AuthMiddleware (6.33s)1033=== CONT TestReadProxyNarStreaming10342026/10/11 05:57:28 INFO Vacuumed table table=closures10352026/10/11 05:57:28 INFO Vacuumed table table=objects10362026/10/11 05:57:28 INFO Received get closure request method=GET path=/api/closures/000000000000000000000000000000001037--- PASS: TestService_createPendingClosureHandler (6.39s)1038=== CONT TestReadProxyContentNegotiation10392026/10/11 05:57:28 INFO Received complete multipart upload request method=POST path=/api/multipart/complete10402026/10/11 05:57:28 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst upload_id=Y2JhY2NlNmQtMWQ5My00ZmEwLTljNTktYTJmNWJhNGU5ZTAxLmJhNDdlZGE0LTRiYmQtNDA3ZS1hZTAyLWEyOTUwOWZjNzM4OHgxNzkxNjk4MjQ3MTU5MDExMDAw parts=1010412026/10/11 05:57:28 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete10422026/10/11 05:57:28 INFO Completed upload id=1 objects=2 duration=19.875208ms10432026/10/11 05:57:28 INFO Received uploads request method=POST path=/api/pending_closures10442026/10/11 05:57:28 INFO Received uploads request method=POST path=/api/pending_closures10452026/10/11 05:57:28 INFO Object in database but missing from S3 key=dadb44fdadb44fdadb44fdadb44f0000.narinfo10462026/10/11 05:57:28 WARN Found objects in DB but missing from S3, will re-upload count=11047--- PASS: TestService_verifyS3Integrity (6.57s)1048=== CONT TestForceGCDuringPushOffersSweptObject1049=== RUN TestForceGCDuringPushOffersSweptObject/before_pending_rows1050=== PAUSE TestForceGCDuringPushOffersSweptObject/before_pending_rows1051=== RUN TestForceGCDuringPushOffersSweptObject/after_presence_check1052=== PAUSE TestForceGCDuringPushOffersSweptObject/after_presence_check1053=== CONT TestReadProxyNarinfoAlreadyDecompressed1054--- PASS: TestGCBugBareHashReferences (4.88s)1055=== CONT TestCreatePendingClosureVerifyS3FailureReleasesConnection10562026/10/11 05:57:29 INFO Received uploads request method=POST path=/api/pending_closures10572026/10/11 05:57:29 INFO Aborted multipart uploads count=0 kept=010582026/10/11 05:57:29 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=010592026/10/11 05:57:29 INFO Vacuumed table table=pending_closures10602026/10/11 05:57:29 INFO Vacuumed table table=pending_objects10612026/10/11 05:57:29 INFO Vacuumed table table=multipart_uploads10622026/10/11 05:57:29 INFO Aborted multipart uploads count=0 kept=010632026/10/11 05:57:29 INFO Vacuumed table table=closures10642026/10/11 05:57:29 WARN Force mode enabled - objects will be deleted immediately without grace period10652026/10/11 05:57:29 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=010662026/10/11 05:57:29 INFO Vacuumed table table=pending_closures10672026/10/11 05:57:29 INFO Vacuumed table table=pending_objects10682026/10/11 05:57:29 INFO Vacuumed table table=multipart_uploads10692026/10/11 05:57:29 INFO Vacuumed table table=closures10702026/10/11 05:57:29 INFO Vacuumed table table=objects10712026/10/11 05:57:29 INFO Vacuumed table table=objects1072--- PASS: TestGCMetrics (5.53s)1073=== CONT TestReadProxyNarinfo10742026/10/11 05:57:29 INFO Aborted multipart uploads count=0 kept=010752026/10/11 05:57:29 WARN Force mode enabled - objects will be deleted immediately without grace period10762026/10/11 05:57:29 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=010772026/10/11 05:57:29 INFO Vacuumed table table=pending_closures10782026/10/11 05:57:29 INFO Vacuumed table table=pending_objects10792026/10/11 05:57:29 INFO Vacuumed table table=multipart_uploads10802026/10/11 05:57:29 INFO Vacuumed table table=closures10812026/10/11 05:57:29 INFO Vacuumed table table=objects1082--- PASS: TestPushDedupSurvivesConcurrentGC (6.35s)1083=== CONT TestIsValidCachePath1084=== RUN TestIsValidCachePath/narinfo1085=== PAUSE TestIsValidCachePath/narinfo1086=== RUN TestIsValidCachePath/narinfo_all_nix_base32_chars1087=== PAUSE TestIsValidCachePath/narinfo_all_nix_base32_chars1088=== RUN TestIsValidCachePath/nar_zst1089=== PAUSE TestIsValidCachePath/nar_zst1090=== RUN TestIsValidCachePath/nar_xz1091=== PAUSE TestIsValidCachePath/nar_xz1092=== RUN TestIsValidCachePath/nar_bz21093=== PAUSE TestIsValidCachePath/nar_bz21094=== RUN TestIsValidCachePath/nar_uncompressed1095=== PAUSE TestIsValidCachePath/nar_uncompressed1096=== RUN TestIsValidCachePath/ls1097=== PAUSE TestIsValidCachePath/ls1098=== RUN TestIsValidCachePath/log1099=== PAUSE TestIsValidCachePath/log1100=== RUN TestIsValidCachePath/realisation1101=== PAUSE TestIsValidCachePath/realisation1102=== RUN TestIsValidCachePath/nix-cache-info1103=== PAUSE TestIsValidCachePath/nix-cache-info1104=== RUN TestIsValidCachePath/index.html1105=== PAUSE TestIsValidCachePath/index.html1106=== RUN TestIsValidCachePath/traversal_parent1107=== PAUSE TestIsValidCachePath/traversal_parent1108=== RUN TestIsValidCachePath/traversal_in_middle1109=== PAUSE TestIsValidCachePath/traversal_in_middle1110=== RUN TestIsValidCachePath/invalid_char_e1111=== PAUSE TestIsValidCachePath/invalid_char_e1112=== RUN TestIsValidCachePath/invalid_char_u1113=== PAUSE TestIsValidCachePath/invalid_char_u1114=== RUN TestIsValidCachePath/random_path1115=== PAUSE TestIsValidCachePath/random_path1116=== RUN TestIsValidCachePath/empty1117=== PAUSE TestIsValidCachePath/empty1118=== RUN TestIsValidCachePath/leading_slash1119=== PAUSE TestIsValidCachePath/leading_slash1120=== RUN TestIsValidCachePath/wrong_extension1121=== PAUSE TestIsValidCachePath/wrong_extension1122=== RUN TestIsValidCachePath/short_hash1123=== PAUSE TestIsValidCachePath/short_hash1124=== CONT TestParseSingleRange1125=== RUN TestParseSingleRange/none1126=== PAUSE TestParseSingleRange/none1127=== RUN TestParseSingleRange/unknown_unit1128=== PAUSE TestParseSingleRange/unknown_unit1129=== RUN TestParseSingleRange/multi-range_ignored1130=== PAUSE TestParseSingleRange/multi-range_ignored1131=== RUN TestParseSingleRange/malformed_no_dash1132=== PAUSE TestParseSingleRange/malformed_no_dash1133=== RUN TestParseSingleRange/malformed_both_empty1134=== PAUSE TestParseSingleRange/malformed_both_empty1135=== RUN TestParseSingleRange/malformed_end_before_start1136=== PAUSE TestParseSingleRange/malformed_end_before_start1137=== RUN TestParseSingleRange/closed1138=== PAUSE TestParseSingleRange/closed1139=== RUN TestParseSingleRange/open-ended1140=== PAUSE TestParseSingleRange/open-ended1141=== RUN TestParseSingleRange/end_clamped_to_size1142=== PAUSE TestParseSingleRange/end_clamped_to_size1143=== RUN TestParseSingleRange/suffix1144=== PAUSE TestParseSingleRange/suffix1145=== RUN TestParseSingleRange/suffix_exceeds_size1146=== PAUSE TestParseSingleRange/suffix_exceeds_size1147=== RUN TestParseSingleRange/single_byte1148=== PAUSE TestParseSingleRange/single_byte1149=== RUN TestParseSingleRange/start_past_EOF1150=== PAUSE TestParseSingleRange/start_past_EOF1151=== RUN TestParseSingleRange/start_far_past_EOF1152=== PAUSE TestParseSingleRange/start_far_past_EOF1153=== CONT TestPresentNotReportedWhileGCDeletesClosure1154=== RUN TestPresentNotReportedWhileGCDeletesClosure/stale1155=== PAUSE TestPresentNotReportedWhileGCDeletesClosure/stale1156=== RUN TestPresentNotReportedWhileGCDeletesClosure/fresh1157=== PAUSE TestPresentNotReportedWhileGCDeletesClosure/fresh1158=== CONT TestPresentRefreshesOnlyStaleClosures1159--- PASS: TestConnectWaitsForAPeerMigration (7.56s)1160=== CONT TestPresentReportsOnlyClosureRoots11612026/10/11 05:57:29 ERROR failed to check GC advisory lock error="query pg_locks: failed to connect to `user=_tribuchetbld3 database=niks3`: /nonexistent/.s.PGSQL.5432 (/nonexistent): dial error: dial unix /nonexistent/.s.PGSQL.5432: connect: no such file or directory"1162--- PASS: TestGCAdvisoryLockBlocksConcurrentRun (5.33s)1163=== CONT TestCreatePin_ReservedPins11642026/10/11 05:57:29 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:59755/oidc11652026/10/11 05:57:29 INFO lead: acquired remote=192.0.2.1:123411662026/10/11 05:57:30 INFO Received uploads request method=POST path=/api/pending_closures11672026/10/11 05:57:30 INFO lead: acquired remote=192.0.2.1:123411682026/10/11 05:57:30 INFO lead: released remote=192.0.2.1:12341169--- PASS: TestLeadIncumbentAnnouncesAtOnce (5.68s)1170=== CONT TestOrphanedObjectsGCStressTest1171--- PASS: TestPushWaitsForSweepHoldingRow (6.16s)1172=== CONT TestOrphanedObjectsGC11732026/10/11 05:57:31 INFO lead: released remote=192.0.2.1:12341174--- PASS: TestLeadEndsOnShutdown (6.46s)1175=== CONT TestObjectStatsLargeCommit11762026/10/11 05:57:31 INFO Aborted multipart uploads count=0 kept=011772026/10/11 05:57:31 WARN Force mode enabled - objects will be deleted immediately without grace period11782026/10/11 05:57:31 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=011792026/10/11 05:57:31 INFO Vacuumed table table=pending_closures11802026/10/11 05:57:31 INFO Vacuumed table table=pending_objects11812026/10/11 05:57:31 INFO Vacuumed table table=multipart_uploads11822026/10/11 05:57:31 INFO lead: acquired remote=192.0.2.1:123411832026/10/11 05:57:31 INFO Vacuumed table table=closures11842026/10/11 05:57:31 INFO Vacuumed table table=objects1185--- PASS: TestSweepRechecksPendingAfterLocking (6.27s)1186=== CONT TestObjectStatsTrigger1187--- PASS: TestGetExistingObjectsLocksRows (6.01s)1188=== CONT TestPendingCleanupUsesOneCutoff1189=== NAME TestClientIntegration1190 client_integration_test.go:286: Created store path: /private/var/tb/3/scratch/7155a60ad86daa12/build/TestClientIntegration4024870164/002/store/52bd9lq2qz53aajmhsyh7539p8fyiims-test-file.txt1191--- PASS: TestRegisterCompletedObjectNeedsPendingRow (6.33s)1192=== CONT TestService_ReadAuthMiddleware11932026/10/11 05:57:32 INFO Received push request method=POST path=/api/pushes11942026/10/11 05:57:32 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)11952026/10/11 05:57:32 INFO Uploading 52bd9lq2qz53aajmhsyh7539p8fyiims-test-file.txt (152B)11962026/10/11 05:57:32 WARN Failed to register uploaded object key=52bd9lq2qz53aajmhsyh7539p8fyiims.ls error="server returned 404: 404 page not found\n"11972026/10/11 05:57:32 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign11982026/10/11 05:57:32 WARN Failed to register uploaded object key=nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst error="server returned 404: 404 page not found\n"11992026/10/11 05:57:32 INFO Signed narinfos id=1 count=112002026/10/11 05:57:32 INFO Uploading 1 narinfos12012026/10/11 05:57:32 INFO Received complete push request method=POST path=/api/pushes/1/complete12022026/10/11 05:57:32 WARN Failed to register uploaded object key=52bd9lq2qz53aajmhsyh7539p8fyiims.narinfo error="server returned 404: 404 page not found\n"12032026/10/11 05:57:32 INFO Completed push id=1 objects=3 duration=25.125583ms12042026/10/11 05:57:32 INFO Upload complete. (169ms)12052026/10/11 05:57:32 INFO lead: released remote=192.0.2.1:123412062026/10/11 05:57:32 INFO All 1 paths already cached1207=== NAME TestClientIntegration1208 client_integration_test.go:312: Retrieved narinfo from S3:1209 StorePath: /private/var/tb/3/scratch/7155a60ad86daa12/build/TestClientIntegration4024870164/002/store/52bd9lq2qz53aajmhsyh7539p8fyiims-test-file.txt1210 URL: nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst1211 Compression: zstd1212 NarHash: sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11213 NarSize: 1521214 References: 1215 CA: fixed:r:sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk112162026/10/11 05:57:32 INFO lead: acquired remote=192.0.2.1:12341217 client_integration_test.go:313: Retrieved .ls file from S3 (compressed size: 77 bytes)1218 client_integration_test.go:313: Decompressed .ls content (64 bytes):1219 {"version":1,"root":{"type":"regular","size":39,"narOffset":96}}1220 client_integration_test.go:316: Testing garbage collection...12212026/10/11 05:57:32 INFO Starting cleanup of old closures method=DELETE path=/api/closures12222026/10/11 05:57:32 INFO Garbage collection started12232026/10/11 05:57:32 INFO Aborted multipart uploads count=0 kept=012242026/10/11 05:57:32 WARN Force mode enabled - objects will be deleted immediately without grace period12252026/10/11 05:57:32 INFO Aborted multipart uploads count=0 kept=012262026/10/11 05:57:32 WARN Force mode enabled - objects will be deleted immediately without grace period12272026/10/11 05:57:32 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=012282026/10/11 05:57:32 INFO Vacuumed table table=pending_closures12292026/10/11 05:57:32 INFO Vacuumed table table=pending_objects12302026/10/11 05:57:32 INFO Vacuumed table table=multipart_uploads12312026/10/11 05:57:32 INFO Vacuumed table table=closures12322026/10/11 05:57:32 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=1 objects-marked-for-deletion=3 objects-deleted-after-grace-period=3 objects-failed-to-delete=012332026/10/11 05:57:32 INFO Vacuumed table table=objects12342026/10/11 05:57:32 INFO Vacuumed table table=pending_closures12352026/10/11 05:57:32 INFO Aborted multipart uploads count=0 kept=012362026/10/11 05:57:32 WARN Force mode enabled - objects will be deleted immediately without grace period12372026/10/11 05:57:32 INFO Vacuumed table table=pending_objects12382026/10/11 05:57:32 INFO Vacuumed table table=multipart_uploads12392026/10/11 05:57:32 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=012402026/10/11 05:57:32 INFO Vacuumed table table=pending_closures12412026/10/11 05:57:32 INFO Vacuumed table table=pending_objects12422026/10/11 05:57:32 INFO Vacuumed table table=multipart_uploads12432026/10/11 05:57:32 INFO Vacuumed table table=closures12442026/10/11 05:57:32 INFO Vacuumed table table=closures12452026/10/11 05:57:32 INFO Vacuumed table table=objects1246--- PASS: TestSweepSkipsRowsLockedByPush (6.63s)1247=== CONT TestService_readinessHandler12482026/10/11 05:57:32 INFO Vacuumed table table=objects12492026/10/11 05:57:32 INFO Received uploads request method=POST path=/api/pending_closures1250--- PASS: TestMultipartUploadAbortedWhenCancelledBeforeRecorded (6.61s)1251=== CONT TestService_ReadScope_PublicByDefault12522026/10/11 05:57:33 INFO Received uploads request method=POST path=/api/pending_closures12532026/10/11 05:57:33 INFO Aborted multipart uploads count=0 kept=012542026/10/11 05:57:33 WARN Force mode enabled - objects will be deleted immediately without grace period12552026/10/11 05:57:33 ERROR failed to remove object object=nar/dddddddddddddddddddddddddddddddddddddddddddddddddddd.nar.zst error="Access Denied."12562026/10/11 05:57:33 ERROR failed to remove object object=dddddddddddddddddddddddddddddddd.narinfo error="Access Denied."1257--- PASS: TestReadProxyConditionalGet (6.06s)1258=== CONT TestMultipartCleanup1259--- PASS: TestFailedS3DeleteKeepsTombstone (6.84s)1260=== CONT TestClientErrorHandling1261=== RUN TestClientErrorHandling/InvalidStorePath1262=== PAUSE TestClientErrorHandling/InvalidStorePath1263=== RUN TestClientErrorHandling/InvalidAuthToken1264=== PAUSE TestClientErrorHandling/InvalidAuthToken1265=== RUN TestClientErrorHandling/ServerNotAvailable1266=== PAUSE TestClientErrorHandling/ServerNotAvailable1267=== CONT TestClientCADerivations12682026/10/11 05:57:33 INFO lead: released remote=192.0.2.1:12341269--- PASS: TestLeadElectsOneAndHandsOver (8.30s)1270=== CONT TestService_RequireScope_OIDC12712026/10/11 05:57:33 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:59786/oidc1272--- PASS: TestReadProxyHead (5.81s)1273=== CONT TestCacheStatsHandler1274--- PASS: TestReadProxyInvalidPath (5.94s)1275=== CONT TestService_AuthMiddleware_OIDC12762026/10/11 05:57:34 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:59794/oidc1277--- PASS: TestReadProxyContentNegotiation (5.77s)1278=== CONT TestCacheConfigHandler1279=== RUN TestCacheConfigHandler/full_config,_no_issuer1280=== PAUSE TestCacheConfigHandler/full_config,_no_issuer1281=== RUN TestCacheConfigHandler/no_cache_url_configured1282=== PAUSE TestCacheConfigHandler/no_cache_url_configured1283=== RUN TestCacheConfigHandler/no_signing_keys1284=== PAUSE TestCacheConfigHandler/no_signing_keys1285=== RUN TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1286=== PAUSE TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1287=== CONT TestServerTLSConfig1288=== RUN TestServerTLSConfig/no_client_CA1289=== PAUSE TestServerTLSConfig/no_client_CA1290=== RUN TestServerTLSConfig/missing_CA_file1291=== PAUSE TestServerTLSConfig/missing_CA_file1292=== RUN TestServerTLSConfig/not_a_PEM_file1293=== PAUSE TestServerTLSConfig/not_a_PEM_file1294=== CONT TestService_AuthMiddleware_MTLSBoundSubjects1295--- PASS: TestReadProxy404 (6.09s)1296=== CONT TestService_AuthMiddleware_MTLSProxyHeader12972026/10/11 05:57:34 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=01298=== NAME TestClientIntegration1299 client_integration_test.go:323: Objects in database after GC:1300 client_integration_test.go:323: Successfully deleted all objects with GC --force1301--- PASS: TestReadProxyNarStreaming (6.28s)1302=== CONT TestService_NativeMTLS1303--- PASS: TestClientIntegration (8.86s)1304=== CONT TestPinProtectsFromGC1305--- PASS: TestReadProxyNarinfoAlreadyDecompressed (6.23s)1306=== CONT TestMetricsCommit13072026/10/11 05:57:35 INFO Received uploads request method=POST path=/api/pending_closures1308--- PASS: TestCreatePendingClosureVerifyS3FailureReleasesConnection (6.35s)1309=== CONT TestGCTaskStore_CompletedAllowsNewTask1310--- PASS: TestGCTaskStore_CompletedAllowsNewTask (0.00s)1311=== CONT TestDeleteClosuresRacingPins13122026/10/11 05:57:35 ERROR Failed to decode narinfo key=3hcdxyjf9yiq7qf3i4548drb6sjmwa1v.narinfo limit=16777216 error=<nil>1313--- PASS: TestReadProxyNarinfo (5.92s)1314=== CONT TestMetricsInventory1315--- PASS: TestPresentReportsOnlyClosureRoots (5.94s)1316=== CONT TestClientFallsBackToClosures1317--- PASS: TestPresentRefreshesOnlyStaleClosures (6.23s)1318=== CONT TestClientPushesUseOnePush13192026/10/11 05:57:36 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux13202026/10/11 05:57:36 WARN Refused reserved pin name=worker-x86_64-linux13212026/10/11 05:57:36 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux13222026/10/11 05:57:36 INFO Received create pin request method=POST path=/api/pins/my-app13232026/10/11 05:57:36 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux1324--- PASS: TestCreatePin_ReservedPins (6.30s)1325=== CONT TestCacheConfigHandlerMaxNarSize1326--- PASS: TestCacheConfigHandlerMaxNarSize (0.00s)1327=== CONT TestCreatePendingClosureRejectsOversizedNAR13282026/10/11 05:57:36 INFO Received uploads request method=POST path=/api/pending_closures1329--- PASS: TestCreatePendingClosureRejectsOversizedNAR (0.00s)1330=== CONT TestService_healthCheckHandler1331--- PASS: TestObjectStatsTrigger (5.67s)1332=== CONT TestGCTaskStore_ConflictDifferentParams1333--- PASS: TestGCTaskStore_ConflictDifferentParams (0.00s)1334=== CONT TestNARDeduplicationMetadataUploadBug1335=== NAME TestOrphanedObjectsGC1336 orphaned_objects_gc_test.go:287: GC Test Summary:1337 orphaned_objects_gc_test.go:288: - Kept: 2 objects from closure A1338 orphaned_objects_gc_test.go:289: - Deleted: 2 objects from closure B1339 orphaned_objects_gc_test.go:290: - Deleted: 6 orphaned chain objects (X1->X2->X3)1340 orphaned_objects_gc_test.go:291: - Deleted: 2 orphaned single objects (Y)1341 orphaned_objects_gc_test.go:292: - Total deleted: 10 objects1342--- PASS: TestOrphanedObjectsGC (6.33s)1343=== CONT TestGracefulShutdownDrainsInflight13442026/10/11 05:57:37 INFO Starting HTTP server address=127.0.0.1:5982313452026/10/11 05:57:37 INFO Shutdown signal received, draining in-flight requests timeout=10s1346--- PASS: TestGracefulShutdownDrainsInflight (0.07s)1347=== CONT TestGCTaskStore_GetReturnsLatest1348--- PASS: TestGCTaskStore_GetReturnsLatest (0.00s)1349=== CONT TestGenerateLandingPage1350--- PASS: TestGenerateLandingPage (0.00s)1351=== CONT TestGCTaskStore_Fail1352--- PASS: TestGCTaskStore_Fail (0.00s)1353=== CONT TestGCTaskStore_GetEmpty1354--- PASS: TestGCTaskStore_GetEmpty (0.00s)1355=== CONT TestGCTaskStore_PhaseUpdates1356--- PASS: TestGCTaskStore_PhaseUpdates (0.00s)1357=== CONT TestGCTaskStore_DeduplicateSameParams1358--- PASS: TestGCTaskStore_DeduplicateSameParams (0.00s)1359=== CONT TestClientWithDependencies13602026/10/11 05:57:37 INFO Received uploads request method=POST path=/api/pending_closures13612026/10/11 05:57:37 INFO Received uploads request method=POST path=/api/pending_closures13622026/10/11 05:57:37 INFO Received cleanup request method=DELETE path=/api/pending_closures1363--- PASS: TestService_ReadAuthMiddleware (5.22s)1364=== CONT TestGCTaskStore_StartNew1365--- PASS: TestGCTaskStore_StartNew (0.00s)1366=== CONT TestClientSharedPathCommittedMidPush1367--- PASS: TestReadProxyOutlastsServerWriteTimeout (10.22s)1368=== CONT TestClientMultipleUploads13692026/10/11 05:57:37 WARN readiness check failed error="closed pool"1370--- PASS: TestService_readinessHandler (4.99s)1371=== CONT TestCompletedNarNotReofferedAcrossClosures1372--- PASS: TestService_ReadScope_PublicByDefault (5.11s)1373=== CONT TestPush_SignsNarinfosOfItsPendingObjects13742026/10/11 05:57:38 INFO Received uploads request method=POST path=/api/pending_closures13752026/10/11 05:57:38 INFO Received cleanup request method=DELETE path=/api/pending_closures13762026/10/11 05:57:38 WARN Failed to abort upload, keeping its closure key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst error="Get \"http://127.0.0.1:1/bucket63/?location=\": dial tcp 127.0.0.1:1: connect: connection refused" code=""13772026/10/11 05:57:38 INFO Aborted multipart uploads count=0 kept=113782026/10/11 05:57:38 INFO Received cleanup request method=DELETE path=/api/pending_closures13792026/10/11 05:57:38 INFO Aborted multipart uploads count=1 kept=01380--- PASS: TestMultipartCleanup (5.23s)1381=== CONT TestPush_RejectsBadRequests1382=== RUN TestService_RequireScope_OIDC/builder_may_write1383=== PAUSE TestService_RequireScope_OIDC/builder_may_write1384=== RUN TestService_RequireScope_OIDC/builder_may_not_admin1385=== PAUSE TestService_RequireScope_OIDC/builder_may_not_admin1386=== RUN TestService_RequireScope_OIDC/ops_may_admin1387=== PAUSE TestService_RequireScope_OIDC/ops_may_admin1388=== RUN TestService_RequireScope_OIDC/ops_may_not_write1389=== PAUSE TestService_RequireScope_OIDC/ops_may_not_write1390=== RUN TestService_RequireScope_OIDC/reader_may_not_write1391=== PAUSE TestService_RequireScope_OIDC/reader_may_not_write1392=== RUN TestService_RequireScope_OIDC/static_token_may_admin1393=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin1394=== RUN TestService_RequireScope_OIDC/static_token_may_write1395=== PAUSE TestService_RequireScope_OIDC/static_token_may_write1396=== RUN TestService_RequireScope_OIDC/reader_may_read1397=== PAUSE TestService_RequireScope_OIDC/reader_may_read1398=== RUN TestService_RequireScope_OIDC/writer_implies_read1399=== PAUSE TestService_RequireScope_OIDC/writer_implies_read1400=== RUN TestService_RequireScope_OIDC/anonymous_may_not_read1401=== PAUSE TestService_RequireScope_OIDC/anonymous_may_not_read1402=== RUN TestService_RequireScope_OIDC/reader_may_read_with_netrc1403=== PAUSE TestService_RequireScope_OIDC/reader_may_read_with_netrc1404=== RUN TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1405=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1406=== RUN TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read1407=== PAUSE TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read1408=== RUN TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1409=== PAUSE TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1410=== CONT TestSkippedUploadsHandler14112026/10/11 05:57:39 INFO Client skipped oversized paths paths=3 nar_bytes=50000000001412--- PASS: TestSkippedUploadsHandler (0.00s)1413=== CONT TestCompleteMultipartUpload_ErrorButObjectExists1414=== NAME TestClientCADerivations1415 client_ca_test.go:136: Built CA derivation: /private/var/tb/3/scratch/7155a60ad86daa12/build/TestClientCADerivations1712265454/001/store/b6mqbqyj04d6gss3nw1p298rlh6zr7wl-ca-test1416 client_ca_test.go:139: Found 1 dependencies (including self)1417--- PASS: TestCacheStatsHandler (5.48s)1418=== CONT TestService_Rustfstest14192026/10/11 05:57:39 INFO Received push request method=POST path=/api/pushes14202026/10/11 05:57:39 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)14212026/10/11 05:57:39 INFO Uploading b6mqbqyj04d6gss3nw1p298rlh6zr7wl-ca-test (144B)14222026/10/11 05:57:39 WARN Failed to register uploaded object key=b6mqbqyj04d6gss3nw1p298rlh6zr7wl.ls error="server returned 404: 404 page not found\n"14232026/10/11 05:57:39 WARN Failed to register uploaded object key=nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst error="server returned 404: 404 page not found\n"14242026/10/11 05:57:39 WARN Failed to register uploaded object key=log/fib8k313xjhkgrnaqm4qz15kz31s713s-ca-test.drv error="server returned 404: 404 page not found\n"14252026/10/11 05:57:39 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign14262026/10/11 05:57:39 INFO Signed narinfos id=1 count=114272026/10/11 05:57:39 INFO Uploading 1 narinfos14282026/10/11 05:57:39 INFO Received complete push request method=POST path=/api/pushes/1/complete14292026/10/11 05:57:39 WARN Failed to register uploaded object key=b6mqbqyj04d6gss3nw1p298rlh6zr7wl.narinfo error="server returned 404: 404 page not found\n"1430=== RUN TestService_AuthMiddleware_OIDC/valid_OIDC_token1431=== PAUSE TestService_AuthMiddleware_OIDC/valid_OIDC_token1432=== RUN TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1433=== PAUSE TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1434=== RUN TestService_AuthMiddleware_OIDC/malformed_token_rejected1435=== PAUSE TestService_AuthMiddleware_OIDC/malformed_token_rejected1436=== RUN TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1437=== PAUSE TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1438=== CONT TestRedundantMultipartUpload14392026/10/11 05:57:39 INFO Completed push id=1 objects=4 duration=38.459458ms14402026/10/11 05:57:39 INFO Upload complete. (267ms)1441=== NAME TestClientCADerivations1442 client_ca_test.go:180: Narinfo contains CA field: StorePath: /private/var/tb/3/scratch/7155a60ad86daa12/build/TestClientCADerivations1712265454/001/store/b6mqbqyj04d6gss3nw1p298rlh6zr7wl-ca-test1443 URL: nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst1444 Compression: zstd1445 NarHash: sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1446 NarSize: 1441447 References: 1448 Deriver: /private/var/tb/3/scratch/7155a60ad86daa12/build/TestClientCADerivations1712265454/001/store/fib8k313xjhkgrnaqm4qz15kz31s713s-ca-test.drv1449 CA: fixed:r:sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1450 client_ca_test.go:185: Checking for realisation files in S3...1451 client_ca_test.go:207: No realisation files uploaded - this is expected for locally built CA derivations1452 client_ca_test.go:208: Locally built CA derivations don't have DrvOutput IDs until they're substituted from a cache1453 client_ca_test.go:258: nix copy output: error: binary cache 's3://bucket64?endpoint=http://localhost:59678®ion=eu-west-1' is for Nix stores with prefix '/nix/store', not '/private/var/tb/3/scratch/7155a60ad86daa12/build/TestClientCADerivations1712265454/001/store'1454 client_ca_test.go:259: nix copy failed (might be expected with isolated stores): exit status 11455--- PASS: TestClientCADerivations (6.28s)1456=== CONT TestPresignedUploadRegisteredBeforeCommit14572026/10/11 05:57:39 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted,O=Other"14582026/10/11 05:57:39 WARN mTLS auth: bound subjects configured but subject DN unavailable14592026/10/11 05:57:39 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted"1460--- PASS: TestService_AuthMiddleware_MTLSBoundSubjects (5.49s)1461=== CONT TestParseSize1462--- PASS: TestParseSize (0.00s)1463=== CONT TestPush_SkippedKeySurvivesGCBeforeCommit1464--- PASS: TestService_AuthMiddleware_MTLSProxyHeader (5.55s)1465=== CONT TestConcurrentCommitsSharingObjectsDoNotDeadlock14662026/10/11 05:57:40 WARN mTLS auth: subject not in bound subjects subject="CN=reader"14672026/10/11 05:57:40 WARN mTLS auth: subject not in bound subjects subject="CN=reader"1468--- PASS: TestService_NativeMTLS (5.67s)1469=== CONT TestGCEndsOnShutdown/before_the_run14702026/10/11 05:57:40 INFO Received push request method=POST path=/api/pushes14712026/10/11 05:57:41 INFO Received complete push request method=POST path=/api/pushes/1/complete1472=== NAME TestPinProtectsFromGC1473 client_integration_test.go:731: Pinned store path: /private/var/tb/3/scratch/7155a60ad86daa12/build/TestPinProtectsFromGC349778345/001/store/b30r0if0nc32k1bf84bhyxhyj30xfbax-pinned-file.txt1474 client_integration_test.go:732: Unpinned store path: /private/var/tb/3/scratch/7155a60ad86daa12/build/TestPinProtectsFromGC349778345/001/store/s8niz8258x5pm6ns0jh8plvh6i24ixbv-unpinned-file.txt14752026/10/11 05:57:41 INFO Completed push id=1 objects=4 duration=33.984292ms14762026/10/11 05:57:41 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete14772026/10/11 05:57:41 INFO Completed upload id=2 objects=2 duration=1.035667ms1478--- PASS: TestMetricsCommit (6.14s)1479=== CONT TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark14802026/10/11 05:57:41 INFO Received push request method=POST path=/api/pushes14812026/10/11 05:57:41 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)14822026/10/11 05:57:41 INFO Uploading b30r0if0nc32k1bf84bhyxhyj30xfbax-pinned-file.txt (128B)14832026/10/11 05:57:41 WARN Failed to register uploaded object key=nar/0qmhsg42pqsz7x6hh02j8gznnac3yi3qpjhrqbwvz88i194jbb5s.nar.zst error="server returned 404: 404 page not found\n"14842026/10/11 05:57:41 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign14852026/10/11 05:57:41 WARN Failed to register uploaded object key=b30r0if0nc32k1bf84bhyxhyj30xfbax.ls error="server returned 404: 404 page not found\n"14862026/10/11 05:57:41 INFO Signed narinfos id=1 count=114872026/10/11 05:57:41 INFO Uploading 1 narinfos14882026/10/11 05:57:41 INFO Received complete push request method=POST path=/api/pushes/1/complete14892026/10/11 05:57:41 WARN Failed to register uploaded object key=b30r0if0nc32k1bf84bhyxhyj30xfbax.narinfo error="server returned 404: 404 page not found\n"14902026/10/11 05:57:41 INFO Completed push id=1 objects=3 duration=23.443375ms14912026/10/11 05:57:41 INFO Upload complete. (174ms)14922026/10/11 05:57:41 INFO Received push request method=POST path=/api/pushes14932026/10/11 05:57:41 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)14942026/10/11 05:57:41 INFO Uploading s8niz8258x5pm6ns0jh8plvh6i24ixbv-unpinned-file.txt (128B)14952026/10/11 05:57:41 WARN Failed to register uploaded object key=nar/0gh0wdnr6gmk4r5sfzzh12isnl14rgmkrwy1ws41hpsrlndclg5h.nar.zst error="server returned 404: 404 page not found\n"14962026/10/11 05:57:41 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign14972026/10/11 05:57:41 WARN Failed to register uploaded object key=s8niz8258x5pm6ns0jh8plvh6i24ixbv.ls error="server returned 404: 404 page not found\n"14982026/10/11 05:57:41 INFO Signed narinfos id=2 count=114992026/10/11 05:57:41 INFO Uploading 1 narinfos15002026/10/11 05:57:41 INFO Received complete push request method=POST path=/api/pushes/2/complete15012026/10/11 05:57:41 WARN Failed to register uploaded object key=s8niz8258x5pm6ns0jh8plvh6i24ixbv.narinfo error="server returned 404: 404 page not found\n"15022026/10/11 05:57:41 INFO Completed push id=2 objects=3 duration=772.833µs15032026/10/11 05:57:41 INFO Upload complete. (116ms)15042026/10/11 05:57:41 INFO Starting cleanup of old closures method=DELETE path=/api/closures15052026/10/11 05:57:41 INFO Garbage collection started15062026/10/11 05:57:41 INFO Aborted multipart uploads count=0 kept=015072026/10/11 05:57:41 WARN Force mode enabled - objects will be deleted immediately without grace period15082026/10/11 05:57:41 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=1 objects-marked-for-deletion=3 objects-deleted-after-grace-period=3 objects-failed-to-delete=015092026/10/11 05:57:41 INFO Vacuumed table table=pending_closures1510--- PASS: TestMetricsInventory (6.15s)1511=== CONT TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete15122026/10/11 05:57:41 INFO Vacuumed table table=pending_objects15132026/10/11 05:57:41 INFO Vacuumed table table=multipart_uploads15142026/10/11 05:57:41 INFO Vacuumed table table=closures15152026/10/11 05:57:41 INFO Vacuumed table table=objects1516=== NAME TestOrphanedObjectsGCStressTest1517 orphaned_objects_gc_test.go:422: Created 10 active closures, 5 to-delete closures, 20 orphaned chains1518 orphaned_objects_gc_test.go:440: Marked 210 objects for deletion15192026/10/11 05:57:42 INFO Received uploads request method=POST path=/api/pending_closures15202026/10/11 05:57:42 INFO Received uploads request method=POST path=/api/pending_closures15212026/10/11 05:57:42 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)15222026/10/11 05:57:42 INFO Uploading xykcjnfcjj4rc2icarsn0prg64nc6i34-a (256B)15232026/10/11 05:57:42 INFO Uploading s87rs1j1azbm0spcxckqan70l6293nji-shared-dep (136B)1524--- PASS: TestService_healthCheckHandler (6.16s)1525=== CONT TestProxyWriteTimeout/narinfo1526=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info15272026/10/11 05:57:42 INFO Received uploads request method=POST path=/1528=== CONT TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key15292026/10/11 05:57:42 INFO Received request for more parts method=POST path=/1530=== CONT TestProxyWriteTimeout/10_GiB_nar1531=== CONT TestProxyWriteTimeout/unknown_size1532=== CONT TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key15332026/10/11 05:57:42 INFO Received complete multipart upload request method=POST path=/1534=== CONT TestProxyWriteTimeout/1_GiB_nar1535--- PASS: TestProxyWriteTimeout (0.05s)1536 --- PASS: TestProxyWriteTimeout/narinfo (0.00s)1537 --- PASS: TestProxyWriteTimeout/10_GiB_nar (0.00s)1538 --- PASS: TestProxyWriteTimeout/unknown_size (0.00s)1539 --- PASS: TestProxyWriteTimeout/1_GiB_nar (0.00s)1540=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal15412026/10/11 05:57:42 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"15422026/10/11 05:57:42 INFO Received uploads request method=POST path=/1543--- PASS: TestUploadHandlersRejectInvalidKeys (0.05s)1544 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info (0.00s)1545 --- PASS: TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key (0.00s)1546 --- PASS: TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key (0.00s)1547 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal (0.00s)1548=== CONT TestIsValidUploadKey/narinfo1549=== CONT TestPendingClosureWriteTimeout/empty1550=== CONT TestIsValidUploadKey/build_log_equals1551=== CONT TestIsValidUploadKey/unknown_type1552=== CONT TestIsValidUploadKey/empty_key1553=== CONT TestIsValidUploadKey/absolute1554=== CONT TestIsValidUploadKey/traversal_nar1555=== CONT TestIsValidUploadKey/traversal1556=== CONT TestIsValidUploadKey/listing_key,_narinfo_type1557=== CONT TestIsValidUploadKey/nar_key,_narinfo_type1558=== CONT TestIsValidUploadKey/narinfo_key,_nar_type1559=== CONT TestIsValidUploadKey/index.html1560=== CONT TestIsValidUploadKey/nix-cache-info1561=== CONT TestIsValidUploadKey/realisation_plus_in_output1562=== CONT TestIsValidUploadKey/realisation1563=== CONT TestIsValidUploadKey/nar_xz1564=== CONT TestIsValidUploadKey/build_log_question_mark15652026/10/11 05:57:42 WARN Failed to register uploaded object key=gbkh31ng8zlq3d6ysxsm6wjw3k29h130.ls error="server returned 404: 404 page not found\n"1566=== CONT TestIsValidUploadKey/build_log_plus_in_name1567=== CONT TestIsValidUploadKey/build_log_home-manager_file15682026/10/11 05:57:42 WARN Failed to register uploaded object key=s87rs1j1azbm0spcxckqan70l6293nji.ls error="server returned 404: 404 page not found\n"1569=== CONT TestIsValidUploadKey/build_log1570=== CONT TestIsValidUploadKey/listing1571=== CONT TestIsValidUploadKey/nar_plain1572=== CONT TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline15732026/10/11 05:57:42 WARN Failed to register uploaded object key=nar/1sbxw5f8j2qdypr56fk9cnc1hg2464ms7nns5f36nip7isx2mzb8.nar.zst error="server returned 404: 404 page not found\n"15742026/10/11 05:57:42 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign15752026/10/11 05:57:42 WARN Failed to register uploaded object key=xykcjnfcjj4rc2icarsn0prg64nc6i34.ls error="server returned 404: 404 page not found\n"15762026/10/11 05:57:42 INFO Signed narinfos id=2 count=215772026/10/11 05:57:42 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign15782026/10/11 05:57:42 INFO Signed narinfos id=1 count=215792026/10/11 05:57:42 INFO Uploading 4 narinfos15802026/10/11 05:57:42 WARN Failed to register uploaded object key=gbkh31ng8zlq3d6ysxsm6wjw3k29h130.narinfo error="server returned 404: 404 page not found\n"15812026/10/11 05:57:42 WARN Failed to register uploaded object key=s87rs1j1azbm0spcxckqan70l6293nji.narinfo error="server returned 404: 404 page not found\n"15822026/10/11 05:57:42 WARN Failed to register uploaded object key=xykcjnfcjj4rc2icarsn0prg64nc6i34.narinfo error="server returned 404: 404 page not found\n"15832026/10/11 05:57:42 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete15842026/10/11 05:57:42 WARN Failed to register uploaded object key=s87rs1j1azbm0spcxckqan70l6293nji.narinfo error="server returned 404: 404 page not found\n"15852026/10/11 05:57:42 INFO Completed upload id=1 objects=6 duration=19.378416ms15862026/10/11 05:57:42 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete15872026/10/11 05:57:42 INFO Completed upload id=2 objects=6 duration=469.292µs15882026/10/11 05:57:42 INFO Upload complete. (176ms)1589=== NAME TestClientFallsBackToClosures1590 client_pushes_test.go:112: Retrieved narinfo from S3:1591 StorePath: /private/var/tb/3/scratch/7155a60ad86daa12/build/TestClientFallsBackToClosures3579238396/001/store/s87rs1j1azbm0spcxckqan70l6293nji-shared-dep1592 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1593 Compression: zstd1594 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821595 NarSize: 1361596 References: 1597 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1598 client_pushes_test.go:112: Retrieved narinfo from S3:1599 StorePath: /private/var/tb/3/scratch/7155a60ad86daa12/build/TestClientFallsBackToClosures3579238396/001/store/xykcjnfcjj4rc2icarsn0prg64nc6i34-a1600 URL: nar/1sbxw5f8j2qdypr56fk9cnc1hg2464ms7nns5f36nip7isx2mzb8.nar.zst1601 Compression: zstd1602 NarHash: sha256:1sbxw5f8j2qdypr56fk9cnc1hg2464ms7nns5f36nip7isx2mzb81603 NarSize: 2561604 References: /private/var/tb/3/scratch/7155a60ad86daa12/build/TestClientFallsBackToClosures3579238396/001/store/s87rs1j1azbm0spcxckqan70l6293nji-shared-dep1605 CA: text:sha256:1fwsp7p26hxyxz42d3qhn0a7i4v4bjmqmhb9j7z1i3v55x4gd7k61606 client_pushes_test.go:112: Retrieved narinfo from S3:1607 StorePath: /private/var/tb/3/scratch/7155a60ad86daa12/build/TestClientFallsBackToClosures3579238396/001/store/gbkh31ng8zlq3d6ysxsm6wjw3k29h130-b1608 URL: nar/1sbxw5f8j2qdypr56fk9cnc1hg2464ms7nns5f36nip7isx2mzb8.nar.zst1609 Compression: zstd1610 NarHash: sha256:1sbxw5f8j2qdypr56fk9cnc1hg2464ms7nns5f36nip7isx2mzb81611 NarSize: 2561612 References: /private/var/tb/3/scratch/7155a60ad86daa12/build/TestClientFallsBackToClosures3579238396/001/store/s87rs1j1azbm0spcxckqan70l6293nji-shared-dep1613 CA: text:sha256:1fwsp7p26hxyxz42d3qhn0a7i4v4bjmqmhb9j7z1i3v55x4gd7k61614--- PASS: TestClientFallsBackToClosures (6.68s)1615=== CONT TestPendingClosureWriteTimeout/670k_objects1616=== CONT TestPendingClosureWriteTimeout/400_objects1617=== CONT TestIsValidUploadKey/nar_zst1618=== CONT TestUploadHandlersRejectOversizedBody/create_pending_closure1619--- PASS: TestIsValidUploadKey (0.05s)1620 --- PASS: TestIsValidUploadKey/narinfo (0.00s)1621 --- PASS: TestIsValidUploadKey/build_log_equals (0.00s)1622 --- PASS: TestIsValidUploadKey/unknown_type (0.00s)1623 --- PASS: TestIsValidUploadKey/empty_key (0.00s)1624 --- PASS: TestIsValidUploadKey/absolute (0.00s)1625 --- PASS: TestIsValidUploadKey/traversal_nar (0.00s)1626 --- PASS: TestIsValidUploadKey/traversal (0.00s)1627 --- PASS: TestIsValidUploadKey/listing_key,_narinfo_type (0.00s)1628 --- PASS: TestIsValidUploadKey/nar_key,_narinfo_type (0.00s)1629 --- PASS: TestIsValidUploadKey/narinfo_key,_nar_type (0.00s)1630 --- PASS: TestIsValidUploadKey/index.html (0.00s)1631 --- PASS: TestIsValidUploadKey/nix-cache-info (0.00s)1632 --- PASS: TestIsValidUploadKey/realisation_plus_in_output (0.00s)1633 --- PASS: TestIsValidUploadKey/realisation (0.00s)1634 --- PASS: TestIsValidUploadKey/nar_xz (0.00s)1635 --- PASS: TestIsValidUploadKey/build_log_question_mark (0.00s)1636 --- PASS: TestIsValidUploadKey/build_log_plus_in_name (0.00s)1637 --- PASS: TestIsValidUploadKey/build_log_home-manager_file (0.00s)1638 --- PASS: TestIsValidUploadKey/build_log (0.00s)1639 --- PASS: TestIsValidUploadKey/listing (0.00s)1640 --- PASS: TestIsValidUploadKey/nar_plain (0.00s)1641 --- PASS: TestIsValidUploadKey/nar_zst (0.00s)16422026/10/11 05:57:42 INFO Received uploads request method=POST path=/16432026/10/11 05:57:42 INFO Received push request method=POST path=/api/pushes16442026/10/11 05:57:42 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)16452026/10/11 05:57:42 INFO Uploading n7rn3b8ikqhwka6m62al2mxq09vmabiy-a (256B)16462026/10/11 05:57:42 INFO Uploading qrfcsmma9cl7dfd6iff5rd2z9imrr2hy-shared-dep (136B)16472026/10/11 05:57:42 WARN Failed to register uploaded object key=38w00ssmsllbrrbfzzbmcl0wbpf9spk0.ls error="server returned 404: 404 page not found\n"16482026/10/11 05:57:42 WARN Failed to register uploaded object key=qrfcsmma9cl7dfd6iff5rd2z9imrr2hy.ls error="server returned 404: 404 page not found\n"16492026/10/11 05:57:42 WARN Failed to register uploaded object key=n7rn3b8ikqhwka6m62al2mxq09vmabiy.ls error="server returned 404: 404 page not found\n"16502026/10/11 05:57:42 WARN Failed to register uploaded object key=nar/0pd4d7q06hc07gs8lpf3ww6gng6bk05ya6wi6bskm2dx2c461jxx.nar.zst error="server returned 404: 404 page not found\n"16512026/10/11 05:57:42 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign16522026/10/11 05:57:42 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"16532026/10/11 05:57:42 INFO Signed narinfos id=1 count=316542026/10/11 05:57:42 INFO Uploading 3 narinfos16552026/10/11 05:57:42 WARN Failed to register uploaded object key=qrfcsmma9cl7dfd6iff5rd2z9imrr2hy.narinfo error="server returned 404: 404 page not found\n"16562026/10/11 05:57:42 INFO Received complete push request method=POST path=/api/pushes/1/complete16572026/10/11 05:57:42 WARN Failed to register uploaded object key=38w00ssmsllbrrbfzzbmcl0wbpf9spk0.narinfo error="server returned 404: 404 page not found\n"16582026/10/11 05:57:42 WARN Failed to register uploaded object key=n7rn3b8ikqhwka6m62al2mxq09vmabiy.narinfo error="server returned 404: 404 page not found\n"16592026/10/11 05:57:42 INFO Completed push id=1 objects=8 duration=11.786875ms16602026/10/11 05:57:42 INFO Upload complete. (112ms)1661=== NAME TestClientPushesUseOnePush1662 client_pushes_test.go:97: Retrieved narinfo from S3:1663 StorePath: /private/var/tb/3/scratch/7155a60ad86daa12/build/TestClientPushesUseOnePush1067497657/001/store/qrfcsmma9cl7dfd6iff5rd2z9imrr2hy-shared-dep1664 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1665 Compression: zstd1666 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821667 NarSize: 1361668 References: 1669 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1670 client_pushes_test.go:97: Retrieved narinfo from S3:1671 StorePath: /private/var/tb/3/scratch/7155a60ad86daa12/build/TestClientPushesUseOnePush1067497657/001/store/n7rn3b8ikqhwka6m62al2mxq09vmabiy-a1672 URL: nar/0pd4d7q06hc07gs8lpf3ww6gng6bk05ya6wi6bskm2dx2c461jxx.nar.zst1673 Compression: zstd1674 NarHash: sha256:0pd4d7q06hc07gs8lpf3ww6gng6bk05ya6wi6bskm2dx2c461jxx1675 NarSize: 2561676 References: /private/var/tb/3/scratch/7155a60ad86daa12/build/TestClientPushesUseOnePush1067497657/001/store/qrfcsmma9cl7dfd6iff5rd2z9imrr2hy-shared-dep1677 CA: text:sha256:0w3gsfq6xijz9zgsxw8zaf4w15ajlnxasb1wdsrndbhka3li7xd51678 client_pushes_test.go:97: Retrieved narinfo from S3:1679 StorePath: /private/var/tb/3/scratch/7155a60ad86daa12/build/TestClientPushesUseOnePush1067497657/001/store/38w00ssmsllbrrbfzzbmcl0wbpf9spk0-b1680 URL: nar/0pd4d7q06hc07gs8lpf3ww6gng6bk05ya6wi6bskm2dx2c461jxx.nar.zst1681 Compression: zstd1682 NarHash: sha256:0pd4d7q06hc07gs8lpf3ww6gng6bk05ya6wi6bskm2dx2c461jxx1683 NarSize: 2561684 References: /private/var/tb/3/scratch/7155a60ad86daa12/build/TestClientPushesUseOnePush1067497657/001/store/qrfcsmma9cl7dfd6iff5rd2z9imrr2hy-shared-dep1685 CA: text:sha256:0w3gsfq6xijz9zgsxw8zaf4w15ajlnxasb1wdsrndbhka3li7xd51686--- PASS: TestClientPushesUseOnePush (6.58s)1687=== CONT TestUploadHandlersRejectOversizedBody/request_more_parts16882026/10/11 05:57:42 INFO Received request for more parts method=POST path=/1689=== CONT TestUploadHandlersRejectOversizedBody/complete_multipart16902026/10/11 05:57:42 INFO Received complete multipart upload request method=POST path=/1691=== CONT TestResolveDBConnectionString/flag_wins1692=== CONT TestResolveDBConnectionString/PGHOST_allows_empty1693=== CONT TestResolveDBConnectionString/nothing_configured1694=== CONT TestResolveDBConnectionString/missing_file_is_an_error1695=== CONT TestResolveDBConnectionString/file_when_flag_empty1696=== CONT TestForceGCDuringPushOffersSweptObject/before_pending_rows1697--- PASS: TestResolveDBConnectionString (0.02s)1698 --- PASS: TestResolveDBConnectionString/flag_wins (0.00s)1699 --- PASS: TestResolveDBConnectionString/PGHOST_allows_empty (0.00s)1700 --- PASS: TestResolveDBConnectionString/nothing_configured (0.00s)1701 --- PASS: TestResolveDBConnectionString/missing_file_is_an_error (0.00s)1702 --- PASS: TestResolveDBConnectionString/file_when_flag_empty (0.00s)1703=== NAME TestNARDeduplicationMetadataUploadBug1704 metadata_upload_test.go:48: First store path: /private/var/tb/3/scratch/7155a60ad86daa12/build/TestNARDeduplicationMetadataUploadBug455716111/001/store/jdbbm29zc9vrs7382nd4nx5vdfgq4z10-file1.txt17052026/10/11 05:57:42 INFO Received push request method=POST path=/api/pushes1706=== CONT TestForceGCDuringPushOffersSweptObject/after_presence_check1707--- PASS: TestUploadHandlersRejectOversizedBody (0.08s)1708 --- PASS: TestUploadHandlersRejectOversizedBody/request_more_parts (0.02s)1709 --- PASS: TestUploadHandlersRejectOversizedBody/complete_multipart (0.02s)1710 --- PASS: TestUploadHandlersRejectOversizedBody/create_pending_closure (0.28s)17112026/10/11 05:57:42 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)17122026/10/11 05:57:42 INFO Uploading jdbbm29zc9vrs7382nd4nx5vdfgq4z10-file1.txt (160B)17132026/10/11 05:57:42 WARN Failed to register uploaded object key=jdbbm29zc9vrs7382nd4nx5vdfgq4z10.ls error="server returned 404: 404 page not found\n"17142026/10/11 05:57:42 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign17152026/10/11 05:57:42 WARN Failed to register uploaded object key=nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst error="server returned 404: 404 page not found\n"17162026/10/11 05:57:42 INFO Signed narinfos id=1 count=117172026/10/11 05:57:42 INFO Uploading 1 narinfos17182026/10/11 05:57:42 INFO Received complete push request method=POST path=/api/pushes/1/complete17192026/10/11 05:57:42 WARN Failed to register uploaded object key=jdbbm29zc9vrs7382nd4nx5vdfgq4z10.narinfo error="server returned 404: 404 page not found\n"17202026/10/11 05:57:42 INFO Completed push id=1 objects=3 duration=18.755459ms17212026/10/11 05:57:42 INFO Upload complete. (212ms)1722=== NAME TestNARDeduplicationMetadataUploadBug1723 metadata_upload_test.go:54: Retrieved narinfo from S3:1724 StorePath: /private/var/tb/3/scratch/7155a60ad86daa12/build/TestNARDeduplicationMetadataUploadBug455716111/001/store/jdbbm29zc9vrs7382nd4nx5vdfgq4z10-file1.txt1725 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1726 Compression: zstd1727 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1728 NarSize: 1601729 References: 1730 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1731 metadata_upload_test.go:55: Retrieved .ls file from S3 (compressed size: 77 bytes)1732 metadata_upload_test.go:55: Decompressed .ls content (64 bytes):1733 {"version":1,"root":{"type":"regular","size":44,"narOffset":96}}1734 metadata_upload_test.go:64: Second store path (same content): /private/var/tb/3/scratch/7155a60ad86daa12/build/TestNARDeduplicationMetadataUploadBug455716111/001/store/hg3hxg76xz2k4n31jlcf3ir0802k9akv-file2.txt17352026/10/11 05:57:42 INFO Received push request method=POST path=/api/pushes17362026/10/11 05:57:42 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)1737=== NAME TestClientWithDependencies1738 client_integration_test.go:613: Built derivation: /private/var/tb/3/scratch/7155a60ad86daa12/build/TestClientWithDependencies3346967637/001/store/cpmgqfkxg4pjbyq1bvzz5ga235rsk7iz-test-script17392026/10/11 05:57:42 WARN Failed to register uploaded object key=hg3hxg76xz2k4n31jlcf3ir0802k9akv.ls error="server returned 404: 404 page not found\n"17402026/10/11 05:57:42 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign17412026/10/11 05:57:42 INFO Signed narinfos id=2 count=117422026/10/11 05:57:42 INFO Uploading 1 narinfos17432026/10/11 05:57:43 INFO Received complete push request method=POST path=/api/pushes/2/complete17442026/10/11 05:57:43 WARN Failed to register uploaded object key=hg3hxg76xz2k4n31jlcf3ir0802k9akv.narinfo error="server returned 404: 404 page not found\n"17452026/10/11 05:57:43 INFO Completed push id=2 objects=3 duration=837.542µs17462026/10/11 05:57:43 INFO Upload complete. (114ms)1747=== NAME TestNARDeduplicationMetadataUploadBug1748 metadata_upload_test.go:76: Retrieved narinfo from S3:1749 StorePath: /private/var/tb/3/scratch/7155a60ad86daa12/build/TestNARDeduplicationMetadataUploadBug455716111/001/store/hg3hxg76xz2k4n31jlcf3ir0802k9akv-file2.txt1750 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1751 Compression: zstd1752 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1753 NarSize: 1601754 References: 1755 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1756=== NAME TestClientWithDependencies1757 client_integration_test.go:615: Found 1 dependencies (including self)1758=== NAME TestNARDeduplicationMetadataUploadBug1759 metadata_upload_test.go:77: Retrieved .ls file from S3 (compressed size: 62 bytes)1760 metadata_upload_test.go:77: Decompressed .ls content (49 bytes):1761 {"version":1,"root":{"type":"regular","size":44}}1762--- PASS: TestNARDeduplicationMetadataUploadBug (5.94s)1763=== CONT TestIsValidCachePath/narinfo1764=== CONT TestIsValidCachePath/index.html1765=== CONT TestIsValidCachePath/short_hash1766=== CONT TestIsValidCachePath/wrong_extension1767=== CONT TestIsValidCachePath/leading_slash1768=== CONT TestIsValidCachePath/empty1769=== CONT TestIsValidCachePath/random_path1770=== CONT TestIsValidCachePath/invalid_char_u1771=== CONT TestIsValidCachePath/invalid_char_e1772=== CONT TestIsValidCachePath/traversal_in_middle1773=== CONT TestIsValidCachePath/traversal_parent1774=== CONT TestIsValidCachePath/nar_uncompressed1775=== CONT TestIsValidCachePath/nix-cache-info1776=== CONT TestIsValidCachePath/realisation1777=== CONT TestIsValidCachePath/log1778=== CONT TestIsValidCachePath/ls1779=== CONT TestIsValidCachePath/nar_xz1780=== CONT TestIsValidCachePath/nar_bz21781=== CONT TestIsValidCachePath/nar_zst1782=== CONT TestIsValidCachePath/narinfo_all_nix_base32_chars1783--- PASS: TestIsValidCachePath (0.02s)1784 --- PASS: TestIsValidCachePath/narinfo (0.00s)1785 --- PASS: TestIsValidCachePath/index.html (0.00s)1786 --- PASS: TestIsValidCachePath/short_hash (0.00s)1787 --- PASS: TestIsValidCachePath/wrong_extension (0.00s)1788 --- PASS: TestIsValidCachePath/leading_slash (0.00s)1789 --- PASS: TestIsValidCachePath/empty (0.00s)1790 --- PASS: TestIsValidCachePath/random_path (0.00s)1791 --- PASS: TestIsValidCachePath/invalid_char_u (0.00s)1792 --- PASS: TestIsValidCachePath/invalid_char_e (0.00s)1793 --- PASS: TestIsValidCachePath/traversal_in_middle (0.00s)1794 --- PASS: TestIsValidCachePath/traversal_parent (0.00s)1795 --- PASS: TestIsValidCachePath/nar_uncompressed (0.00s)1796 --- PASS: TestIsValidCachePath/nix-cache-info (0.00s)1797 --- PASS: TestIsValidCachePath/realisation (0.00s)1798 --- PASS: TestIsValidCachePath/log (0.00s)1799 --- PASS: TestIsValidCachePath/ls (0.00s)1800 --- PASS: TestIsValidCachePath/nar_xz (0.00s)1801 --- PASS: TestIsValidCachePath/nar_bz2 (0.00s)1802 --- PASS: TestIsValidCachePath/nar_zst (0.00s)1803 --- PASS: TestIsValidCachePath/narinfo_all_nix_base32_chars (0.00s)1804=== CONT TestParseSingleRange/none1805=== CONT TestParseSingleRange/start_past_EOF1806=== CONT TestParseSingleRange/single_byte1807=== CONT TestParseSingleRange/suffix_exceeds_size1808=== CONT TestParseSingleRange/suffix1809=== CONT TestParseSingleRange/end_clamped_to_size1810=== CONT TestParseSingleRange/start_far_past_EOF1811=== CONT TestParseSingleRange/open-ended1812=== CONT TestParseSingleRange/closed1813=== CONT TestParseSingleRange/malformed_end_before_start1814=== CONT TestParseSingleRange/malformed_both_empty1815=== CONT TestParseSingleRange/malformed_no_dash1816=== CONT TestParseSingleRange/multi-range_ignored1817=== CONT TestParseSingleRange/unknown_unit1818--- PASS: TestParseSingleRange (0.03s)1819 --- PASS: TestParseSingleRange/none (0.00s)1820 --- PASS: TestParseSingleRange/start_past_EOF (0.00s)1821 --- PASS: TestParseSingleRange/single_byte (0.00s)1822 --- PASS: TestParseSingleRange/suffix_exceeds_size (0.00s)1823 --- PASS: TestParseSingleRange/suffix (0.00s)1824 --- PASS: TestParseSingleRange/end_clamped_to_size (0.00s)1825 --- PASS: TestParseSingleRange/start_far_past_EOF (0.00s)1826 --- PASS: TestParseSingleRange/open-ended (0.00s)1827 --- PASS: TestParseSingleRange/closed (0.00s)1828 --- PASS: TestParseSingleRange/malformed_end_before_start (0.00s)1829 --- PASS: TestParseSingleRange/malformed_both_empty (0.00s)1830 --- PASS: TestParseSingleRange/malformed_no_dash (0.00s)1831 --- PASS: TestParseSingleRange/multi-range_ignored (0.00s)1832 --- PASS: TestParseSingleRange/unknown_unit (0.00s)1833=== CONT TestPresentNotReportedWhileGCDeletesClosure/stale18342026/10/11 05:57:43 INFO Received push request method=POST path=/api/pushes18352026/10/11 05:57:43 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)18362026/10/11 05:57:43 INFO Uploading cpmgqfkxg4pjbyq1bvzz5ga235rsk7iz-test-script (136B)18372026/10/11 05:57:43 WARN Failed to register uploaded object key=cpmgqfkxg4pjbyq1bvzz5ga235rsk7iz.ls error="server returned 404: 404 page not found\n"18382026/10/11 05:57:43 INFO Received push request method=POST path=/api/pushes18392026/10/11 05:57:43 WARN Failed to register uploaded object key=nar/1s7yghixzpinyqm7g59kyn3sav81pmnsdi5v63m6x4r2vacy907j.nar.zst error="server returned 404: 404 page not found\n"18402026/10/11 05:57:43 WARN Failed to register uploaded object key=log/qqqackpyq4hz1i4wba4pzg8cx32lqxsa-test-script.drv error="server returned 404: 404 page not found\n"18412026/10/11 05:57:43 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign18422026/10/11 05:57:43 INFO Signed narinfos id=1 count=118432026/10/11 05:57:43 INFO Uploading 1 narinfos18442026/10/11 05:57:43 INFO Received complete push request method=POST path=/api/pushes/1/complete18452026/10/11 05:57:43 INFO Uploading 2 paths to 127.0.0.1 (0 already cached)18462026/10/11 05:57:43 INFO Uploading cmbmdy01392jgbx2c96f3zd5mp8y0dr4-shared-dep (136B)18472026/10/11 05:57:43 WARN Failed to register uploaded object key=cpmgqfkxg4pjbyq1bvzz5ga235rsk7iz.narinfo error="server returned 404: 404 page not found\n"18482026/10/11 05:57:43 INFO Uploading v0qhdm6a2l06fvhyg30za9x9vs9l259j-top (264B)18492026/10/11 05:57:43 INFO Completed push id=1 objects=4 duration=18.572833ms18502026/10/11 05:57:43 INFO Upload complete. (196ms)18512026/10/11 05:57:43 WARN Failed to register uploaded object key=v0qhdm6a2l06fvhyg30za9x9vs9l259j.ls error="server returned 404: 404 page not found\n"1852=== NAME TestClientWithDependencies1853 client_integration_test.go:617: Skipping nix copy test - isolated store (/private/var/tb/3/scratch/7155a60ad86daa12/build/TestClientWithDependencies3346967637/001/store) requires matching store prefix18542026/10/11 05:57:43 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"18552026/10/11 05:57:43 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign18562026/10/11 05:57:43 WARN Failed to register uploaded object key=cmbmdy01392jgbx2c96f3zd5mp8y0dr4.ls error="server returned 404: 404 page not found\n"18572026/10/11 05:57:43 WARN Failed to register uploaded object key=nar/05xp3ljs4igimwhp4k28mzpclrm7la5qg1vccl2yabqmwjgkcl9p.nar.zst error="server returned 404: 404 page not found\n"18582026/10/11 05:57:43 INFO Signed narinfos id=1 count=218592026/10/11 05:57:43 INFO Uploading 2 narinfos18602026/10/11 05:57:43 WARN Failed to register uploaded object key=cmbmdy01392jgbx2c96f3zd5mp8y0dr4.narinfo error="server returned 404: 404 page not found\n"18612026/10/11 05:57:43 INFO Received complete push request method=POST path=/api/pushes/1/complete18622026/10/11 05:57:43 WARN Failed to register uploaded object key=v0qhdm6a2l06fvhyg30za9x9vs9l259j.narinfo error="server returned 404: 404 page not found\n"1863=== NAME TestClientMultipleUploads1864 client_integration_test.go:358: Created store path 0: /private/var/tb/3/scratch/7155a60ad86daa12/build/TestClientMultipleUploads3421128934/001/store/qdh6wawhvbz4wxykfkv61jsxc6gb4fwd-test-file-0.txt18652026/10/11 05:57:43 INFO Completed push id=1 objects=6 duration=21.913708ms18662026/10/11 05:57:43 INFO Upload complete. (240ms)18672026/10/11 05:57:43 INFO Received uploads request method=POST path=/api/pending_closures1868=== NAME TestClientSharedPathCommittedMidPush1869 client_integration_test.go:680: Retrieved narinfo from S3:1870 StorePath: /private/var/tb/3/scratch/7155a60ad86daa12/build/TestClientSharedPathCommittedMidPush1995435141/001/store/cmbmdy01392jgbx2c96f3zd5mp8y0dr4-shared-dep1871 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1872 Compression: zstd1873 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821874 NarSize: 1361875 References: 1876 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1877--- PASS: TestClientWithDependencies (6.07s)1878=== CONT TestPresentNotReportedWhileGCDeletesClosure/fresh1879=== NAME TestClientSharedPathCommittedMidPush1880 client_integration_test.go:680: Retrieved narinfo from S3:1881 StorePath: /private/var/tb/3/scratch/7155a60ad86daa12/build/TestClientSharedPathCommittedMidPush1995435141/001/store/v0qhdm6a2l06fvhyg30za9x9vs9l259j-top1882 URL: nar/05xp3ljs4igimwhp4k28mzpclrm7la5qg1vccl2yabqmwjgkcl9p.nar.zst1883 Compression: zstd1884 NarHash: sha256:05xp3ljs4igimwhp4k28mzpclrm7la5qg1vccl2yabqmwjgkcl9p1885 NarSize: 2641886 References: /private/var/tb/3/scratch/7155a60ad86daa12/build/TestClientSharedPathCommittedMidPush1995435141/001/store/cmbmdy01392jgbx2c96f3zd5mp8y0dr4-shared-dep1887 CA: text:sha256:08ssfngbk96kdh72bkn054v3vlb3cyvw3hy46nps3b12s34kai8g18882026/10/11 05:57:43 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=018892026/10/11 05:57:43 INFO Received create pin request method=POST path=/api/pins/myapp18902026/10/11 05:57:43 INFO Aborted multipart uploads count=1 kept=01891=== NAME TestClientMultipleUploads1892 client_integration_test.go:358: Created store path 1: /private/var/tb/3/scratch/7155a60ad86daa12/build/TestClientMultipleUploads3421128934/001/store/49bds2pdhbf2bhd689pz464qdxhg78wg-test-file-1.txt1893--- PASS: TestClientSharedPathCommittedMidPush (5.85s)1894=== CONT TestClientErrorHandling/InvalidStorePath18952026/10/11 05:57:43 INFO Created/updated pin name=myapp store_path=/private/var/tb/3/scratch/7155a60ad86daa12/build/TestPinProtectsFromGC349778345/001/store/b30r0if0nc32k1bf84bhyxhyj30xfbax-pinned-file.txt narinfo_key=b30r0if0nc32k1bf84bhyxhyj30xfbax.narinfo18962026/10/11 05:57:43 INFO Starting cleanup of old closures method=DELETE path=/api/closures18972026/10/11 05:57:43 INFO Received cleanup request method=DELETE path=/api/pending_closures18982026/10/11 05:57:43 INFO Garbage collection started18992026/10/11 05:57:43 INFO Aborted multipart uploads count=0 kept=019002026/10/11 05:57:43 INFO Aborted multipart uploads count=1 kept=019012026/10/11 05:57:43 WARN Force mode enabled - objects will be deleted immediately without grace period1902--- PASS: TestPendingCleanupUsesOneCutoff (11.76s)19032026/10/11 05:57:43 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=01904=== CONT TestClientErrorHandling/ServerNotAvailable19052026/10/11 05:57:43 INFO Vacuumed table table=pending_closures1906=== NAME TestClientMultipleUploads1907 client_integration_test.go:358: Created store path 2: /private/var/tb/3/scratch/7155a60ad86daa12/build/TestClientMultipleUploads3421128934/001/store/2yi9dy6b1y5mnrhbbmz0487hy2cm5app-test-file-2.txt19082026/10/11 05:57:43 INFO Vacuumed table table=pending_objects19092026/10/11 05:57:43 INFO Vacuumed table table=multipart_uploads19102026/10/11 05:57:43 INFO Vacuumed table table=closures19112026/10/11 05:57:43 INFO Vacuumed table table=objects19122026/10/11 05:57:43 INFO Received push request method=POST path=/api/pushes19132026/10/11 05:57:43 INFO Received push request method=POST path=/api/pushes19142026/10/11 05:57:43 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign19152026/10/11 05:57:43 INFO Uploading 3 paths to 127.0.0.1 (0 already cached)19162026/10/11 05:57:43 INFO Uploading qdh6wawhvbz4wxykfkv61jsxc6gb4fwd-test-file-0.txt (160B)19172026/10/11 05:57:43 INFO Uploading 49bds2pdhbf2bhd689pz464qdxhg78wg-test-file-1.txt (160B)19182026/10/11 05:57:43 INFO Uploading 2yi9dy6b1y5mnrhbbmz0487hy2cm5app-test-file-2.txt (160B)19192026/10/11 05:57:43 INFO Signed narinfos id=1 count=119202026/10/11 05:57:43 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign19212026/10/11 05:57:43 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign19222026/10/11 05:57:43 ERROR Failed to sign narinfos signer="index 1" error="signing key cannot be nil"19232026/10/11 05:57:43 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign19242026/10/11 05:57:43 ERROR Failed to sign narinfos signer=niks3-test-1 error="signer failed"19252026/10/11 05:57:43 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign19262026/10/11 05:57:43 WARN Failed to register uploaded object key=nar/0ahq3izw3h0b0c08p3xdfclh758fwxnp85ccvflasb4vnfsv50ri.nar.zst error="server returned 404: 404 page not found\n"19272026/10/11 05:57:43 ERROR Signer returned unexpected signature count signer=niks3-test-1 got=0 want=119282026/10/11 05:57:43 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign19292026/10/11 05:57:43 WARN Failed to register uploaded object key=49bds2pdhbf2bhd689pz464qdxhg78wg.ls error="server returned 404: 404 page not found\n"19302026/10/11 05:57:43 WARN Failed to register uploaded object key=nar/13p9pqi0ga6fx2apcwls9hjnv7nmf740ggpn5zvfzdsp5vz2bbg4.nar.zst error="server returned 404: 404 page not found\n"19312026/10/11 05:57:43 ERROR Signer returned unexpected object key signer=niks3-test-1 object_key=unexpected.narinfo1932--- PASS: TestPush_SignsNarinfosOfItsPendingObjects (5.69s)19332026/10/11 05:57:43 WARN Failed to register uploaded object key=2yi9dy6b1y5mnrhbbmz0487hy2cm5app.ls error="server returned 404: 404 page not found\n"1934=== CONT TestClientErrorHandling/InvalidAuthToken19352026/10/11 05:57:43 WARN Failed to register uploaded object key=qdh6wawhvbz4wxykfkv61jsxc6gb4fwd.ls error="server returned 404: 404 page not found\n"19362026/10/11 05:57:43 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign19372026/10/11 05:57:43 WARN Failed to register uploaded object key=nar/1823g6vx4q5zqvr73m7lkq1wpk40fin7bsc792di430yk7sg4lka.nar.zst error="server returned 404: 404 page not found\n"19382026/10/11 05:57:43 INFO Signed narinfos id=1 count=319392026/10/11 05:57:43 INFO Uploading 3 narinfos19402026/10/11 05:57:43 WARN Failed to register uploaded object key=qdh6wawhvbz4wxykfkv61jsxc6gb4fwd.narinfo error="server returned 404: 404 page not found\n"19412026/10/11 05:57:43 WARN Failed to register uploaded object key=2yi9dy6b1y5mnrhbbmz0487hy2cm5app.narinfo error="server returned 404: 404 page not found\n"19422026/10/11 05:57:43 INFO Received complete push request method=POST path=/api/pushes/1/complete19432026/10/11 05:57:43 WARN Failed to register uploaded object key=49bds2pdhbf2bhd689pz464qdxhg78wg.narinfo error="server returned 404: 404 page not found\n"19442026/10/11 05:57:43 INFO Completed push id=1 objects=9 duration=38.046709ms19452026/10/11 05:57:43 INFO Upload complete. (302ms)1946=== NAME TestClientMultipleUploads19472026/10/11 05:57:43 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/objects/present1948 client_integration_test.go:369: Uploaded 3 paths in 344.907959ms1949=== RUN TestPush_RejectsBadRequests/no_roots1950=== PAUSE TestPush_RejectsBadRequests/no_roots1951=== RUN TestPush_RejectsBadRequests/no_objects1952=== PAUSE TestPush_RejectsBadRequests/no_objects1953=== RUN TestPush_RejectsBadRequests/bad_root1954=== PAUSE TestPush_RejectsBadRequests/bad_root1955=== RUN TestPush_RejectsBadRequests/root_not_in_objects19562026/10/11 05:57:44 WARN Request failed, retrying attempt=2 backoff=213.336765ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/objects/present1957=== PAUSE TestPush_RejectsBadRequests/root_not_in_objects1958=== CONT TestCacheConfigHandler/full_config,_no_issuer1959=== CONT TestCacheConfigHandler/no_signing_keys1960=== CONT TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1961=== CONT TestCacheConfigHandler/no_cache_url_configured1962--- PASS: TestCacheConfigHandler (0.01s)1963 --- PASS: TestCacheConfigHandler/full_config,_no_issuer (0.00s)1964 --- PASS: TestCacheConfigHandler/no_signing_keys (0.00s)1965 --- PASS: TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator (0.00s)1966 --- PASS: TestCacheConfigHandler/no_cache_url_configured (0.00s)1967=== CONT TestServerTLSConfig/no_client_CA1968=== CONT TestServerTLSConfig/not_a_PEM_file1969--- PASS: TestClientMultipleUploads (6.26s)1970=== CONT TestServerTLSConfig/missing_CA_file1971=== CONT TestService_RequireScope_OIDC/builder_may_write1972=== CONT TestService_RequireScope_OIDC/static_token_may_write1973=== CONT TestService_RequireScope_OIDC/ops_may_admin1974=== CONT TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1975=== CONT TestService_RequireScope_OIDC/static_token_may_admin1976=== CONT TestService_RequireScope_OIDC/reader_may_not_write1977--- PASS: TestServerTLSConfig (0.00s)1978 --- PASS: TestServerTLSConfig/no_client_CA (0.00s)1979 --- PASS: TestServerTLSConfig/missing_CA_file (0.00s)1980 --- PASS: TestServerTLSConfig/not_a_PEM_file (0.03s)1981=== CONT TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read19822026/10/11 05:57:44 WARN Authentication failed token_preview=wrong token_length=5 oidc_error="no provider could verify the token (signature or issuer mismatch)" oidc_provider="" tried_providers=[test]1983=== CONT TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1984=== CONT TestService_RequireScope_OIDC/reader_may_read_with_netrc1985=== CONT TestService_RequireScope_OIDC/anonymous_may_not_read1986=== CONT TestService_RequireScope_OIDC/writer_implies_read1987=== CONT TestService_RequireScope_OIDC/reader_may_read1988=== CONT TestService_RequireScope_OIDC/builder_may_not_admin1989=== CONT TestService_RequireScope_OIDC/ops_may_not_write1990=== CONT TestService_AuthMiddleware_OIDC/valid_OIDC_token1991--- PASS: TestService_RequireScope_OIDC (5.31s)1992 --- PASS: TestService_RequireScope_OIDC/builder_may_write (0.00s)1993 --- PASS: TestService_RequireScope_OIDC/static_token_may_write (0.00s)1994 --- PASS: TestService_RequireScope_OIDC/ops_may_admin (0.00s)1995 --- PASS: TestService_RequireScope_OIDC/empty_netrc_password_may_not_read (0.00s)1996 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin (0.00s)1997 --- PASS: TestService_RequireScope_OIDC/reader_may_not_write (0.00s)1998 --- PASS: TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read (0.01s)1999 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin_with_netrc (0.00s)2000 --- PASS: TestService_RequireScope_OIDC/reader_may_read_with_netrc (0.00s)2001 --- PASS: TestService_RequireScope_OIDC/anonymous_may_not_read (0.00s)2002 --- PASS: TestService_RequireScope_OIDC/writer_implies_read (0.00s)2003 --- PASS: TestService_RequireScope_OIDC/reader_may_read (0.00s)2004 --- PASS: TestService_RequireScope_OIDC/builder_may_not_admin (0.00s)2005 --- PASS: TestService_RequireScope_OIDC/ops_may_not_write (0.00s)2006=== CONT TestService_AuthMiddleware_OIDC/malformed_token_rejected20072026/10/11 05:57:44 WARN Authentication failed token_preview=not-a-valid-jwt token_length=15 oidc_error="no provider could verify the token (signature or issuer mismatch)" oidc_provider="" tried_providers=[test]2008=== CONT TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected2009=== CONT TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured20102026/10/11 05:57:44 WARN Authentication failed token_preview=eyJhbGciOi...zRjvs-0rxg token_length=701 oidc_error="no rule matched: claim \"repository_owner\" value [otherorg] not in allowed patterns [myorg]" oidc_provider=test tried_providers=[test]2011=== CONT TestPush_RejectsBadRequests/no_roots2012=== CONT TestPush_RejectsBadRequests/bad_root20132026/10/11 05:57:44 INFO Received push request method=POST path=/api/pushes20142026/10/11 05:57:44 INFO Received push request method=POST path=/api/pushes2015=== CONT TestPush_RejectsBadRequests/root_not_in_objects20162026/10/11 05:57:44 INFO Received push request method=POST path=/api/pushes2017=== CONT TestPush_RejectsBadRequests/no_objects20182026/10/11 05:57:44 INFO Received push request method=POST path=/api/pushes2019--- PASS: TestService_AuthMiddleware_OIDC (5.52s)2020 --- PASS: TestService_AuthMiddleware_OIDC/valid_OIDC_token (0.00s)2021 --- PASS: TestService_AuthMiddleware_OIDC/malformed_token_rejected (0.01s)2022 --- PASS: TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected (0.01s)2023 --- PASS: TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured (0.00s)2024--- PASS: TestPush_RejectsBadRequests (5.41s)2025 --- PASS: TestPush_RejectsBadRequests/no_roots (0.00s)2026 --- PASS: TestPush_RejectsBadRequests/root_not_in_objects (0.00s)2027 --- PASS: TestPush_RejectsBadRequests/no_objects (0.00s)2028 --- PASS: TestPush_RejectsBadRequests/bad_root (0.01s)20292026/10/11 05:57:44 WARN Request failed, retrying attempt=3 backoff=433.864586ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/objects/present2030--- PASS: TestObjectStatsLargeCommit (13.41s)20312026/10/11 05:57:44 INFO Received uploads request method=POST path=/api/pending_closures2032=== NAME TestOrphanedObjectsGCStressTest2033 orphaned_objects_gc_test.go:503: Stress test completed successfully:2034 orphaned_objects_gc_test.go:504: - Active objects preserved: 202035 orphaned_objects_gc_test.go:505: - Objects deleted: 2102036 orphaned_objects_gc_test.go:506: - Total GC'd: 2102037--- PASS: TestOrphanedObjectsGCStressTest (13.90s)2038--- PASS: TestService_Rustfstest (5.43s)20392026/10/11 05:57:44 WARN Request failed, retrying attempt=4 backoff=862.003587ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/objects/present20402026/10/11 05:57:44 INFO Received complete multipart upload request method=POST path=/api/multipart/complete20412026/10/11 05:57:44 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified key does not exist." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=Y2JhY2NlNmQtMWQ5My00ZmEwLTljNTktYTJmNWJhNGU5ZTAxLmJhNjAyNzlhLTM3NDgtNDYzNy04MWUwLWVlMmRmODY5Y2M1YXgxNzkxNjk4MjY0NDk2MzI3MDAw20422026/10/11 05:57:44 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=Y2JhY2NlNmQtMWQ5My00ZmEwLTljNTktYTJmNWJhNGU5ZTAxLmJhNjAyNzlhLTM3NDgtNDYzNy04MWUwLWVlMmRmODY5Y2M1YXgxNzkxNjk4MjY0NDk2MzI3MDAw parts=12043--- PASS: TestCompleteMultipartUpload_ErrorButObjectExists (5.80s)2044--- PASS: TestDeleteClosuresRacingPins (9.54s)20452026/10/11 05:57:45 INFO Received uploads request method=POST path=/api/pending_closures20462026/10/11 05:57:45 INFO Received uploads request method=POST path=/api/pending_closures20472026/10/11 05:57:45 INFO Received complete multipart upload request method=POST path=/api/multipart/complete20482026/10/11 05:57:45 INFO Completed multipart upload object_key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhh0100000000000000000000.nar.zst upload_id=Y2JhY2NlNmQtMWQ5My00ZmEwLTljNTktYTJmNWJhNGU5ZTAxLjNkZGE5YTE0LTdjNTYtNDU5OC04ZmY1LTk1ZTY0MTNjYjY0OHgxNzkxNjk4MjYzMzk2NzM2MDAw parts=1220492026/10/11 05:57:45 INFO Received uploads request method=POST path=/api/pending_closures20502026/10/11 05:57:45 INFO Received push request method=POST path=/api/pushes2051--- PASS: TestCompletedNarNotReofferedAcrossClosures (7.44s)20522026/10/11 05:57:45 INFO Received complete push request method=POST path=/api/pushes/1/complete20532026/10/11 05:57:45 INFO Completed push id=1 objects=4 duration=38.011791ms20542026/10/11 05:57:45 INFO Received push request method=POST path=/api/pushes20552026/10/11 05:57:45 INFO Aborted multipart uploads count=0 kept=020562026/10/11 05:57:45 WARN Force mode enabled - objects will be deleted immediately without grace period2057=== NAME TestPinProtectsFromGC2058 client_integration_test.go:840: Pin successfully protected closure from garbage collection20592026/10/11 05:57:45 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=020602026/10/11 05:57:45 WARN Request failed, retrying attempt=5 backoff=1.481131944s error="Post \"http://localhost:19999/api/objects/present\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/objects/present20612026/10/11 05:57:45 INFO Vacuumed table table=pending_closures20622026/10/11 05:57:45 INFO Received uploads request method=POST path=/api/pending_closures20632026/10/11 05:57:45 INFO Vacuumed table table=pending_objects2064--- PASS: TestPinProtectsFromGC (10.90s)20652026/10/11 05:57:45 INFO Vacuumed table table=multipart_uploads20662026/10/11 05:57:45 INFO Vacuumed table table=closures20672026/10/11 05:57:45 INFO Vacuumed table table=objects20682026/10/11 05:57:45 INFO Received complete push request method=POST path=/api/pushes/2/complete20692026/10/11 05:57:45 INFO Completed push id=2 objects=4 duration=7.852709ms2070--- PASS: TestPush_SkippedKeySurvivesGCBeforeCommit (5.98s)20712026/10/11 05:57:45 INFO Registered completed upload object_key=nar/jjjjjjjjjjjjjjjjjjjjjjjjjjjjjj0100000000000000000000.nar.zst20722026/10/11 05:57:45 INFO Received uploads request method=POST path=/api/pending_closures2073--- PASS: TestPresignedUploadRegisteredBeforeCommit (6.02s)20742026-10-11 05:57:46.140 UTC [91853] LOG: checkpoint starting: wal20752026/10/11 05:57:46 INFO Aborted multipart uploads count=0 kept=020762026/10/11 05:57:46 WARN Force mode enabled - objects will be deleted immediately without grace period20772026-10-11 05:57:46.671 UTC [92339] ERROR: canceling statement due to user request20782026-10-11 05:57:46.671 UTC [92339] STATEMENT: -- name: MarkStaleObjects :execrows2079 WITH RECURSIVE ct AS (2080 SELECT timezone('UTC', now()) AS now2081 ),2082 closure_reach AS (2083 -- Start with all closure keys2084 SELECT o.key, o.refs2085 FROM objects o2086 INNER JOIN closures c ON o.key = c.key2087 UNION2088 -- Recursively add all referenced objects2089 SELECT o.key, o.refs2090 FROM objects o2091 INNER JOIN closure_reach cr ON o.key = ANY(cr.refs)2092 ),2093 reachable_objects AS (2094 SELECT DISTINCT key FROM closure_reach2095 ),2096 stale_objects AS (2097 SELECT o.key2098 FROM objects AS o, ct2099 WHERE2100 NOT EXISTS (2101 SELECT 12102 FROM reachable_objects ro2103 WHERE ro.key = o.key2104 )2105 AND NOT EXISTS (2106 SELECT 12107 FROM pending_objects AS po2108 WHERE po.key = o.key2109 )2110 AND o.deleted_at IS NULL -- Only mark fresh objects2111 ORDER BY o.key COLLATE "C" -- lock in key order, like commit_pending_closure2112 FOR UPDATE2113 )2114 UPDATE objects2115 SET2116 deleted_at = ct.now,2117 first_deleted_at = COALESCE(first_deleted_at, ct.now)2118 FROM stale_objects, ct2119 WHERE objects.key = stale_objects.key2120 21212026/10/11 05:57:46 INFO Aborted multipart uploads count=0 kept=021222026/10/11 05:57:46 INFO Received complete multipart upload request method=POST path=/api/multipart/complete21232026/10/11 05:57:46 WARN Force mode enabled - objects will be deleted immediately without grace period21242026/10/11 05:57:46 ERROR failed to remove object object=nar/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa.nar.zst error="Post \"http://localhost:59678/bucket93/?delete=\": context canceled"2125--- PASS: TestGCEndsOnShutdown (0.00s)2126 --- PASS: TestGCEndsOnShutdown/before_the_run (5.87s)2127 --- PASS: TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark (5.58s)2128 --- PASS: TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete (5.35s)21292026/10/11 05:57:46 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=Y2JhY2NlNmQtMWQ5My00ZmEwLTljNTktYTJmNWJhNGU5ZTAxLjliZWFiZmUwLWFmMjItNDg0My1iY2I5LTc1ZmIwOGE4YzEzYngxNzkxNjk4MjY1MDkxODg1MDAw parts=1221302026/10/11 05:57:47 INFO Received uploads request method=POST path=/api/pending_closures21312026/10/11 05:57:47 INFO Received uploads request method=POST path=/api/pending_closures21322026/10/11 05:57:47 INFO Received uploads request method=POST path=/api/pending_closures21332026/10/11 05:57:47 WARN Request failed, retrying attempt=1 backoff=100ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/cache-config2134--- PASS: TestConcurrentCommitsSharingObjectsDoNotDeadlock (7.09s)21352026/10/11 05:57:47 WARN Request failed, retrying attempt=2 backoff=207.062543ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21362026/10/11 05:57:47 INFO Received uploads request method=POST path=/api/pending_closures21372026/10/11 05:57:47 INFO Aborted multipart uploads count=0 kept=021382026/10/11 05:57:47 WARN Force mode enabled - objects will be deleted immediately without grace period21392026/10/11 05:57:47 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=021402026/10/11 05:57:47 INFO Vacuumed table table=pending_closures21412026/10/11 05:57:47 INFO Vacuumed table table=pending_objects21422026/10/11 05:57:47 INFO Vacuumed table table=multipart_uploads21432026/10/11 05:57:47 INFO Vacuumed table table=closures21442026/10/11 05:57:47 INFO Vacuumed table table=objects21452026/10/11 05:57:47 WARN Request failed, retrying attempt=3 backoff=402.275011ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21462026/10/11 05:57:47 INFO Received uploads request method=POST path=/api/pending_closures21472026/10/11 05:57:47 INFO Aborted multipart uploads count=0 kept=021482026/10/11 05:57:47 WARN Force mode enabled - objects will be deleted immediately without grace period21492026/10/11 05:57:47 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=021502026/10/11 05:57:47 INFO Vacuumed table table=pending_closures21512026/10/11 05:57:47 INFO Vacuumed table table=pending_objects21522026/10/11 05:57:47 INFO Vacuumed table table=multipart_uploads21532026/10/11 05:57:47 INFO Vacuumed table table=closures21542026/10/11 05:57:47 INFO Vacuumed table table=objects2155--- PASS: TestForceGCDuringPushOffersSweptObject (0.00s)2156 --- PASS: TestForceGCDuringPushOffersSweptObject/before_pending_rows (5.04s)2157 --- PASS: TestForceGCDuringPushOffersSweptObject/after_presence_check (5.17s)21582026/10/11 05:57:47 WARN Request failed, retrying attempt=4 backoff=722.249601ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/cache-config2159--- PASS: TestPendingClosureWriteTimeout (0.05s)2160 --- PASS: TestPendingClosureWriteTimeout/empty (0.00s)2161 --- PASS: TestPendingClosureWriteTimeout/670k_objects (0.00s)2162 --- PASS: TestPendingClosureWriteTimeout/400_objects (0.00s)2163 --- PASS: TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline (5.75s)21642026/10/11 05:57:48 INFO Received complete multipart upload request method=POST path=/api/multipart/complete21652026/10/11 05:57:48 WARN Failed to abort redundant multipart upload, keeping its row object_key=nar/gggggggggggggggggggggggggggggg0200000000000000000000.nar.zst upload_id=Y2JhY2NlNmQtMWQ5My00ZmEwLTljNTktYTJmNWJhNGU5ZTAxLjEwZmU0ZTk3LTk2YTUtNGQyMC1iMGQ1LWU4ZTJiZDYzZTQyOXgxNzkxNjk4MjY3MDUzNjI5MDAw error="Get \"http://127.0.0.1:1/bucket87/?location=\": dial tcp 127.0.0.1:1: connect: connection refused"21662026/10/11 05:57:48 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0200000000000000000000.nar.zst upload_id=Y2JhY2NlNmQtMWQ5My00ZmEwLTljNTktYTJmNWJhNGU5ZTAxLmVkZTM5NzQzLWZhNDItNDZmNi1iYWEzLTY5ZWNhZTY3MTY0MngxNzkxNjk4MjY3MDA5NTA5MDAw parts=1221672026/10/11 05:57:48 INFO Received cleanup request method=DELETE path=/api/pending_closures21682026/10/11 05:57:48 INFO Aborted multipart uploads count=1 kept=02169--- PASS: TestRedundantMultipartUpload (8.94s)2170--- PASS: TestPresentNotReportedWhileGCDeletesClosure (0.00s)2171 --- PASS: TestPresentNotReportedWhileGCDeletesClosure/stale (5.27s)2172 --- PASS: TestPresentNotReportedWhileGCDeletesClosure/fresh (5.22s)21732026/10/11 05:57:48 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"21742026/10/11 05:57:48 WARN Request failed, retrying attempt=5 backoff=1.489671623s error="Get \"http://localhost:19999/api/cache-config\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21752026/10/11 05:57:48 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"21762026/10/11 05:57:50 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 127.0.0.1:19999: connect: connection refused"21772026/10/11 05:57:50 WARN Request failed, retrying attempt=1 backoff=100ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21782026/10/11 05:57:50 WARN Request failed, retrying attempt=2 backoff=200.824714ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21792026/10/11 05:57:50 WARN Request failed, retrying attempt=3 backoff=426.459738ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21802026/10/11 05:57:50 WARN Request failed, retrying attempt=4 backoff=809.675303ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21812026/10/11 05:57:51 WARN Request failed, retrying attempt=5 backoff=1.480101528s error="Get \"http://localhost:19999/api/cache-config\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21822026/10/11 05:57:53 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures21832026/10/11 05:57:53 WARN Request failed, retrying attempt=2 backoff=201.667913ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures21842026/10/11 05:57:53 WARN Request failed, retrying attempt=3 backoff=379.309716ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures21852026/10/11 05:57:53 WARN Request failed, retrying attempt=4 backoff=854.530561ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures21862026/10/11 05:57:54 WARN Request failed, retrying attempt=5 backoff=1.648143423s error="Post \"http://localhost:19999/api/pending_closures\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures2187--- PASS: TestClientErrorHandling (0.01s)2188 --- PASS: TestClientErrorHandling/InvalidStorePath (4.88s)2189 --- PASS: TestClientErrorHandling/InvalidAuthToken (4.82s)2190 --- PASS: TestClientErrorHandling/ServerNotAvailable (12.74s)2191PASS21922026-10-11 05:57:56.543 UTC [91848] LOG: received smart shutdown request21932026-10-11 05:57:56.544 UTC [91848] LOG: background worker "logical replication launcher" (PID 91858) exited with exit code 121942026-10-11 05:57:57.716 UTC [91853] LOG: checkpoint complete: wrote 11881 buffers (72.5%), wrote 5 SLRU buffers; 0 WAL file(s) added, 0 removed, 33 recycled; write=10.777 s, sync=0.679 s, total=11.577 s; sync files=34045, longest=0.021 s, average=0.001 s; distance=533058 kB, estimate=533058 kB; lsn=0/227CFDC8, redo lsn=0/2201DB5021952026-10-11 05:57:57.717 UTC [91853] LOG: shutting down21962026-10-11 05:57:57.718 UTC [91853] LOG: checkpoint starting: shutdown immediate21972026-10-11 05:57:57.748 UTC [91853] LOG: checkpoint complete: wrote 491 buffers (3.0%), wrote 1 SLRU buffers; 0 WAL file(s) added, 0 removed, 0 recycled; write=0.003 s, sync=0.010 s, total=0.031 s; sync files=90, longest=0.002 s, average=0.001 s; distance=7880 kB, estimate=480541 kB; lsn=0/227CFE40, redo lsn=0/227CFE4021982026-10-11 05:57:57.754 UTC [91848] LOG: database system is shut down2199Running OIDC tests...2200=== RUN TestAudienceForIssuer2201=== PAUSE TestAudienceForIssuer2202=== RUN TestGlobMatch2203=== PAUSE TestGlobMatch2204=== RUN TestValidateToken_ValidToken2205=== PAUSE TestValidateToken_ValidToken2206=== RUN TestValidateToken_WrongAudience2207=== PAUSE TestValidateToken_WrongAudience2208=== RUN TestValidateToken_Expired2209=== PAUSE TestValidateToken_Expired2210=== RUN TestValidateToken_BoundClaimsMismatch2211=== PAUSE TestValidateToken_BoundClaimsMismatch2212=== RUN TestValidateToken_BoundSubjectMismatch2213=== PAUSE TestValidateToken_BoundSubjectMismatch2214=== RUN TestValidateToken_MultipleProviders2215=== PAUSE TestValidateToken_MultipleProviders2216=== RUN TestValidateToken_NoMatchingProvider2217=== PAUSE TestValidateToken_NoMatchingProvider2218=== RUN TestValidateToken_KubernetesServiceAccount2219=== PAUSE TestValidateToken_KubernetesServiceAccount2220=== RUN TestNewValidator_KubernetesRequiresCA2221=== PAUSE TestNewValidator_KubernetesRequiresCA2222=== RUN TestValidateToken_KubernetesIssuerFromOwnToken2223=== PAUSE TestValidateToken_KubernetesIssuerFromOwnToken2224=== RUN TestPins_ReservedForMatchingRule2225=== PAUSE TestPins_ReservedForMatchingRule2226=== RUN TestPins_TopLevelShorthand2227=== PAUSE TestPins_TopLevelShorthand2228=== RUN TestPins_ConfigValidation2229=== PAUSE TestPins_ConfigValidation2230=== RUN TestScopes_LegacyProviderDefaultsToWrite2231=== PAUSE TestScopes_LegacyProviderDefaultsToWrite2232=== RUN TestScopes_Rules2233=== PAUSE TestScopes_Rules2234=== RUN TestScopes_ConfigValidation2235=== PAUSE TestScopes_ConfigValidation2236=== CONT TestAudienceForIssuer2237=== CONT TestValidateToken_KubernetesServiceAccount2238=== CONT TestPins_ReservedForMatchingRule2239=== CONT TestValidateToken_BoundClaimsMismatch2240--- PASS: TestAudienceForIssuer (0.00s)2241=== CONT TestValidateToken_KubernetesIssuerFromOwnToken2242=== CONT TestPins_ConfigValidation2243=== CONT TestPins_TopLevelShorthand2244=== CONT TestNewValidator_KubernetesRequiresCA2245=== CONT TestValidateToken_Expired2246=== CONT TestValidateToken_WrongAudience2247--- PASS: TestPins_ConfigValidation (0.01s)2248=== CONT TestValidateToken_ValidToken2249=== CONT TestGlobMatch2250=== RUN TestGlobMatch/foo_foo2251=== PAUSE TestGlobMatch/foo_foo2252=== RUN TestGlobMatch/foo_bar2253=== PAUSE TestGlobMatch/foo_bar2254=== RUN TestGlobMatch/*_2255=== PAUSE TestGlobMatch/*_2256=== RUN TestGlobMatch/*_anything2257=== PAUSE TestGlobMatch/*_anything2258=== RUN TestGlobMatch/foo*_foo2259=== PAUSE TestGlobMatch/foo*_foo2260=== RUN TestGlobMatch/foo*_foobar2261=== PAUSE TestGlobMatch/foo*_foobar2262=== RUN TestGlobMatch/foo*_bar2263=== PAUSE TestGlobMatch/foo*_bar2264=== RUN TestGlobMatch/*bar_bar2265=== PAUSE TestGlobMatch/*bar_bar2266=== RUN TestGlobMatch/*bar_foobar2267=== PAUSE TestGlobMatch/*bar_foobar2268=== RUN TestGlobMatch/*bar_foo2269=== PAUSE TestGlobMatch/*bar_foo2270=== RUN TestGlobMatch/foo*bar_foobar2271=== PAUSE TestGlobMatch/foo*bar_foobar2272=== RUN TestGlobMatch/foo*bar_foo123bar2273=== PAUSE TestGlobMatch/foo*bar_foo123bar2274=== RUN TestGlobMatch/foo*bar_foobarbaz2275=== PAUSE TestGlobMatch/foo*bar_foobarbaz2276=== RUN TestGlobMatch/*/*_foo/bar2277=== PAUSE TestGlobMatch/*/*_foo/bar2278=== RUN TestGlobMatch/*/*_foo2279=== PAUSE TestGlobMatch/*/*_foo2280=== RUN TestGlobMatch/refs/heads/*_refs/heads/main2281=== PAUSE TestGlobMatch/refs/heads/*_refs/heads/main2282=== RUN TestGlobMatch/refs/heads/*_refs/tags/v1.02283=== PAUSE TestGlobMatch/refs/heads/*_refs/tags/v1.02284=== RUN TestGlobMatch/refs/*/main_refs/heads/main2285=== PAUSE TestGlobMatch/refs/*/main_refs/heads/main2286=== RUN TestGlobMatch/fo?_foo2287=== PAUSE TestGlobMatch/fo?_foo2288=== RUN TestGlobMatch/fo?_fo2289=== PAUSE TestGlobMatch/fo?_fo2290=== RUN TestGlobMatch/fo?_fooo2291=== PAUSE TestGlobMatch/fo?_fooo2292=== RUN TestGlobMatch/?oo_foo2293=== PAUSE TestGlobMatch/?oo_foo2294=== RUN TestGlobMatch/?oo_boo2295=== PAUSE TestGlobMatch/?oo_boo2296=== RUN TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2297=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2298=== RUN TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2299=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2300=== CONT TestGlobMatch/foo_foo2301=== CONT TestValidateToken_MultipleProviders2302=== CONT TestGlobMatch/*/*_foo/bar2303=== CONT TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2304=== CONT TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2305=== CONT TestGlobMatch/?oo_boo2306=== CONT TestGlobMatch/?oo_foo2307=== CONT TestGlobMatch/fo?_fooo2308=== CONT TestGlobMatch/fo?_fo2309=== CONT TestGlobMatch/fo?_foo2310=== CONT TestGlobMatch/refs/*/main_refs/heads/main2311=== CONT TestGlobMatch/refs/heads/*_refs/tags/v1.02312=== CONT TestGlobMatch/refs/heads/*_refs/heads/main2313=== CONT TestGlobMatch/*/*_foo2314=== CONT TestGlobMatch/*bar_bar2315=== CONT TestGlobMatch/foo*bar_foobarbaz2316=== CONT TestGlobMatch/foo*bar_foo123bar2317=== CONT TestGlobMatch/foo*bar_foobar2318=== CONT TestGlobMatch/*bar_foo2319=== CONT TestGlobMatch/*bar_foobar2320=== CONT TestGlobMatch/foo*_foo2321=== CONT TestGlobMatch/foo*_bar2322=== CONT TestGlobMatch/foo*_foobar2323=== CONT TestGlobMatch/*_2324=== CONT TestGlobMatch/*_anything2325=== CONT TestGlobMatch/foo_bar2326--- PASS: TestGlobMatch (0.00s)2327 --- PASS: TestGlobMatch/foo_foo (0.00s)2328 --- PASS: TestGlobMatch/*/*_foo/bar (0.00s)2329 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main (0.00s)2330 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main (0.00s)2331 --- PASS: TestGlobMatch/?oo_boo (0.00s)2332 --- PASS: TestGlobMatch/?oo_foo (0.00s)2333 --- PASS: TestGlobMatch/fo?_fooo (0.00s)2334 --- PASS: TestGlobMatch/fo?_fo (0.00s)2335 --- PASS: TestGlobMatch/fo?_foo (0.00s)2336 --- PASS: TestGlobMatch/refs/*/main_refs/heads/main (0.00s)2337 --- PASS: TestGlobMatch/refs/heads/*_refs/tags/v1.0 (0.00s)2338 --- PASS: TestGlobMatch/refs/heads/*_refs/heads/main (0.00s)2339 --- PASS: TestGlobMatch/*/*_foo (0.00s)2340 --- PASS: TestGlobMatch/*bar_bar (0.00s)2341 --- PASS: TestGlobMatch/foo*bar_foobarbaz (0.00s)2342 --- PASS: TestGlobMatch/foo*bar_foo123bar (0.00s)2343 --- PASS: TestGlobMatch/foo*bar_foobar (0.00s)2344 --- PASS: TestGlobMatch/*bar_foo (0.00s)2345 --- PASS: TestGlobMatch/*bar_foobar (0.00s)2346 --- PASS: TestGlobMatch/foo*_foo (0.00s)2347 --- PASS: TestGlobMatch/foo*_bar (0.00s)2348 --- PASS: TestGlobMatch/foo*_foobar (0.00s)2349 --- PASS: TestGlobMatch/*_ (0.00s)2350 --- PASS: TestGlobMatch/*_anything (0.00s)2351 --- PASS: TestGlobMatch/foo_bar (0.00s)2352=== CONT TestValidateToken_NoMatchingProvider2353=== CONT TestValidateToken_BoundSubjectMismatch2354=== CONT TestScopes_Rules2355=== CONT TestScopes_ConfigValidation2356--- PASS: TestScopes_ConfigValidation (0.00s)2357=== CONT TestScopes_LegacyProviderDefaultsToWrite23582026/10/11 05:57:59 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:60001/oidc23592026/10/11 05:57:59 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:60002/oidc23602026/10/11 05:57:59 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:60005/oidc23612026/10/11 05:57:59 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:60006/oidc2362--- PASS: TestPins_TopLevelShorthand (0.09s)2363--- PASS: TestValidateToken_ValidToken (0.08s)2364--- PASS: TestValidateToken_Expired (0.09s)2365--- PASS: TestValidateToken_BoundClaimsMismatch (0.09s)23662026/10/11 05:57:59 INFO OIDC provider initialized name=kubernetes issuer=https://127.0.0.1:6001123672026/10/11 05:57:59 INFO OIDC provider initialized name=kubernetes issuer=https://oidc.eks.invalid/id/ABC12323682026/10/11 05:57:59 http: TLS handshake error from 127.0.0.1:60012: read tcp 127.0.0.1:60004->127.0.0.1:60012: use of closed network connection2369--- PASS: TestNewValidator_KubernetesRequiresCA (0.09s)2370--- PASS: TestValidateToken_KubernetesServiceAccount (0.09s)2371--- PASS: TestValidateToken_KubernetesIssuerFromOwnToken (0.10s)23722026/10/11 05:57:59 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:60016/oidc23732026/10/11 05:57:59 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:60018/oidc2374--- PASS: TestValidateToken_WrongAudience (0.10s)2375--- PASS: TestScopes_Rules (0.09s)23762026/10/11 05:57:59 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:60020/oidc2377--- PASS: TestValidateToken_BoundSubjectMismatch (0.10s)23782026/10/11 05:57:59 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:60022/oidc23792026/10/11 05:57:59 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:60024/oidc2380--- PASS: TestPins_ReservedForMatchingRule (0.11s)2381--- PASS: TestScopes_LegacyProviderDefaultsToWrite (0.10s)23822026/10/11 05:57:59 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:60003/oidc2383--- PASS: TestValidateToken_NoMatchingProvider (0.13s)23842026/10/11 05:57:59 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:60028/oidc23852026/10/11 05:57:59 INFO OIDC provider initialized name=provider2 issuer=http://127.0.0.1:60029/oidc2386--- PASS: TestValidateToken_MultipleProviders (0.30s)2387PASS2388Running hook tests...2389=== RUN TestSendPathsEmpty2390=== PAUSE TestSendPathsEmpty2391=== RUN TestQueueEnqueueAndFetch2392=== PAUSE TestQueueEnqueueAndFetch2393=== RUN TestQueueDeduplication2394=== PAUSE TestQueueDeduplication2395=== RUN TestQueueRemove2396=== PAUSE TestQueueRemove2397=== RUN TestQueueFetchBatchLimit2398=== PAUSE TestQueueFetchBatchLimit2399=== RUN TestQueueRetryMovesToBack2400=== PAUSE TestQueueRetryMovesToBack2401=== RUN TestQueueFetchRemoveLifecycle2402=== PAUSE TestQueueFetchRemoveLifecycle2403=== RUN TestQueueConcurrentWriters2404=== PAUSE TestQueueConcurrentWriters2405=== RUN TestQueueRemoveLargeClosure2406=== PAUSE TestQueueRemoveLargeClosure2407=== RUN TestServerClientIntegration2408--- PASS: TestServerClientIntegration (0.00s)2409=== RUN TestServerQueueError24102026/10/11 05:57:59 ERROR Failed to queue paths error="permission denied" count=12411--- PASS: TestServerQueueError (0.00s)2412=== RUN TestGetListenerSocketActivation2413 server_test.go:146: systemd socket activation does not exist on darwin2414--- SKIP: TestGetListenerSocketActivation (0.00s)2415=== RUN TestDrainIsolatesPoisonPath2416=== PAUSE TestDrainIsolatesPoisonPath2417=== RUN TestRunNotBlockedByPoisonHead2418=== PAUSE TestRunNotBlockedByPoisonHead2419=== RUN TestDrainGivesUpWhenServerDown2420=== PAUSE TestDrainGivesUpWhenServerDown2421=== RUN TestFailedPathPrunedByLaterClosure2422=== PAUSE TestFailedPathPrunedByLaterClosure2423=== RUN TestWorkerUploadsAndRemoves2424=== PAUSE TestWorkerUploadsAndRemoves2425=== RUN TestWorkerSkipsGCdPaths2426=== PAUSE TestWorkerSkipsGCdPaths2427=== RUN TestWorkerPrunesClosureDeps2428=== PAUSE TestWorkerPrunesClosureDeps2429=== RUN TestDrainTimeout2430=== PAUSE TestDrainTimeout2431=== CONT TestSendPathsEmpty2432=== CONT TestDrainIsolatesPoisonPath2433--- PASS: TestSendPathsEmpty (0.00s)2434=== CONT TestQueueRemoveLargeClosure2435=== CONT TestQueueConcurrentWriters2436=== CONT TestQueueRemove2437=== CONT TestQueueDeduplication2438=== CONT TestQueueEnqueueAndFetch2439=== CONT TestWorkerUploadsAndRemoves2440=== CONT TestDrainTimeout2441=== CONT TestQueueFetchBatchLimit2442=== CONT TestWorkerPrunesClosureDeps2443=== CONT TestWorkerSkipsGCdPaths2444=== CONT TestQueueFetchRemoveLifecycle2445=== CONT TestQueueRetryMovesToBack2446=== CONT TestDrainGivesUpWhenServerDown2447=== CONT TestFailedPathPrunedByLaterClosure2448=== CONT TestRunNotBlockedByPoisonHead24492026/10/11 05:57:59 INFO Upload queue status pending=224502026/10/11 05:57:59 INFO Uploading batch count=124512026/10/11 05:57:59 INFO Upload queue status pending=224522026/10/11 05:57:59 WARN Store path no longer exists (garbage collected?), removing from queue path=/private/var/tb/3/scratch/7155a60ad86daa12/build/TestWorkerSkipsGCdPaths1536117442/002/nonexistent24532026/10/11 05:57:59 INFO Uploading batch count=224542026/10/11 05:57:59 INFO Upload queue status pending=22455--- PASS: TestQueueFetchBatchLimit (0.01s)24562026/10/11 05:57:59 INFO Uploading batch count=124572026/10/11 05:57:59 INFO Uploading batch count=424582026/10/11 05:57:59 ERROR Upload failed error="upload failed" count=424592026/10/11 05:57:59 INFO Uploading batch count=224602026/10/11 05:57:59 INFO Upload queue status pending=324612026/10/11 05:57:59 INFO Uploading batch count=124622026/10/11 05:57:59 ERROR Upload failed error="upload failed" count=124632026/10/11 05:57:59 INFO Uploading batch count=124642026/10/11 05:57:59 ERROR Upload failed error="upload failed" count=124652026/10/11 05:57:59 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/3/scratch/7155a60ad86daa12/build/TestDrainIsolatesPoisonPath201378276/002/bbb2466--- PASS: TestQueueRemove (0.02s)24672026/10/11 05:57:59 INFO Uploading batch count=22468--- PASS: TestQueueEnqueueAndFetch (0.02s)24692026/10/11 05:57:59 ERROR Upload failed error="upload failed" count=224702026/10/11 05:57:59 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/3/scratch/7155a60ad86daa12/build/TestDrainGivesUpWhenServerDown2266450680/002/a24712026/10/11 05:57:59 INFO Uploading batch count=12472--- PASS: TestQueueFetchRemoveLifecycle (0.01s)24732026/10/11 05:57:59 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/3/scratch/7155a60ad86daa12/build/TestDrainGivesUpWhenServerDown2266450680/002/b24742026/10/11 05:57:59 INFO Uploading batch count=12475--- PASS: TestQueueDeduplication (0.02s)24762026/10/11 05:57:59 INFO Uploading batch count=224772026/10/11 05:57:59 ERROR Upload failed error="upload failed" count=224782026/10/11 05:57:59 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/3/scratch/7155a60ad86daa12/build/TestDrainGivesUpWhenServerDown2266450680/002/c24792026/10/11 05:57:59 INFO Uploading batch count=124802026/10/11 05:57:59 ERROR Upload failed error="upload failed" count=124812026/10/11 05:57:59 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/3/scratch/7155a60ad86daa12/build/TestDrainGivesUpWhenServerDown2266450680/002/d2482--- PASS: TestQueueRetryMovesToBack (0.02s)24832026/10/11 05:57:59 INFO Uploading batch count=124842026/10/11 05:57:59 ERROR Upload failed error="upload failed" count=124852026/10/11 05:57:59 INFO Uploading batch count=224862026/10/11 05:57:59 ERROR Upload failed error="upload failed" count=224872026/10/11 05:57:59 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/3/scratch/7155a60ad86daa12/build/TestDrainGivesUpWhenServerDown2266450680/002/e24882026/10/11 05:57:59 INFO Uploading batch count=124892026/10/11 05:57:59 ERROR Upload failed error="upload failed" count=124902026/10/11 05:57:59 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/3/scratch/7155a60ad86daa12/build/TestDrainGivesUpWhenServerDown2266450680/002/f24912026/10/11 05:57:59 ERROR Drain finished with paths left in queue remaining=124922026/10/11 05:57:59 ERROR Drain finished with paths left in queue remaining=102493--- PASS: TestFailedPathPrunedByLaterClosure (0.02s)2494--- PASS: TestDrainIsolatesPoisonPath (0.02s)2495--- PASS: TestDrainGivesUpWhenServerDown (0.02s)2496--- PASS: TestWorkerSkipsGCdPaths (0.03s)2497--- PASS: TestWorkerPrunesClosureDeps (0.03s)2498--- PASS: TestWorkerUploadsAndRemoves (0.03s)2499--- PASS: TestQueueRemoveLargeClosure (0.05s)2500--- PASS: TestQueueConcurrentWriters (0.10s)25012026/10/11 05:57:59 ERROR Upload failed error="context deadline exceeded" count=225022026/10/11 05:57:59 ERROR Drain finished with paths left in queue remaining=42503--- PASS: TestDrainTimeout (0.22s)25042026/10/11 05:58:00 INFO Uploading batch count=125052026/10/11 05:58:00 INFO Uploading batch count=125062026/10/11 05:58:00 INFO Uploading batch count=125072026/10/11 05:58:00 ERROR Upload failed error="upload failed" count=125082026/10/11 05:58:00 INFO Uploading batch count=125092026/10/11 05:58:00 ERROR Upload failed error="upload failed" count=125102026/10/11 05:58:00 INFO Uploading batch count=125112026/10/11 05:58:00 ERROR Upload failed error="upload failed" count=125122026/10/11 05:58:00 INFO Uploading batch count=125132026/10/11 05:58:00 ERROR Upload failed error="upload failed" count=125142026/10/11 05:58:00 ERROR Drain finished with paths left in queue remaining=12515--- PASS: TestRunNotBlockedByPoisonHead (1.04s)2516PASS2517Running signing tests...2518=== RUN TestExternalSigner2519=== PAUSE TestExternalSigner2520=== RUN TestExternalSignerWrongPublicKey2521=== PAUSE TestExternalSignerWrongPublicKey2522=== RUN TestExternalSignerErrors2523=== PAUSE TestExternalSignerErrors2524=== RUN TestExternalSignerRestartsAfterCrash2525=== PAUSE TestExternalSignerRestartsAfterCrash2526=== RUN TestExternalSignerProgramErrorKeepsProcess2527=== PAUSE TestExternalSignerProgramErrorKeepsProcess2528=== RUN TestExternalSignerClose2529=== PAUSE TestExternalSignerClose2530=== RUN TestExternalSignerRejectsInvalidPublicKey2531=== PAUSE TestExternalSignerRejectsInvalidPublicKey2532=== RUN TestExternalSignerCancellation2533=== PAUSE TestExternalSignerCancellation2534=== RUN TestGenerateFingerprint2535=== PAUSE TestGenerateFingerprint2536=== RUN TestParseSigningKey2537=== PAUSE TestParseSigningKey2538=== RUN TestSign2539=== PAUSE TestSign2540=== RUN TestSignBatch2541=== PAUSE TestSignBatch2542=== RUN TestNilKeyPublicKey2543=== PAUSE TestNilKeyPublicKey2544=== RUN TestSignErrors2545=== PAUSE TestSignErrors2546=== CONT TestExternalSigner2547=== CONT TestExternalSignerCancellation2548=== CONT TestExternalSignerProgramErrorKeepsProcess2549=== CONT TestExternalSignerRejectsInvalidPublicKey2550=== RUN TestExternalSignerRejectsInvalidPublicKey/#002551=== CONT TestExternalSignerRestartsAfterCrash2552=== PAUSE TestExternalSignerRejectsInvalidPublicKey/#002553=== RUN TestExternalSignerRejectsInvalidPublicKey/no-colon2554=== PAUSE TestExternalSignerRejectsInvalidPublicKey/no-colon2555=== CONT TestExternalSignerErrors2556=== CONT TestSignBatch2557=== CONT TestSignErrors2558=== CONT TestNilKeyPublicKey2559--- PASS: TestNilKeyPublicKey (0.00s)2560=== CONT TestExternalSignerClose2561=== CONT TestParseSigningKey2562=== RUN TestParseSigningKey/valid_32-byte_key2563=== PAUSE TestParseSigningKey/valid_32-byte_key2564=== RUN TestParseSigningKey/valid_32-byte_key_with_different_name2565=== PAUSE TestParseSigningKey/valid_32-byte_key_with_different_name2566=== RUN TestParseSigningKey/no_colon2567=== PAUSE TestParseSigningKey/no_colon2568=== RUN TestParseSigningKey/empty_name2569=== PAUSE TestParseSigningKey/empty_name2570=== CONT TestSign2571=== CONT TestGenerateFingerprint2572=== RUN TestGenerateFingerprint/basic_with_references2573=== PAUSE TestGenerateFingerprint/basic_with_references2574=== RUN TestGenerateFingerprint/no_references2575=== CONT TestExternalSignerWrongPublicKey2576=== RUN TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2577=== PAUSE TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2578=== RUN TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2579=== PAUSE TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2580=== RUN TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2581=== PAUSE TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2582=== CONT TestExternalSignerRejectsInvalidPublicKey/#002583=== CONT TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2584=== CONT TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2585=== CONT TestExternalSignerRejectsInvalidPublicKey/no-colon2586=== PAUSE TestGenerateFingerprint/no_references2587=== RUN TestParseSigningKey/invalid_base642588=== CONT TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2589--- PASS: TestExternalSignerRejectsInvalidPublicKey (0.00s)2590 --- PASS: TestExternalSignerRejectsInvalidPublicKey/#00 (0.00s)2591 --- PASS: TestExternalSignerRejectsInvalidPublicKey/test-key:invalid! (0.00s)2592 --- PASS: TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA= (0.00s)2593 --- PASS: TestExternalSignerRejectsInvalidPublicKey/no-colon (0.00s)2594 --- PASS: TestExternalSignerRejectsInvalidPublicKey/test-key:YQ== (0.00s)2595=== RUN TestExternalSignerErrors/unrequested_key2596=== RUN TestGenerateFingerprint/unsorted_references_get_sorted2597=== PAUSE TestExternalSignerErrors/unrequested_key2598=== PAUSE TestParseSigningKey/invalid_base642599=== PAUSE TestGenerateFingerprint/unsorted_references_get_sorted2600=== RUN TestExternalSignerErrors/missing_signature_name2601=== RUN TestGenerateFingerprint/invalid_nar_hash_prefix2602=== PAUSE TestGenerateFingerprint/invalid_nar_hash_prefix2603=== RUN TestGenerateFingerprint/invalid_nar_hash_length2604=== PAUSE TestGenerateFingerprint/invalid_nar_hash_length2605=== RUN TestParseSigningKey/wrong_length2606=== RUN TestGenerateFingerprint/invalid_store_path_prefix2607=== PAUSE TestExternalSignerErrors/missing_signature_name2608=== PAUSE TestParseSigningKey/wrong_length2609=== PAUSE TestGenerateFingerprint/invalid_store_path_prefix2610=== RUN TestExternalSignerErrors/invalid_signature_base642611=== CONT TestParseSigningKey/valid_32-byte_key2612=== CONT TestParseSigningKey/wrong_length2613=== PAUSE TestExternalSignerErrors/invalid_signature_base642614=== CONT TestParseSigningKey/valid_32-byte_key_with_different_name2615=== RUN TestExternalSignerErrors/program_error2616=== RUN TestGenerateFingerprint/invalid_reference_prefix2617=== PAUSE TestGenerateFingerprint/invalid_reference_prefix2618=== CONT TestParseSigningKey/invalid_base642619=== CONT TestGenerateFingerprint/basic_with_references2620=== CONT TestParseSigningKey/empty_name2621=== CONT TestGenerateFingerprint/invalid_nar_hash_length2622=== CONT TestParseSigningKey/no_colon2623=== PAUSE TestExternalSignerErrors/program_error2624=== CONT TestGenerateFingerprint/invalid_nar_hash_prefix2625=== CONT TestGenerateFingerprint/unsorted_references_get_sorted2626=== CONT TestGenerateFingerprint/no_references2627=== CONT TestGenerateFingerprint/invalid_reference_prefix2628=== CONT TestGenerateFingerprint/invalid_store_path_prefix2629--- PASS: TestGenerateFingerprint (0.00s)2630 --- PASS: TestGenerateFingerprint/basic_with_references (0.00s)2631 --- PASS: TestGenerateFingerprint/invalid_nar_hash_length (0.00s)2632 --- PASS: TestGenerateFingerprint/invalid_nar_hash_prefix (0.00s)2633 --- PASS: TestGenerateFingerprint/unsorted_references_get_sorted (0.00s)2634 --- PASS: TestGenerateFingerprint/no_references (0.00s)2635 --- PASS: TestGenerateFingerprint/invalid_reference_prefix (0.00s)2636 --- PASS: TestGenerateFingerprint/invalid_store_path_prefix (0.00s)2637=== RUN TestExternalSignerErrors/exit_at_startup2638=== PAUSE TestExternalSignerErrors/exit_at_startup2639=== RUN TestExternalSignerErrors/exit_on_request2640=== PAUSE TestExternalSignerErrors/exit_on_request2641=== RUN TestExternalSignerErrors/invalid_JSON2642=== PAUSE TestExternalSignerErrors/invalid_JSON2643=== RUN TestExternalSignerErrors/null2644=== PAUSE TestExternalSignerErrors/null2645=== RUN TestExternalSignerErrors/missing_signatures2646=== PAUSE TestExternalSignerErrors/missing_signatures2647=== RUN TestExternalSignerErrors/too_few_signatures2648=== PAUSE TestExternalSignerErrors/too_few_signatures2649=== RUN TestExternalSignerErrors/wrong_id2650=== PAUSE TestExternalSignerErrors/wrong_id2651=== RUN TestExternalSignerErrors/wrong_signatures_shape2652=== PAUSE TestExternalSignerErrors/wrong_signatures_shape2653=== RUN TestExternalSignerErrors/wrong_signature_name2654=== PAUSE TestExternalSignerErrors/wrong_signature_name2655=== RUN TestExternalSignerErrors/wrong_shape2656=== PAUSE TestExternalSignerErrors/wrong_shape2657=== RUN TestExternalSignerErrors/null_signatures2658=== PAUSE TestExternalSignerErrors/null_signatures2659=== RUN TestExternalSignerErrors/wrong_signature_length2660=== PAUSE TestExternalSignerErrors/wrong_signature_length2661=== CONT TestExternalSignerErrors/unrequested_key2662=== CONT TestExternalSignerErrors/missing_signatures2663=== CONT TestExternalSignerErrors/exit_at_startup2664=== CONT TestExternalSignerErrors/wrong_signature_name2665=== CONT TestExternalSignerErrors/wrong_signatures_shape2666=== CONT TestExternalSignerErrors/program_error2667=== RUN TestSignErrors/nil_key2668=== PAUSE TestSignErrors/nil_key2669=== RUN TestSignErrors/nil_narinfo2670=== PAUSE TestSignErrors/nil_narinfo2671=== RUN TestSignErrors/invalid_narinfo2672=== PAUSE TestSignErrors/invalid_narinfo2673=== RUN TestSignErrors/canceled2674=== PAUSE TestSignErrors/canceled2675=== CONT TestSignErrors/nil_key2676=== CONT TestExternalSignerErrors/null2677=== CONT TestExternalSignerErrors/invalid_JSON2678=== CONT TestExternalSignerErrors/wrong_id2679=== CONT TestExternalSignerErrors/too_few_signatures2680--- PASS: TestSign (0.00s)2681=== CONT TestExternalSignerErrors/invalid_signature_base642682=== CONT TestSignErrors/canceled2683=== CONT TestSignErrors/invalid_narinfo2684=== CONT TestExternalSignerErrors/wrong_signature_length2685=== CONT TestSignErrors/nil_narinfo2686--- PASS: TestSignErrors (0.00s)2687 --- PASS: TestSignErrors/nil_key (0.00s)2688 --- PASS: TestSignErrors/canceled (0.00s)2689 --- PASS: TestSignErrors/invalid_narinfo (0.00s)2690 --- PASS: TestSignErrors/nil_narinfo (0.00s)2691--- PASS: TestParseSigningKey (0.00s)2692 --- PASS: TestParseSigningKey/wrong_length (0.00s)2693 --- PASS: TestParseSigningKey/invalid_base64 (0.00s)2694 --- PASS: TestParseSigningKey/empty_name (0.00s)2695 --- PASS: TestParseSigningKey/no_colon (0.00s)2696 --- PASS: TestParseSigningKey/valid_32-byte_key (0.00s)2697 --- PASS: TestParseSigningKey/valid_32-byte_key_with_different_name (0.00s)2698=== CONT TestExternalSignerErrors/exit_on_request2699=== CONT TestExternalSignerErrors/missing_signature_name2700=== CONT TestExternalSignerErrors/wrong_shape2701--- PASS: TestSignBatch (0.00s)2702=== CONT TestExternalSignerErrors/null_signatures2703--- PASS: TestExternalSignerCancellation (0.12s)2704--- PASS: TestExternalSignerProgramErrorKeepsProcess (0.17s)2705--- PASS: TestExternalSigner (0.25s)2706--- PASS: TestExternalSignerRestartsAfterCrash (0.33s)2707/private/var/tb/3/scratch/7155a60ad86daa12/build/TestExternalSignerRestartsAfterCrash1973473937/001/sign program: line 7: /private/var/tb/3/scratch/7155a60ad86daa12/build/TestExternalSignerRestartsAfterCrash1973473937/001/sign program.starts: No such file or directory2708--- PASS: TestExternalSignerClose (0.39s)2709--- PASS: TestExternalSignerWrongPublicKey (0.46s)2710--- PASS: TestExternalSignerErrors (0.00s)2711 --- PASS: TestExternalSignerErrors/missing_signatures (0.53s)2712 --- PASS: TestExternalSignerErrors/wrong_signature_length (0.60s)2713 --- PASS: TestExternalSignerErrors/null_signatures (0.67s)2714 --- PASS: TestExternalSignerErrors/exit_at_startup (0.75s)2715 --- PASS: TestExternalSignerErrors/invalid_signature_base64 (0.82s)2716 --- PASS: TestExternalSignerErrors/program_error (0.90s)2717 --- PASS: TestExternalSignerErrors/null (0.98s)2718 --- PASS: TestExternalSignerErrors/unrequested_key (1.05s)2719 --- PASS: TestExternalSignerErrors/wrong_signatures_shape (1.12s)2720 --- PASS: TestExternalSignerErrors/wrong_id (1.19s)2721 --- PASS: TestExternalSignerErrors/exit_on_request (1.27s)2722 --- PASS: TestExternalSignerErrors/too_few_signatures (1.34s)2723 --- PASS: TestExternalSignerErrors/wrong_shape (1.41s)2724 --- PASS: TestExternalSignerErrors/invalid_JSON (1.49s)2725 --- PASS: TestExternalSignerErrors/missing_signature_name (1.56s)2726 --- PASS: TestExternalSignerErrors/wrong_signature_name (1.64s)2727PASS2728Running OpenBao signer tests...2729=== RUN TestSign2730=== PAUSE TestSign2731=== RUN TestSignErrors2732=== PAUSE TestSignErrors2733=== RUN TestServe2734=== PAUSE TestServe2735=== RUN TestServeRejectsGarbage2736=== PAUSE TestServeRejectsGarbage2737=== CONT TestSign2738=== CONT TestServe2739=== CONT TestSignErrors2740=== RUN TestSignErrors/http_error2741=== PAUSE TestSignErrors/http_error2742=== RUN TestSignErrors/invalid_json2743=== PAUSE TestSignErrors/invalid_json2744=== CONT TestServeRejectsGarbage2745=== RUN TestSignErrors/no_prefix2746=== PAUSE TestSignErrors/no_prefix2747=== RUN TestSignErrors/invalid_base642748=== PAUSE TestSignErrors/invalid_base642749--- PASS: TestServeRejectsGarbage (0.00s)2750=== CONT TestSignErrors/http_error2751=== CONT TestSignErrors/invalid_base642752=== CONT TestSignErrors/no_prefix2753--- PASS: TestServe (0.00s)2754=== CONT TestSignErrors/invalid_json2755--- PASS: TestSign (0.00s)2756--- PASS: TestSignErrors (0.00s)2757 --- PASS: TestSignErrors/invalid_base64 (0.00s)2758 --- PASS: TestSignErrors/http_error (0.00s)2759 --- PASS: TestSignErrors/invalid_json (0.00s)2760 --- PASS: TestSignErrors/no_prefix (0.00s)2761PASS