niks3-go-unit-tests
checks.aarch64-darwin.go-unit-tests
· build #419
· 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.20s)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 TestStreamPushStopsWhenCanceled115=== CONT TestRateLimiterFeedback_400DoesNotCountAsSuccess116=== CONT TestScriptTokenEmptyCommand117=== CONT TestDoWithRetry_BodyReplayedViaGetBody118=== CONT TestClientSignaturesByStorePath119=== CONT TestStreamPushReportsSignatures120=== CONT TestStreamPushGivesUpOnDeadServer121=== CONT TestStreamPushIsolatesFailures122=== CONT TestStreamPushBatchesUnderLoad1232026/10/20 08:18:37 ERROR Upload failed error="connection refused" count=201242026/10/20 08:18:37 ERROR Server seems unavailable, giving up on batch untried=17125=== CONT TestStreamPushReportsEveryPath126=== CONT TestShellSplitErrors1272026/10/20 08:18:37 WARN Rate limiter enabled after throttle name=server-test rate=5128=== CONT TestGetStorePathHash129=== RUN TestGetStorePathHash/valid_store_path130=== PAUSE TestGetStorePathHash/valid_store_path131=== RUN TestGetStorePathHash/basename_without_hyphen_should_error132=== PAUSE TestGetStorePathHash/basename_without_hyphen_should_error133=== RUN TestGetStorePathHash/hash_with_invalid_characters_should_error134=== PAUSE TestGetStorePathHash/hash_with_invalid_characters_should_error135=== RUN TestGetStorePathHash/hash_with_wrong_length_should_error136=== PAUSE TestGetStorePathHash/hash_with_wrong_length_should_error137=== CONT TestShellSplit1382026/10/20 08:18:37 ERROR Upload failed error="bad path" count=3139=== CONT TestStaticToken140=== CONT TestFileTokenMissing141=== CONT TestDoWithRetry_FinalResponseBodyReadable142=== CONT TestFileTokenReadsAndCaches143=== CONT TestRetryTimeoutOutlastsMaxRetries144=== CONT TestDumpPathWriterError145=== CONT TestResolveStorePath146=== CONT TestRegisterUploadedObject_BoundedAgainstSilentServer147=== CONT TestFileTokenEmpty148=== CONT TestScriptTokenScriptFails149=== CONT TestScriptTokenBadJSON150=== CONT TestScriptTokenEmptyToken151--- PASS: TestScriptTokenEmptyCommand (0.00s)152--- PASS: TestStreamPushStopsWhenCanceled (0.00s)153--- PASS: TestClientSignaturesByStorePath (0.00s)154--- PASS: TestShellSplitErrors (0.00s)155--- PASS: TestStaticToken (0.00s)156--- PASS: TestShellSplit (0.00s)157=== CONT TestScriptTokenCachesUntilRefresh158=== CONT TestStreamPushReportsSkippedPaths159=== CONT TestScriptTokenNoExpiryRerunsEveryCall1602026/10/20 08:18:37 ERROR Upload failed error=boom count=1161=== CONT TestParsePathInfoJSONMultiplePaths162=== RUN TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths163=== PAUSE TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths164=== RUN TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths165=== PAUSE TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths166=== CONT TestParsePathInfoJSON167=== RUN TestParsePathInfoJSON/Nix_format168=== PAUSE TestParsePathInfoJSON/Nix_format169=== RUN TestParsePathInfoJSON/Lix_format170=== CONT TestDumpPathSingleFile171=== PAUSE TestParsePathInfoJSON/Lix_format172=== CONT TestSupersededNARStillUploadsListing173=== CONT TestStreamPushRequestLine174=== CONT TestPathInfoHashCompatibility175--- PASS: TestFileTokenReadsAndCaches (0.00s)176=== CONT TestConvertHashToNix32177=== CONT TestPathInfoCACompatibility178=== CONT TestRateLimiterFeedback179--- PASS: TestStreamPushGivesUpOnDeadServer (0.00s)180--- PASS: TestStreamPushReportsSkippedPaths (0.00s)181--- PASS: TestStreamPushReportsSignatures (0.00s)182--- PASS: TestStreamPushReportsEveryPath (0.00s)183--- PASS: TestStreamPushIsolatesFailures (0.00s)1842026/10/20 08:18:37 WARN Rate limiter enabled after throttle name=server-test rate=51852026/10/20 08:18:37 WARN Request returned retryable status, retrying attempt=1 backoff=1ms status=502 url=http://127.0.0.1:526451862026/10/20 08:18:37 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:526441872026/10/20 08:18:37 WARN Request returned retryable status, retrying attempt=2 backoff=1ms status=502 url=http://127.0.0.1:526451882026/10/20 08:18:37 ERROR Upload failed error=boom count=1189=== RUN TestParsePathInfoJSON/empty_input190=== PAUSE TestParsePathInfoJSON/empty_input191=== RUN TestSupersededNARStillUploadsListing/small_NAR192=== PAUSE TestSupersededNARStillUploadsListing/small_NAR193=== RUN TestSupersededNARStillUploadsListing/dump_cut_short194=== PAUSE TestSupersededNARStillUploadsListing/dump_cut_short195=== RUN TestSupersededNARStillUploadsListing/listing_upload_fails196=== PAUSE TestSupersededNARStillUploadsListing/listing_upload_fails197=== CONT TestDumpPathMatchesNix198=== RUN TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)199=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)200=== RUN TestPathInfoHashCompatibility/old_string_format_with_colon201=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_colon202=== RUN TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI203=== PAUSE TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI204=== RUN TestPathInfoHashCompatibility/new_structured_format_with_sha5122052026/10/20 08:18:37 WARN Rate limiter enabled after throttle name=server-test rate=52062026/10/20 08:18:37 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:52643207=== RUN TestPathInfoCACompatibility/null_ca_field208=== RUN TestConvertHashToNix32/SRI_format_to_Nix32209=== PAUSE TestConvertHashToNix32/SRI_format_to_Nix32210=== RUN TestConvertHashToNix32/already_Nix32_format211--- PASS: TestScriptTokenScriptFails (0.01s)212=== CONT TestUploadMultipart_PartsInParallel213=== PAUSE TestPathInfoHashCompatibility/new_structured_format_with_sha512214--- PASS: TestResolveStorePath (0.01s)215=== CONT TestFilterOversizedClosures216=== CONT TestRunGarbageCollection_NotFoundAfterLocalRun217--- PASS: TestFileTokenMissing (0.02s)218=== CONT TestUploadMultipart_SupersededByPeer219--- PASS: TestDoServerRequestAttachesToken (0.02s)220=== PAUSE TestPathInfoCACompatibility/null_ca_field221=== CONT TestCaseHackSuffix2222026/10/20 08:18:37 WARN Rate limiter backed off name=server-test rate=52232026/10/20 08:18:37 WARN Request returned retryable status, retrying attempt=2 backoff=0s status=503 url=http://127.0.0.1:526432242026/10/20 08:18:37 WARN Rate limiter backed off name=server-test rate=5225--- PASS: TestDoWithRetry_FinalResponseBodyReadable (0.02s)226=== CONT TestPartSizeForNAR227--- PASS: TestFileTokenEmpty (0.02s)228=== CONT TestEncodeNixBase32WithRealHash229=== PAUSE TestConvertHashToNix32/already_Nix32_format230--- PASS: TestEncodeNixBase32WithRealHash (0.00s)231=== CONT TestRunGarbageCollection_FinishedOnAnotherReplica232=== RUN TestRateLimiterFeedback/429_enables_limiter233=== PAUSE TestRateLimiterFeedback/429_enables_limiter234=== RUN TestRateLimiterFeedback/503_enables_limiter235=== PAUSE TestRateLimiterFeedback/503_enables_limiter236=== RUN TestRateLimiterFeedback/200_does_not_enable_limiter237=== PAUSE TestRateLimiterFeedback/200_does_not_enable_limiter238=== RUN TestRateLimiterFeedback/400_does_not_enable_limiter239=== PAUSE TestRateLimiterFeedback/400_does_not_enable_limiter240=== RUN TestParsePathInfoJSON/whitespace_only241=== PAUSE TestParsePathInfoJSON/whitespace_only242=== RUN TestParsePathInfoJSON/invalid_JSON243=== PAUSE TestParsePathInfoJSON/invalid_JSON244=== CONT TestEncodeNixBase32245=== RUN TestEncodeNixBase32/test_string_hash246=== PAUSE TestEncodeNixBase32/test_string_hash247=== CONT TestUploadBuildLog_FileBodyReplayedOnRetry248=== RUN TestPathInfoCACompatibility/old_string_format_-_text249=== PAUSE TestPathInfoCACompatibility/old_string_format_-_text250=== RUN TestPathInfoCACompatibility/old_string_format_-_fixed_recursive251=== PAUSE TestPathInfoCACompatibility/old_string_format_-_fixed_recursive252=== RUN TestPathInfoCACompatibility/new_structured_format_-_text253=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_text254=== RUN TestPathInfoCACompatibility/new_structured_format_-_nar_method255=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_nar_method256=== RUN TestPartSizeForNAR/zero_stays_at_minimum257=== PAUSE TestPartSizeForNAR/zero_stays_at_minimum258=== RUN TestPartSizeForNAR/small_stays_at_minimum259=== PAUSE TestPartSizeForNAR/small_stays_at_minimum260=== RUN TestPartSizeForNAR/80_GiB_fits_at_minimum261=== PAUSE TestPartSizeForNAR/80_GiB_fits_at_minimum262=== RUN TestPartSizeForNAR/115_GiB_needs_larger_parts263=== PAUSE TestPartSizeForNAR/115_GiB_needs_larger_parts264=== RUN TestPartSizeForNAR/1_TiB265=== PAUSE TestPartSizeForNAR/1_TiB266=== RUN TestPartSizeForNAR/5_TiB_S3_max_object267=== PAUSE TestPartSizeForNAR/5_TiB_S3_max_object268=== RUN TestPartSizeForNAR/capped_at_5_GiB269=== PAUSE TestPartSizeForNAR/capped_at_5_GiB270=== CONT TestSetClientTLSDoesNotMutateDefaultTransport271=== CONT TestSetClientTLSErrors272--- PASS: TestScriptTokenBadJSON (0.02s)273=== CONT TestSetClientTLS274--- PASS: TestDoWithRetry_BodyReplayedViaGetBody (0.02s)275=== CONT TestRegisterUploadedObjectReusesConnections2762026/10/20 08:18:37 INFO Garbage collection started2772026/10/20 08:18:37 INFO Garbage collection started278=== RUN TestFilterOversizedClosures/no_limit_keeps_everything279=== PAUSE TestFilterOversizedClosures/no_limit_keeps_everything280=== RUN TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped281=== PAUSE TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped282=== RUN TestFilterOversizedClosures/all_closures_skipped283=== PAUSE TestFilterOversizedClosures/all_closures_skipped284=== RUN TestUploadMultipart_SupersededByPeer/exists285=== PAUSE TestUploadMultipart_SupersededByPeer/exists286=== RUN TestUploadMultipart_SupersededByPeer/missing287=== PAUSE TestUploadMultipart_SupersededByPeer/missing288=== CONT TestGetStorePathHash/valid_store_path289=== CONT TestGetStorePathHash/hash_with_wrong_length_should_error290=== CONT TestGetStorePathHash/basename_without_hyphen_should_error291=== CONT TestGetStorePathHash/hash_with_invalid_characters_should_error292--- PASS: TestGetStorePathHash (0.00s)293 --- PASS: TestGetStorePathHash/valid_store_path (0.00s)294 --- PASS: TestGetStorePathHash/hash_with_wrong_length_should_error (0.00s)295 --- PASS: TestGetStorePathHash/basename_without_hyphen_should_error (0.00s)296 --- PASS: TestGetStorePathHash/hash_with_invalid_characters_should_error (0.00s)297=== CONT TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths298=== CONT TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths299=== CONT TestSupersededNARStillUploadsListing/small_NAR300=== RUN TestSetClientTLSErrors/missing_cert_file301=== PAUSE TestSetClientTLSErrors/missing_cert_file302=== RUN TestSetClientTLSErrors/missing_key_file303=== PAUSE TestSetClientTLSErrors/missing_key_file304=== RUN TestSetClientTLSErrors/missing_ca_file305=== PAUSE TestSetClientTLSErrors/missing_ca_file306=== RUN TestSetClientTLSErrors/invalid_ca_file307=== PAUSE TestSetClientTLSErrors/invalid_ca_file308--- PASS: TestScriptTokenEmptyToken (0.02s)309=== RUN TestConvertHashToNix32/invalid_format310=== CONT TestSupersededNARStillUploadsListing/listing_upload_fails311=== PAUSE TestConvertHashToNix32/invalid_format312=== CONT TestSupersededNARStillUploadsListing/dump_cut_short313=== CONT TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)314=== CONT TestPathInfoHashCompatibility/new_structured_format_with_sha512315=== RUN TestSetClientTLS/rejects_connection_without_client_cert316=== PAUSE TestSetClientTLS/rejects_connection_without_client_cert317=== RUN TestSetClientTLS/succeeds_with_client_cert_and_CA318=== RUN TestEncodeNixBase32/empty_input319=== PAUSE TestEncodeNixBase32/empty_input320=== CONT TestPathInfoHashCompatibility/old_string_format_with_colon321=== CONT TestRateLimiterFeedback/429_enables_limiter3222026/10/20 08:18:37 WARN Rate limiter enabled after throttle name=server-test rate=53232026/10/20 08:18:37 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=429 url=http://127.0.0.1:527163242026/10/20 08:18:37 WARN Rate limiter enabled after throttle name=s3-test rate=53252026/10/20 08:18:37 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:526653262026/10/20 08:18:37 WARN Rate limiter backed off name=server-test rate=5327=== CONT TestParsePathInfoJSON/Nix_format328=== CONT TestRateLimiterFeedback/400_does_not_enable_limiter329--- PASS: TestRunGarbageCollection_NotFoundAfterLocalRun (0.01s)330=== CONT TestRateLimiterFeedback/200_does_not_enable_limiter3312026/10/20 08:18:37 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=0332--- PASS: TestUploadBuildLog_FileBodyReplayedOnRetry (0.01s)333=== CONT TestRateLimiterFeedback/503_enables_limiter334--- PASS: TestParsePathInfoJSONMultiplePaths (0.00s)335 --- PASS: TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths (0.00s)336 --- PASS: TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths (0.00s)337=== CONT TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI3382026/10/20 08:18:37 WARN Request returned retryable status, retrying attempt=1 backoff=1ms status=502 url=http://127.0.0.1:52645339=== CONT TestParsePathInfoJSON/invalid_JSON340=== CONT TestParsePathInfoJSON/whitespace_only341=== CONT TestParsePathInfoJSON/empty_input342=== CONT TestParsePathInfoJSON/Lix_format343--- PASS: TestParsePathInfoJSON (0.02s)344 --- PASS: TestParsePathInfoJSON/Nix_format (0.00s)345 --- PASS: TestParsePathInfoJSON/invalid_JSON (0.00s)346 --- PASS: TestParsePathInfoJSON/whitespace_only (0.00s)347 --- PASS: TestParsePathInfoJSON/empty_input (0.00s)348 --- PASS: TestParsePathInfoJSON/Lix_format (0.00s)349=== CONT TestPathInfoCACompatibility/null_ca_field350=== CONT TestPartSizeForNAR/zero_stays_at_minimum351=== CONT TestPartSizeForNAR/1_TiB352=== CONT TestPartSizeForNAR/capped_at_5_GiB353=== CONT TestPartSizeForNAR/5_TiB_S3_max_object354=== CONT TestPartSizeForNAR/80_GiB_fits_at_minimum355=== CONT TestPartSizeForNAR/115_GiB_needs_larger_parts356=== CONT TestPartSizeForNAR/small_stays_at_minimum357--- PASS: TestPartSizeForNAR (0.00s)358 --- PASS: TestPartSizeForNAR/zero_stays_at_minimum (0.00s)359 --- PASS: TestPartSizeForNAR/1_TiB (0.00s)360 --- PASS: TestPartSizeForNAR/capped_at_5_GiB (0.00s)361 --- PASS: TestPartSizeForNAR/5_TiB_S3_max_object (0.00s)362 --- PASS: TestPartSizeForNAR/80_GiB_fits_at_minimum (0.00s)363 --- PASS: TestPartSizeForNAR/115_GiB_needs_larger_parts (0.00s)364 --- PASS: TestPartSizeForNAR/small_stays_at_minimum (0.00s)365=== CONT TestFilterOversizedClosures/no_limit_keeps_everything366=== CONT TestUploadMultipart_SupersededByPeer/exists367=== CONT TestFilterOversizedClosures/all_closures_skipped368=== PAUSE TestSetClientTLS/succeeds_with_client_cert_and_CA369=== RUN TestSetClientTLS/preserves_debug_logging_transport370=== PAUSE TestSetClientTLS/preserves_debug_logging_transport3712026/10/20 08:18:37 WARN Rate limiter enabled after throttle name=server-test rate=53722026/10/20 08:18:37 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:527353732026/10/20 08:18:37 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=503742026/10/20 08:18:37 INFO Uploading abc-hello (1.0GB)3752026/10/20 08:18:37 INFO Uploading abc-hello (1.0GB)376=== CONT TestUploadMultipart_SupersededByPeer/missing377=== CONT TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped3782026/10/20 08:18:37 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=2000379=== CONT TestPathInfoCACompatibility/new_structured_format_-_text380=== CONT TestPathInfoCACompatibility/old_string_format_-_fixed_recursive381=== CONT TestPathInfoCACompatibility/old_string_format_-_text382=== CONT TestSetClientTLSErrors/invalid_ca_file383=== CONT TestSetClientTLSErrors/missing_ca_file384=== CONT TestSetClientTLSErrors/missing_cert_file385=== CONT TestSetClientTLSErrors/missing_key_file386--- PASS: TestPathInfoHashCompatibility (0.01s)387 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) (0.00s)388 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_colon (0.00s)389 --- PASS: TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI (0.00s)390 --- PASS: TestPathInfoHashCompatibility/new_structured_format_with_sha512 (0.01s)391=== CONT TestConvertHashToNix32/SRI_format_to_Nix32392=== CONT TestConvertHashToNix32/already_Nix32_format393=== CONT TestEncodeNixBase32/test_string_hash394=== CONT TestEncodeNixBase32/empty_input395=== CONT TestSetClientTLS/rejects_connection_without_client_cert396=== CONT TestPathInfoCACompatibility/new_structured_format_-_nar_method397=== CONT TestSetClientTLS/preserves_debug_logging_transport3982026/10/20 08:18:37 WARN Garbage collection finished on another replica. Its statistics are not available here399--- PASS: TestFilterOversizedClosures (0.01s)400 --- PASS: TestFilterOversizedClosures/no_limit_keeps_everything (0.00s)401 --- PASS: TestFilterOversizedClosures/all_closures_skipped (0.00s)402 --- PASS: TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped (0.00s)403--- PASS: TestSetClientTLSDoesNotMutateDefaultTransport (0.01s)404=== CONT TestConvertHashToNix32/invalid_format405--- PASS: TestRunGarbageCollection_FinishedOnAnotherReplica (0.01s)406=== CONT TestSetClientTLS/succeeds_with_client_cert_and_CA407--- PASS: TestConvertHashToNix32 (0.02s)408 --- PASS: TestConvertHashToNix32/SRI_format_to_Nix32 (0.00s)409 --- PASS: TestConvertHashToNix32/already_Nix32_format (0.00s)410 --- PASS: TestConvertHashToNix32/invalid_format (0.00s)411--- PASS: TestEncodeNixBase32 (0.00s)412 --- PASS: TestEncodeNixBase32/test_string_hash (0.00s)413 --- PASS: TestEncodeNixBase32/empty_input (0.00s)4142026/10/20 08:18:37 WARN Request returned retryable status, retrying attempt=2 backoff=1ms status=502 url=http://127.0.0.1:526454152026/10/20 08:18:37 WARN Rate limiter backed off name=server-test rate=5416--- PASS: TestRateLimiterFeedback (0.01s)417 --- PASS: TestRateLimiterFeedback/429_enables_limiter (0.00s)418 --- PASS: TestRateLimiterFeedback/400_does_not_enable_limiter (0.00s)419 --- PASS: TestRateLimiterFeedback/200_does_not_enable_limiter (0.00s)420 --- PASS: TestRateLimiterFeedback/503_enables_limiter (0.01s)421--- PASS: TestUploadMultipart_SupersededByPeer (0.01s)422 --- PASS: TestUploadMultipart_SupersededByPeer/exists (0.00s)423 --- PASS: TestUploadMultipart_SupersededByPeer/missing (0.00s)424--- PASS: TestPathInfoCACompatibility (0.01s)425 --- PASS: TestPathInfoCACompatibility/null_ca_field (0.00s)426 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_text (0.00s)427 --- PASS: TestPathInfoCACompatibility/old_string_format_-_fixed_recursive (0.00s)428 --- PASS: TestPathInfoCACompatibility/old_string_format_-_text (0.00s)429 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_nar_method (0.00s)430--- PASS: TestSetClientTLSErrors (0.00s)431 --- PASS: TestSetClientTLSErrors/missing_cert_file (0.00s)432 --- PASS: TestSetClientTLSErrors/missing_key_file (0.00s)433 --- PASS: TestSetClientTLSErrors/missing_ca_file (0.00s)434 --- PASS: TestSetClientTLSErrors/invalid_ca_file (0.00s)4352026/10/20 08:18:37 WARN Request returned retryable status, retrying attempt=3 backoff=1ms status=502 url=http://127.0.0.1:52645436--- PASS: TestStreamPushRequestLine (0.03s)4372026/10/20 08:18:37 WARN Request returned retryable status, retrying attempt=4 backoff=1ms status=502 url=http://127.0.0.1:526454382026/10/20 08:18:37 WARN Request returned retryable status, retrying attempt=5 backoff=1ms status=502 url=http://127.0.0.1:526454392026/10/20 08:18:37 WARN Request returned retryable status, retrying attempt=6 backoff=1ms status=502 url=http://127.0.0.1:526454402026/10/20 08:18:37 WARN Request returned retryable status, retrying attempt=7 backoff=1ms status=502 url=http://127.0.0.1:526454412026/10/20 08:18:37 WARN Request returned retryable status, retrying attempt=8 backoff=1ms status=502 url=http://127.0.0.1:526454422026/10/20 08:18:37 WARN Request returned retryable status, retrying attempt=9 backoff=1ms status=502 url=http://127.0.0.1:526454432026/10/20 08:18:37 WARN Request returned retryable status, retrying attempt=10 backoff=1ms status=502 url=http://127.0.0.1:526454442026/10/20 08:18:37 WARN Request returned retryable status, retrying attempt=11 backoff=1ms status=502 url=http://127.0.0.1:526454452026/10/20 08:18:37 WARN Request returned retryable status, retrying attempt=12 backoff=1ms status=502 url=http://127.0.0.1:526454462026/10/20 08:18:37 WARN Request returned retryable status, retrying attempt=13 backoff=1ms status=502 url=http://127.0.0.1:526454472026/10/20 08:18:37 WARN Request returned retryable status, retrying attempt=14 backoff=1ms status=502 url=http://127.0.0.1:526454482026/10/20 08:18:37 WARN Request returned retryable status, retrying attempt=15 backoff=1ms status=502 url=http://127.0.0.1:52645449--- PASS: TestRegisterUploadedObjectReusesConnections (0.05s)4502026/10/20 08:18:37 WARN Request returned retryable status, retrying attempt=16 backoff=1ms status=502 url=http://127.0.0.1:526454512026/10/20 08:18:37 WARN Request returned retryable status, retrying attempt=17 backoff=1ms status=502 url=http://127.0.0.1:52645452--- PASS: TestRetryTimeoutOutlastsMaxRetries (0.08s)4532026/10/20 08:18:37 http: TLS handshake error from 127.0.0.1:52747: read tcp 127.0.0.1:52707->127.0.0.1:52747: use of closed network connection454--- PASS: TestSetClientTLS (0.01s)455 --- PASS: TestSetClientTLS/preserves_debug_logging_transport (0.01s)456 --- PASS: TestSetClientTLS/succeeds_with_client_cert_and_CA (0.01s)457 --- PASS: TestSetClientTLS/rejects_connection_without_client_cert (0.05s)458--- PASS: TestScriptTokenCachesUntilRefresh (0.09s)459--- PASS: TestStreamPushBatchesUnderLoad (0.10s)4602026/10/20 08:18:37 INFO Uploading abc-hello (1.0GB)461--- PASS: TestScriptTokenNoExpiryRerunsEveryCall (0.16s)4622026/10/20 08:18:37 WARN Request failed, retrying attempt=1 backoff=100ms error="Put \"http://127.0.0.1:52703/part/2\": uploading part 1: server returned 404: no such upload\n" url=http://127.0.0.1:52703/part/2463--- PASS: TestDumpPathSingleFile (0.18s)4642026/10/20 08:18:37 ERROR Failed to close zstd encoder error="io: read/write on closed pipe"465--- PASS: TestDumpPathWriterError (0.21s)466--- PASS: TestCaseHackSuffix (0.19s)467--- PASS: TestDumpPathMatchesNix (0.34s)468--- PASS: TestUploadMultipart_PartsInParallel (0.65s)469--- PASS: TestSupersededNARStillUploadsListing (0.01s)470 --- PASS: TestSupersededNARStillUploadsListing/listing_upload_fails (0.01s)471 --- PASS: TestSupersededNARStillUploadsListing/small_NAR (0.02s)472 --- PASS: TestSupersededNARStillUploadsListing/dump_cut_short (0.65s)473--- PASS: TestRateLimiterFeedback_400DoesNotCountAsSuccess (1.00s)4742026/10/20 08:18:38 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:52646/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:52646/api/uploads/complete4752026/10/20 08:18:38 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:52646/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:52646/api/uploads/complete4762026/10/20 08:18:38 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"4772026/10/20 08:18:38 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"4782026/10/20 08:18:38 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:52646/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:52646/api/uploads/complete4792026/10/20 08:18:38 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"480--- PASS: TestRegisterUploadedObject_BoundedAgainstSilentServer (1.00s)481PASS482Running server tests...483The files belonging to this database system will be owned by user "_tribuchetbld1".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/1/scratch/c8b5f9203adb9a1c/build/postgres1131874824/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/1/scratch/c8b5f9203adb9a1c/build/postgres1131874824/data -l logfile start5095102026-10-20 08:18:40.980 UTC [88923] LOG: starting PostgreSQL 18.6 on aarch64-apple-darwin25.6.0, compiled by clang version 21.1.8, 64-bit5112026-10-20 08:18:40.980 UTC [88923] LOG: listening on Unix socket "/private/var/tb/1/scratch/c8b5f9203adb9a1c/build/postgres1131874824/.s.PGSQL.5432"5122026-10-20 08:18:40.990 UTC [88936] LOG: database system was shut down at 2026-10-20 08:18:40 UTC5132026-10-20 08:18:40.992 UTC [88923] LOG: database system is ready to accept connections514/private/var/tb/1/scratch/c8b5f9203adb9a1c/build/postgres1131874824:5432 - accepting connections515{"timestamp":"2026-10-20T08:18:43.355693Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"2d021d4e-41a3-4489-9e79-4ae6c66d40ba","trace_id":"unknown","span_id":"unknown","peer_addr":"127.0.0.1","method":"GET","uri":"/health/ready","status_code":503,"suppressed_errors":0,"duration_ms":0,"result":"server_error","target":"rustfs::server::http","filename":"rustfs/src/server/layer.rs","line_number":501,"threadName":"rustfs-worker","threadId":"ThreadId(8)"}516{"timestamp":"2026-10-20T08:18:43.459901Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"fb83e5cb-bccb-4faf-8eac-d3baa92b8f14","trace_id":"unknown","span_id":"unknown","peer_addr":"127.0.0.1","method":"GET","uri":"/health/ready","status_code":503,"suppressed_errors":0,"duration_ms":0,"result":"server_error","target":"rustfs::server::http","filename":"rustfs/src/server/layer.rs","line_number":501,"threadName":"rustfs-worker","threadId":"ThreadId(8)"}517{"timestamp":"2026-10-20T08:18:43.561401Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"abb74af3-2e94-4cee-aebb-cf5028a9558d","trace_id":"unknown","span_id":"unknown","peer_addr":"127.0.0.1","method":"GET","uri":"/health/ready","status_code":503,"suppressed_errors":0,"duration_ms":0,"result":"server_error","target":"rustfs::server::http","filename":"rustfs/src/server/layer.rs","line_number":501,"threadName":"rustfs-worker","threadId":"ThreadId(6)"}518{"timestamp":"2026-10-20T08:18:43.664653Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"b9332284-649e-4799-9f8b-8a7bbaeb63fa","trace_id":"unknown","span_id":"unknown","peer_addr":"127.0.0.1","method":"GET","uri":"/health/ready","status_code":503,"suppressed_errors":0,"duration_ms":0,"result":"server_error","target":"rustfs::server::http","filename":"rustfs/src/server/layer.rs","line_number":501,"threadName":"rustfs-worker","threadId":"ThreadId(10)"}519=== RUN TestService_AuthMiddleware520=== PAUSE TestService_AuthMiddleware521=== RUN TestService_AuthMiddleware_MTLSProxyHeader522=== PAUSE TestService_AuthMiddleware_MTLSProxyHeader523=== RUN TestService_AuthMiddleware_MTLSBoundSubjects524=== PAUSE TestService_AuthMiddleware_MTLSBoundSubjects525=== RUN TestService_ReadAuthMiddleware526=== PAUSE TestService_ReadAuthMiddleware527=== RUN TestService_AuthMiddleware_OIDC528=== PAUSE TestService_AuthMiddleware_OIDC529=== RUN TestService_RequireScope_OIDC530=== PAUSE TestService_RequireScope_OIDC531=== RUN TestService_ReadScope_PublicByDefault532=== PAUSE TestService_ReadScope_PublicByDefault533=== RUN TestCacheConfigHandler534=== PAUSE TestCacheConfigHandler535=== RUN TestCacheStatsHandler536=== PAUSE TestCacheStatsHandler537=== RUN TestClientCADerivations538=== PAUSE TestClientCADerivations539=== RUN TestClientErrorHandling540=== PAUSE TestClientErrorHandling541=== RUN TestClientIntegration542=== PAUSE TestClientIntegration543=== RUN TestClientMultipleUploads544=== PAUSE TestClientMultipleUploads545=== RUN TestClientWithDependencies546=== PAUSE TestClientWithDependencies547=== RUN TestClientSharedPathCommittedMidPush548=== PAUSE TestClientSharedPathCommittedMidPush549=== RUN TestPinProtectsFromGC550=== PAUSE TestPinProtectsFromGC551=== RUN TestClientPushesUseOnePush552=== PAUSE TestClientPushesUseOnePush553=== RUN TestClientFallsBackToClosures554=== PAUSE TestClientFallsBackToClosures555=== RUN TestDeleteClosuresRacingPins556=== PAUSE TestDeleteClosuresRacingPins557=== RUN TestConcurrentCommitsSharingObjectsDoNotDeadlock558=== PAUSE TestConcurrentCommitsSharingObjectsDoNotDeadlock559=== RUN TestResolveDBConnectionString560=== PAUSE TestResolveDBConnectionString561=== RUN TestConnectWaitsForAPeerMigration562=== PAUSE TestConnectWaitsForAPeerMigration563=== RUN TestLeadElectsOneAndHandsOver564=== PAUSE TestLeadElectsOneAndHandsOver565=== RUN TestLeadIncumbentWinsAfterRestart5662026/10/20 08:18:44 INFO lead: acquired remote=192.0.2.1:12345672026/10/20 08:18:44 INFO lead: released remote=192.0.2.1:12345682026/10/20 08:18:44 INFO lead: acquired remote=192.0.2.1:12345692026/10/20 08:18:45 INFO lead: released remote=192.0.2.1:1234570--- PASS: TestLeadIncumbentWinsAfterRestart (2.22s)571=== RUN TestLeadIncumbentAnnouncesAtOnce572=== PAUSE TestLeadIncumbentAnnouncesAtOnce573=== RUN TestLeadEndsOnShutdown574=== PAUSE TestLeadEndsOnShutdown575=== RUN TestLeadEndsWhenItsConnectionHangs5762026/10/20 08:18:46 INFO lead: acquired remote=192.0.2.1:12345772026-10-20 08:18:47.356 UTC [91856] FATAL: terminating connection due to administrator command5782026/10/20 08:18:47 INFO lead: acquired remote=192.0.2.1:12345792026/10/20 08:18:48 WARN lead: lock connection lost error="timeout: context deadline exceeded"5802026/10/20 08:18:48 INFO lead: released remote=192.0.2.1:12345812026/10/20 08:18:48 INFO lead: released remote=192.0.2.1:1234582--- PASS: TestLeadEndsWhenItsConnectionHangs (2.76s)583=== RUN TestGCAdvisoryLockBlocksConcurrentRun584=== PAUSE TestGCAdvisoryLockBlocksConcurrentRun585=== RUN TestGCBugBareHashReferences586=== PAUSE TestGCBugBareHashReferences587=== RUN TestGCMetrics588=== PAUSE TestGCMetrics589=== RUN TestPushDedupSurvivesConcurrentGC590=== PAUSE TestPushDedupSurvivesConcurrentGC591=== RUN TestDeduplicatedObjectsRecordedAsPending592=== PAUSE TestDeduplicatedObjectsRecordedAsPending593=== RUN TestGCSweepSkipsPendingObjects594=== PAUSE TestGCSweepSkipsPendingObjects595=== RUN TestTombstonedObjectOfferedWithoutWaiting596=== PAUSE TestTombstonedObjectOfferedWithoutWaiting597=== RUN TestGCSweepDeliversEachKeyOnce598=== PAUSE TestGCSweepDeliversEachKeyOnce599=== RUN TestCreatePendingClosureVerifyS3FailureReleasesConnection600=== PAUSE TestCreatePendingClosureVerifyS3FailureReleasesConnection601=== RUN TestForceGCDuringPushOffersSweptObject602=== PAUSE TestForceGCDuringPushOffersSweptObject603=== RUN TestFailedS3DeleteKeepsTombstone604=== PAUSE TestFailedS3DeleteKeepsTombstone605=== RUN TestSweepSkipsRowsLockedByPush606=== PAUSE TestSweepSkipsRowsLockedByPush607=== RUN TestRegisterCompletedObjectNeedsPendingRow608=== PAUSE TestRegisterCompletedObjectNeedsPendingRow609=== RUN TestGetExistingObjectsLocksRows610=== PAUSE TestGetExistingObjectsLocksRows611=== RUN TestSweepRechecksPendingAfterLocking612=== PAUSE TestSweepRechecksPendingAfterLocking613=== RUN TestPushWaitsForSweepHoldingRow614=== PAUSE TestPushWaitsForSweepHoldingRow615=== RUN TestCommitRacingPendingCleanupKeepsObjects616=== PAUSE TestCommitRacingPendingCleanupKeepsObjects617=== RUN TestGCEndsOnShutdown618=== PAUSE TestGCEndsOnShutdown619=== RUN TestGCTaskStore_StartNew620=== PAUSE TestGCTaskStore_StartNew621=== RUN TestGCTaskStore_DeduplicateSameParams622=== PAUSE TestGCTaskStore_DeduplicateSameParams623=== RUN TestGCTaskStore_ConflictDifferentParams624=== PAUSE TestGCTaskStore_ConflictDifferentParams625=== RUN TestGCTaskStore_GetEmpty626=== PAUSE TestGCTaskStore_GetEmpty627=== RUN TestGCTaskStore_GetReturnsLatest628=== PAUSE TestGCTaskStore_GetReturnsLatest629=== RUN TestGCTaskStore_CompletedAllowsNewTask630=== PAUSE TestGCTaskStore_CompletedAllowsNewTask631=== RUN TestGCTaskStore_PhaseUpdates632=== PAUSE TestGCTaskStore_PhaseUpdates633=== RUN TestGCTaskStore_Fail634=== PAUSE TestGCTaskStore_Fail635=== RUN TestGracefulShutdownDrainsInflight636=== PAUSE TestGracefulShutdownDrainsInflight637=== RUN TestService_healthCheckHandler638=== PAUSE TestService_healthCheckHandler639=== RUN TestService_readinessHandler640=== PAUSE TestService_readinessHandler641=== RUN TestGenerateLandingPage642=== PAUSE TestGenerateLandingPage643=== RUN TestCacheConfigHandlerMaxNarSize644=== PAUSE TestCacheConfigHandlerMaxNarSize645=== RUN TestCreatePendingClosureRejectsOversizedNAR646=== PAUSE TestCreatePendingClosureRejectsOversizedNAR647=== RUN TestNARDeduplicationMetadataUploadBug648=== PAUSE TestNARDeduplicationMetadataUploadBug649=== RUN TestMetricsInventory650=== PAUSE TestMetricsInventory651=== RUN TestMetricsCommit652=== PAUSE TestMetricsCommit653=== RUN TestService_NativeMTLS654=== PAUSE TestService_NativeMTLS655=== RUN TestServerTLSConfig656=== PAUSE TestServerTLSConfig657=== RUN TestMultipartCleanup658=== PAUSE TestMultipartCleanup659=== RUN TestMultipartUploadAbortedWhenCancelledBeforeRecorded660=== PAUSE TestMultipartUploadAbortedWhenCancelledBeforeRecorded661=== RUN TestPendingCleanupUsesOneCutoff662=== PAUSE TestPendingCleanupUsesOneCutoff663=== RUN TestObjectStatsTrigger664=== PAUSE TestObjectStatsTrigger665=== RUN TestObjectStatsLargeCommit666=== PAUSE TestObjectStatsLargeCommit667=== RUN TestOrphanedObjectsGC668=== PAUSE TestOrphanedObjectsGC669=== RUN TestOrphanedObjectsGCStressTest670=== PAUSE TestOrphanedObjectsGCStressTest671=== RUN TestCreatePin_ReservedPins672=== PAUSE TestCreatePin_ReservedPins673=== RUN TestPresentReportsOnlyClosureRoots674=== PAUSE TestPresentReportsOnlyClosureRoots675=== RUN TestPresentRefreshesOnlyStaleClosures676=== PAUSE TestPresentRefreshesOnlyStaleClosures677=== RUN TestPresentNotReportedWhileGCDeletesClosure678=== PAUSE TestPresentNotReportedWhileGCDeletesClosure679=== RUN TestParseSingleRange680=== PAUSE TestParseSingleRange681=== RUN TestProxyHeadersOnlyTrustedOnSocket6822026/10/20 08:18:48 INFO Starting HTTP server address=proxy.sock6832026/10/20 08:18:48 INFO Starting HTTP server address=127.0.0.1:528256842026/10/20 08:18:48 WARN mTLS auth: subject not in bound subjects subject="CN=someone"6852026/10/20 08:18:48 INFO Shutdown signal received, draining in-flight requests timeout=10s686--- PASS: TestProxyHeadersOnlyTrustedOnSocket (0.14s)687=== RUN TestIsValidCachePath688=== PAUSE TestIsValidCachePath689=== RUN TestReadProxyNarinfo690=== PAUSE TestReadProxyNarinfo691=== RUN TestReadProxyNarinfoAlreadyDecompressed692=== PAUSE TestReadProxyNarinfoAlreadyDecompressed693=== RUN TestReadProxyContentNegotiation694=== PAUSE TestReadProxyContentNegotiation695=== RUN TestReadProxyNarStreaming696=== PAUSE TestReadProxyNarStreaming697=== RUN TestReadProxy404698=== PAUSE TestReadProxy404699=== RUN TestReadProxyInvalidPath700=== PAUSE TestReadProxyInvalidPath701=== RUN TestReadProxyHead702=== PAUSE TestReadProxyHead703=== RUN TestReadProxyOutlastsServerWriteTimeout704=== PAUSE TestReadProxyOutlastsServerWriteTimeout705=== RUN TestReadProxyConditionalGet706=== PAUSE TestReadProxyConditionalGet707=== RUN TestReadProxyRootRedirectsToIndexHTML708=== PAUSE TestReadProxyRootRedirectsToIndexHTML709=== RUN TestReadProxyDisabled710=== PAUSE TestReadProxyDisabled711=== RUN TestReadRedirectNar712=== PAUSE TestReadRedirectNar713=== RUN TestReadRedirectKeepsNarinfoProxied714=== PAUSE TestReadRedirectKeepsNarinfoProxied715=== RUN TestReadProxyRangeRequest716=== PAUSE TestReadProxyRangeRequest717=== RUN TestReadRedirectUsesPublicS3URL718=== PAUSE TestReadRedirectUsesPublicS3URL719=== RUN TestPush_OverlappingRootsStoreOneRowPerKey720=== PAUSE TestPush_OverlappingRootsStoreOneRowPerKey721=== RUN TestPush_CompleteCommitsEveryRoot722=== PAUSE TestPush_CompleteCommitsEveryRoot723=== RUN TestPush_RepeatedRootCommitsOnce724=== PAUSE TestPush_RepeatedRootCommitsOnce725=== RUN TestPush_CompleteWaitsForCleanupOfThePush726=== PAUSE TestPush_CompleteWaitsForCleanupOfThePush727=== RUN TestPush_RootsAreLockedInByteOrder728=== PAUSE TestPush_RootsAreLockedInByteOrder729=== RUN TestPush_SkippedKeySurvivesGCBeforeCommit730=== PAUSE TestPush_SkippedKeySurvivesGCBeforeCommit731=== RUN TestPush_RejectsBadRequests732=== PAUSE TestPush_RejectsBadRequests733=== RUN TestPush_SignsNarinfosOfItsPendingObjects734=== PAUSE TestPush_SignsNarinfosOfItsPendingObjects735=== RUN TestRedundantMultipartUpload736=== PAUSE TestRedundantMultipartUpload737=== RUN TestCompleteMultipartUpload_ErrorButObjectExists738=== PAUSE TestCompleteMultipartUpload_ErrorButObjectExists739=== RUN TestCompletedNarNotReofferedAcrossClosures740=== PAUSE TestCompletedNarNotReofferedAcrossClosures741=== RUN TestPresignedUploadRegisteredBeforeCommit742=== PAUSE TestPresignedUploadRegisteredBeforeCommit743=== RUN TestService_Rustfstest744=== PAUSE TestService_Rustfstest745=== RUN TestParseSize746=== PAUSE TestParseSize747=== RUN TestSkippedUploadsHandler748=== PAUSE TestSkippedUploadsHandler749=== RUN TestSystemdListenerNotActivated750--- PASS: TestSystemdListenerNotActivated (0.00s)751=== RUN TestWatchdogBeatsWhenHealthy752--- PASS: TestWatchdogBeatsWhenHealthy (0.02s)753=== RUN TestWatchdogSkipsWhenUnhealthy7542026/10/20 08:18:48 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7552026/10/20 08:18:48 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7562026/10/20 08:18:48 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7572026/10/20 08:18:49 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7582026/10/20 08:18:49 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7592026/10/20 08:18:49 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7602026/10/20 08:18:49 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7612026/10/20 08:18:49 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7622026/10/20 08:18:49 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7632026/10/20 08:18:49 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"764--- PASS: TestWatchdogSkipsWhenUnhealthy (0.20s)765=== RUN TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle766=== PAUSE TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle767=== RUN TestProxyWriteTimeout768=== PAUSE TestProxyWriteTimeout769=== RUN TestPendingClosureWriteTimeout770=== PAUSE TestPendingClosureWriteTimeout771=== RUN TestIsValidUploadKey772=== PAUSE TestIsValidUploadKey773=== RUN TestUploadHandlersRejectInvalidKeys774=== PAUSE TestUploadHandlersRejectInvalidKeys775=== RUN TestUploadHandlersRejectOversizedBody776=== PAUSE TestUploadHandlersRejectOversizedBody777=== RUN TestService_cleanupPendingClosuresHandler778=== PAUSE TestService_cleanupPendingClosuresHandler779=== RUN TestService_createPendingClosureHandler780=== PAUSE TestService_createPendingClosureHandler781=== RUN TestService_verifyS3Integrity782=== PAUSE TestService_verifyS3Integrity783=== RUN TestCompleteMultipartUnregistered784=== PAUSE TestCompleteMultipartUnregistered785=== RUN TestCreatePendingClosure_SmallNARUsesSimplePUT786=== PAUSE TestCreatePendingClosure_SmallNARUsesSimplePUT787=== CONT TestPush_CompleteCommitsEveryRoot788=== CONT TestReadProxyNarStreaming789=== CONT TestIsValidUploadKey790=== RUN TestIsValidUploadKey/narinfo791=== PAUSE TestIsValidUploadKey/narinfo792=== CONT TestPush_OverlappingRootsStoreOneRowPerKey793=== CONT TestReadRedirectUsesPublicS3URL794=== CONT TestReadProxyRangeRequest795=== CONT TestReadRedirectKeepsNarinfoProxied796=== CONT TestReadRedirectNar797=== CONT TestSkippedUploadsHandler798=== CONT TestReadProxyDisabled799=== CONT TestCreatePendingClosure_SmallNARUsesSimplePUT800=== CONT TestReadProxyRootRedirectsToIndexHTML801=== CONT TestCompleteMultipartUnregistered802=== CONT TestReadProxyConditionalGet803=== CONT TestService_verifyS3Integrity804=== CONT TestReadProxyOutlastsServerWriteTimeout805=== CONT TestService_createPendingClosureHandler806=== CONT TestReadProxyHead8072026/10/20 08:18:49 INFO Client skipped oversized paths paths=3 nar_bytes=5000000000808=== CONT TestService_cleanupPendingClosuresHandler809=== CONT TestReadProxyInvalidPath810=== CONT TestUploadHandlersRejectOversizedBody811=== CONT TestReadProxy404812=== CONT TestUploadHandlersRejectInvalidKeys813=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info814=== CONT TestService_AuthMiddleware815=== RUN TestIsValidUploadKey/nar_zst816=== PAUSE TestIsValidUploadKey/nar_zst817=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info818=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal819=== RUN TestIsValidUploadKey/nar_xz820=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal821=== RUN TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key822=== PAUSE TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key823=== RUN TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key824=== PAUSE TestIsValidUploadKey/nar_xz825=== PAUSE TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key826=== CONT TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle827=== RUN TestIsValidUploadKey/nar_plain828=== PAUSE TestIsValidUploadKey/nar_plain829=== RUN TestIsValidUploadKey/listing830=== PAUSE TestIsValidUploadKey/listing831=== RUN TestIsValidUploadKey/build_log832=== PAUSE TestIsValidUploadKey/build_log833=== RUN TestIsValidUploadKey/build_log_home-manager_file834=== PAUSE TestIsValidUploadKey/build_log_home-manager_file835=== RUN TestIsValidUploadKey/build_log_plus_in_name836=== PAUSE TestIsValidUploadKey/build_log_plus_in_name837=== RUN TestIsValidUploadKey/build_log_question_mark838=== PAUSE TestIsValidUploadKey/build_log_question_mark839=== RUN TestIsValidUploadKey/build_log_equals840=== PAUSE TestIsValidUploadKey/build_log_equals841=== RUN TestIsValidUploadKey/realisation842--- PASS: TestSkippedUploadsHandler (0.01s)843=== CONT TestProxyWriteTimeout844=== RUN TestProxyWriteTimeout/narinfo845=== PAUSE TestIsValidUploadKey/realisation846=== RUN TestIsValidUploadKey/realisation_plus_in_output847=== PAUSE TestIsValidUploadKey/realisation_plus_in_output848=== RUN TestIsValidUploadKey/nix-cache-info849=== PAUSE TestIsValidUploadKey/nix-cache-info850=== RUN TestIsValidUploadKey/index.html851=== PAUSE TestIsValidUploadKey/index.html852=== RUN TestIsValidUploadKey/narinfo_key,_nar_type853=== PAUSE TestIsValidUploadKey/narinfo_key,_nar_type854=== RUN TestIsValidUploadKey/nar_key,_narinfo_type855=== PAUSE TestIsValidUploadKey/nar_key,_narinfo_type856=== RUN TestIsValidUploadKey/listing_key,_narinfo_type857=== PAUSE TestIsValidUploadKey/listing_key,_narinfo_type858=== RUN TestIsValidUploadKey/traversal859=== PAUSE TestIsValidUploadKey/traversal860=== RUN TestIsValidUploadKey/traversal_nar861=== PAUSE TestIsValidUploadKey/traversal_nar862=== RUN TestIsValidUploadKey/absolute863=== PAUSE TestIsValidUploadKey/absolute864=== RUN TestIsValidUploadKey/empty_key865=== PAUSE TestIsValidUploadKey/empty_key866=== RUN TestIsValidUploadKey/unknown_type867=== PAUSE TestIsValidUploadKey/unknown_type868=== PAUSE TestProxyWriteTimeout/narinfo869=== RUN TestProxyWriteTimeout/1_GiB_nar870=== PAUSE TestProxyWriteTimeout/1_GiB_nar871=== RUN TestProxyWriteTimeout/10_GiB_nar872=== PAUSE TestProxyWriteTimeout/10_GiB_nar873=== RUN TestProxyWriteTimeout/unknown_size874=== PAUSE TestProxyWriteTimeout/unknown_size875=== CONT TestPendingClosureWriteTimeout876=== RUN TestPendingClosureWriteTimeout/empty877=== PAUSE TestPendingClosureWriteTimeout/empty878=== RUN TestPendingClosureWriteTimeout/400_objects879=== PAUSE TestPendingClosureWriteTimeout/400_objects880=== RUN TestPendingClosureWriteTimeout/670k_objects881=== PAUSE TestPendingClosureWriteTimeout/670k_objects882=== RUN TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline883=== PAUSE TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline884=== CONT TestRedundantMultipartUpload885=== CONT TestParseSize886--- PASS: TestParseSize (0.00s)887=== CONT TestService_Rustfstest888=== RUN TestUploadHandlersRejectOversizedBody/request_more_parts889=== PAUSE TestUploadHandlersRejectOversizedBody/request_more_parts890=== RUN TestUploadHandlersRejectOversizedBody/create_pending_closure891=== PAUSE TestUploadHandlersRejectOversizedBody/create_pending_closure892=== RUN TestUploadHandlersRejectOversizedBody/complete_multipart893=== PAUSE TestUploadHandlersRejectOversizedBody/complete_multipart894=== CONT TestPresignedUploadRegisteredBeforeCommit895--- PASS: TestReadProxyNarStreaming (0.68s)896=== CONT TestSweepRechecksPendingAfterLocking8972026/10/20 08:18:49 INFO Received complete multipart upload request method=POST path=/api/multipart/complete8982026/10/20 08:18:49 ERROR Failed to get multipart upload error="no rows in result set" upload_id=does-not-exist object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst899--- PASS: TestCompleteMultipartUnregistered (0.81s)900=== CONT TestCompletedNarNotReofferedAcrossClosures9012026/10/20 08:18:50 INFO Received push request method=POST path=/api/pushes902--- PASS: TestPush_OverlappingRootsStoreOneRowPerKey (1.12s)903=== CONT TestReadProxyContentNegotiation904--- PASS: TestReadRedirectNar (1.22s)905=== CONT TestCompleteMultipartUpload_ErrorButObjectExists9062026/10/20 08:18:50 INFO Received uploads request method=POST path=/api/pending_closures907--- PASS: TestReadRedirectKeepsNarinfoProxied (2.12s)908=== CONT TestReadProxyNarinfoAlreadyDecompressed909--- PASS: TestReadProxyDisabled (2.32s)910=== CONT TestReadProxyNarinfo911--- PASS: TestReadRedirectUsesPublicS3URL (2.55s)912=== CONT TestCreatePendingClosureRejectsOversizedNAR9132026/10/20 08:18:51 INFO Received uploads request method=POST path=/api/pending_closures914--- PASS: TestCreatePendingClosureRejectsOversizedNAR (0.00s)915=== CONT TestCacheConfigHandlerMaxNarSize916--- PASS: TestCacheConfigHandlerMaxNarSize (0.00s)917=== CONT TestGenerateLandingPage918--- PASS: TestGenerateLandingPage (0.00s)919=== CONT TestService_readinessHandler9202026/10/20 08:18:51 INFO Received uploads request method=POST path=/api/pending_closures921--- PASS: TestCreatePendingClosure_SmallNARUsesSimplePUT (2.88s)922=== CONT TestNARDeduplicationMetadataUploadBug9232026/10/20 08:18:52 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9242026/10/20 08:18:52 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst upload_id=YzU0ZWNiMzAtMDYyNy00M2M0LTkwYTktN2QwNmYyZDZmYWRlLmY4NDViNjdiLTI4NjItNGFmMC1hM2EwLWU0NmE0MWIxNmJhYngxNzkyNDg0MzMwOTY3MDUzMDAw parts=109252026/10/20 08:18:52 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete9262026/10/20 08:18:52 INFO Completed upload id=1 objects=2 duration=11.556375ms9272026/10/20 08:18:52 INFO Received uploads request method=POST path=/api/pending_closures9282026/10/20 08:18:52 INFO Received uploads request method=POST path=/api/pending_closures9292026/10/20 08:18:52 INFO Object in database but missing from S3 key=dadb44fdadb44fdadb44fdadb44f0000.narinfo9302026/10/20 08:18:52 WARN Found objects in DB but missing from S3, will re-upload count=1931--- PASS: TestService_verifyS3Integrity (3.14s)932=== CONT TestIsValidCachePath933=== RUN TestIsValidCachePath/narinfo934=== PAUSE TestIsValidCachePath/narinfo935=== RUN TestIsValidCachePath/narinfo_all_nix_base32_chars936=== PAUSE TestIsValidCachePath/narinfo_all_nix_base32_chars937=== RUN TestIsValidCachePath/nar_zst938=== PAUSE TestIsValidCachePath/nar_zst939=== RUN TestIsValidCachePath/nar_xz940=== PAUSE TestIsValidCachePath/nar_xz941=== RUN TestIsValidCachePath/nar_bz2942=== PAUSE TestIsValidCachePath/nar_bz2943=== RUN TestIsValidCachePath/nar_uncompressed944=== PAUSE TestIsValidCachePath/nar_uncompressed945=== RUN TestIsValidCachePath/ls946=== PAUSE TestIsValidCachePath/ls947=== RUN TestIsValidCachePath/log948=== PAUSE TestIsValidCachePath/log949=== RUN TestIsValidCachePath/realisation950=== PAUSE TestIsValidCachePath/realisation951=== RUN TestIsValidCachePath/nix-cache-info952=== PAUSE TestIsValidCachePath/nix-cache-info953=== RUN TestIsValidCachePath/index.html954=== PAUSE TestIsValidCachePath/index.html955=== RUN TestIsValidCachePath/traversal_parent956=== PAUSE TestIsValidCachePath/traversal_parent957=== RUN TestIsValidCachePath/traversal_in_middle958=== PAUSE TestIsValidCachePath/traversal_in_middle959=== RUN TestIsValidCachePath/invalid_char_e960=== PAUSE TestIsValidCachePath/invalid_char_e961=== RUN TestIsValidCachePath/invalid_char_u962=== PAUSE TestIsValidCachePath/invalid_char_u963=== RUN TestIsValidCachePath/random_path964=== PAUSE TestIsValidCachePath/random_path965=== RUN TestIsValidCachePath/empty966=== PAUSE TestIsValidCachePath/empty967=== RUN TestIsValidCachePath/leading_slash968=== PAUSE TestIsValidCachePath/leading_slash969=== RUN TestIsValidCachePath/wrong_extension970=== PAUSE TestIsValidCachePath/wrong_extension971=== RUN TestIsValidCachePath/short_hash972=== PAUSE TestIsValidCachePath/short_hash973=== CONT TestParseSingleRange974=== RUN TestParseSingleRange/none975=== PAUSE TestParseSingleRange/none976=== RUN TestParseSingleRange/unknown_unit977=== PAUSE TestParseSingleRange/unknown_unit978=== RUN TestParseSingleRange/multi-range_ignored979=== PAUSE TestParseSingleRange/multi-range_ignored980=== RUN TestParseSingleRange/malformed_no_dash981=== PAUSE TestParseSingleRange/malformed_no_dash982=== RUN TestParseSingleRange/malformed_both_empty983=== PAUSE TestParseSingleRange/malformed_both_empty984=== RUN TestParseSingleRange/malformed_end_before_start985=== PAUSE TestParseSingleRange/malformed_end_before_start986=== RUN TestParseSingleRange/closed987=== PAUSE TestParseSingleRange/closed988=== RUN TestParseSingleRange/open-ended989=== PAUSE TestParseSingleRange/open-ended990=== RUN TestParseSingleRange/end_clamped_to_size991=== PAUSE TestParseSingleRange/end_clamped_to_size992=== RUN TestParseSingleRange/suffix993=== PAUSE TestParseSingleRange/suffix994=== RUN TestParseSingleRange/suffix_exceeds_size995=== PAUSE TestParseSingleRange/suffix_exceeds_size996=== RUN TestParseSingleRange/single_byte997=== PAUSE TestParseSingleRange/single_byte998=== RUN TestParseSingleRange/start_past_EOF999=== PAUSE TestParseSingleRange/start_past_EOF1000=== RUN TestParseSingleRange/start_far_past_EOF1001=== PAUSE TestParseSingleRange/start_far_past_EOF1002=== CONT TestService_healthCheckHandler1003--- PASS: TestReadProxyRootRedirectsToIndexHTML (3.23s)1004=== CONT TestPresentNotReportedWhileGCDeletesClosure1005=== RUN TestPresentNotReportedWhileGCDeletesClosure/stale1006=== PAUSE TestPresentNotReportedWhileGCDeletesClosure/stale1007=== RUN TestPresentNotReportedWhileGCDeletesClosure/fresh1008=== PAUSE TestPresentNotReportedWhileGCDeletesClosure/fresh1009=== CONT TestGracefulShutdownDrainsInflight10102026/10/20 08:18:52 INFO Starting HTTP server address=127.0.0.1:5288310112026/10/20 08:18:52 INFO Shutdown signal received, draining in-flight requests timeout=10s1012--- PASS: TestGracefulShutdownDrainsInflight (0.07s)1013=== CONT TestPresentRefreshesOnlyStaleClosures1014--- PASS: TestReadProxyRangeRequest (3.40s)1015=== CONT TestGCTaskStore_Fail1016--- PASS: TestGCTaskStore_Fail (0.00s)1017=== CONT TestPresentReportsOnlyClosureRoots1018--- PASS: TestReadProxyInvalidPath (3.51s)1019=== CONT TestGCTaskStore_PhaseUpdates1020--- PASS: TestGCTaskStore_PhaseUpdates (0.00s)1021=== CONT TestGCTaskStore_CompletedAllowsNewTask1022--- PASS: TestGCTaskStore_CompletedAllowsNewTask (0.00s)1023=== CONT TestGCTaskStore_GetReturnsLatest1024--- PASS: TestGCTaskStore_GetReturnsLatest (0.00s)1025=== CONT TestPush_SkippedKeySurvivesGCBeforeCommit10262026/10/20 08:18:52 INFO Received uploads request method=POST path=/api/pending_closures10272026/10/20 08:18:52 INFO Received uploads request method=POST path=/api/pending_closures10282026/10/20 08:18:53 INFO Received push request method=POST path=/api/pushes10292026/10/20 08:18:53 INFO Received complete push request method=POST path=/api/pushes/1/complete10302026/10/20 08:18:53 INFO Completed push id=1 objects=6 duration=25.579084ms1031--- PASS: TestPush_CompleteCommitsEveryRoot (4.03s)1032=== CONT TestCreatePin_ReservedPins10332026/10/20 08:18:53 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:52903/oidc10342026/10/20 08:18:53 INFO Received uploads request method=POST path=/api/pending_closures1035--- PASS: TestReadProxyHead (4.40s)1036=== CONT TestPush_SignsNarinfosOfItsPendingObjects10372026/10/20 08:18:53 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1038--- PASS: TestReadProxyConditionalGet (4.73s)1039=== CONT TestOrphanedObjectsGCStressTest10402026/10/20 08:18:54 WARN Authentication failed token_preview=wrongtoken token_length=10 reason="static API token mismatch"1041--- PASS: TestService_AuthMiddleware (4.88s)1042=== CONT TestPush_RejectsBadRequests10432026/10/20 08:18:54 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1044--- PASS: TestService_Rustfstest (5.01s)1045=== CONT TestGCTaskStore_GetEmpty1046--- PASS: TestGCTaskStore_GetEmpty (0.00s)1047=== CONT TestOrphanedObjectsGC10482026/10/20 08:18:54 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=YzU0ZWNiMzAtMDYyNy00M2M0LTkwYTktN2QwNmYyZDZmYWRlLmI2MGZkZWZhLTI2ZDItNDFhMy1iODE3LWExZmQyNmU5NTI1MHgxNzkyNDg0MzMyODMzNTgwMDAw parts=1210492026/10/20 08:18:54 INFO Received uploads request method=POST path=/api/pending_closures10502026/10/20 08:18:54 INFO Received uploads request method=POST path=/api/pending_closures10512026/10/20 08:18:54 INFO Received uploads request method=POST path=/api/pending_closures10522026/10/20 08:18:54 INFO Registered completed upload object_key=nar/jjjjjjjjjjjjjjjjjjjjjjjjjjjjjj0100000000000000000000.nar.zst10532026/10/20 08:18:54 INFO Received uploads request method=POST path=/api/pending_closures1054--- PASS: TestPresignedUploadRegisteredBeforeCommit (5.25s)1055=== CONT TestObjectStatsLargeCommit10562026/10/20 08:18:54 INFO Received cleanup request method=DELETE path=/api/pending_closures10572026/10/20 08:18:54 INFO Aborted multipart uploads count=0 kept=010582026/10/20 08:18:54 INFO Received uploads request method=POST path=/api/pending_closures10592026/10/20 08:18:54 INFO Received cleanup request method=DELETE path=/api/pending_closures10602026/10/20 08:18:54 INFO Aborted multipart uploads count=1 kept=010612026/10/20 08:18:54 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete10622026-10-20 08:18:54.664 UTC [93563] ERROR: Closure does not exist: id=110632026-10-20 08:18:54.664 UTC [93563] CONTEXT: PL/pgSQL function commit_pending_closure(bigint) line 13 at RAISE10642026-10-20 08:18:54.664 UTC [93563] STATEMENT: -- name: CommitPendingClosure :one1065 SELECT commit_pending_closure($1::bigint)::bigint1066 1067--- PASS: TestService_cleanupPendingClosuresHandler (5.53s)1068=== CONT TestObjectStatsTrigger10692026/10/20 08:18:54 INFO Received uploads request method=POST path=/api/pending_closures10702026/10/20 08:18:54 INFO Received uploads request method=POST path=/api/pending_closures10712026/10/20 08:18:54 INFO Received uploads request method=POST path=/api/pending_closures1072--- PASS: TestReadProxy404 (5.95s)1073=== CONT TestPendingCleanupUsesOneCutoff10742026/10/20 08:18:55 INFO Received uploads request method=POST path=/api/pending_closures10752026/10/20 08:18:55 INFO Received complete multipart upload request method=POST path=/api/multipart/complete10762026/10/20 08:18:55 WARN Failed to abort redundant multipart upload, keeping its row object_key=nar/gggggggggggggggggggggggggggggg0200000000000000000000.nar.zst upload_id=YzU0ZWNiMzAtMDYyNy00M2M0LTkwYTktN2QwNmYyZDZmYWRlLjM0ZTk3NWQ5LTMwZjYtNDU1My1iZWMxLWIwMjhkMDllNjZlZngxNzkyNDg0MzM0MzEzMDQ1MDAw error="Get \"http://127.0.0.1:1/bucket17/?location=\": dial tcp 127.0.0.1:1: connect: connection refused"10772026/10/20 08:18:55 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0200000000000000000000.nar.zst upload_id=YzU0ZWNiMzAtMDYyNy00M2M0LTkwYTktN2QwNmYyZDZmYWRlLmZhYTFiNGY2LTY4MjItNGZkMy04NmRhLTRiODcyMDFiZGE5MXgxNzkyNDg0MzM0Mjg2MzkzMDAw parts=1210782026/10/20 08:18:55 INFO Received cleanup request method=DELETE path=/api/pending_closures1079--- PASS: TestReadProxyContentNegotiation (5.46s)1080=== CONT TestMultipartUploadAbortedWhenCancelledBeforeRecorded10812026/10/20 08:18:55 INFO Aborted multipart uploads count=1 kept=01082--- PASS: TestRedundantMultipartUpload (6.54s)1083=== CONT TestMetricsCommit10842026/10/20 08:18:55 INFO Received uploads request method=POST path=/api/pending_closures10852026/10/20 08:18:56 INFO Received complete multipart upload request method=POST path=/api/multipart/complete10862026/10/20 08:18:56 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified key does not exist." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=YzU0ZWNiMzAtMDYyNy00M2M0LTkwYTktN2QwNmYyZDZmYWRlLjU1ZjZkOTVjLWMwNDEtNDBkYy04ZGEzLWQwNmZlODM0OTYzNHgxNzkyNDg0MzM1ODgwMzUxMDAw10872026/10/20 08:18:56 INFO Received complete multipart upload request method=POST path=/api/multipart/complete10882026/10/20 08:18:56 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=YzU0ZWNiMzAtMDYyNy00M2M0LTkwYTktN2QwNmYyZDZmYWRlLjU1ZjZkOTVjLWMwNDEtNDBkYy04ZGEzLWQwNmZlODM0OTYzNHgxNzkyNDg0MzM1ODgwMzUxMDAw parts=11089--- PASS: TestCompleteMultipartUpload_ErrorButObjectExists (5.92s)1090=== CONT TestGCEndsOnShutdown1091=== RUN TestGCEndsOnShutdown/before_the_run1092=== PAUSE TestGCEndsOnShutdown/before_the_run1093=== RUN TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete1094=== PAUSE TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete1095=== RUN TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark1096=== PAUSE TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark1097=== CONT TestMetricsInventory10982026/10/20 08:18:56 INFO Aborted multipart uploads count=0 kept=010992026/10/20 08:18:56 WARN Force mode enabled - objects will be deleted immediately without grace period11002026/10/20 08:18:56 INFO Completed multipart upload object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst upload_id=YzU0ZWNiMzAtMDYyNy00M2M0LTkwYTktN2QwNmYyZDZmYWRlLjhlOTQ2NDQzLTMyNWUtNGFjZC1iNmVjLTQ5ZTk2NjQ0YWE4M3gxNzkyNDg0MzM0Nzk4NTM2MDAw parts=1011012026/10/20 08:18:56 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete11022026/10/20 08:18:56 INFO Completed upload id=1 objects=2 duration=22.803209ms11032026/10/20 08:18:56 INFO Received get closure request method=GET path=/api/closures/0000000000000000000000000000000011042026/10/20 08:18:56 INFO Received uploads request method=POST path=/api/pending_closures11052026/10/20 08:18:56 INFO Starting cleanup of old closures method=DELETE path=/api/closures11062026/10/20 08:18:56 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=01107--- PASS: TestReadProxyOutlastsServerWriteTimeout (7.28s)1108=== CONT TestCommitRacingPendingCleanupKeepsObjects11092026/10/20 08:18:56 INFO Aborted multipart uploads count=0 kept=011102026/10/20 08:18:56 INFO Vacuumed table table=pending_closures11112026/10/20 08:18:56 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=011122026/10/20 08:18:56 INFO Vacuumed table table=pending_closures11132026/10/20 08:18:56 INFO Vacuumed table table=pending_objects11142026/10/20 08:18:56 INFO Vacuumed table table=multipart_uploads11152026/10/20 08:18:56 INFO Vacuumed table table=closures11162026/10/20 08:18:56 INFO Vacuumed table table=pending_objects11172026/10/20 08:18:56 INFO Vacuumed table table=objects1118--- PASS: TestSweepRechecksPendingAfterLocking (6.68s)1119=== CONT TestPush_CompleteWaitsForCleanupOfThePush11202026/10/20 08:18:56 INFO Vacuumed table table=multipart_uploads1121--- PASS: TestReadProxyNarinfoAlreadyDecompressed (5.28s)1122=== CONT TestPushWaitsForSweepHoldingRow11232026/10/20 08:18:56 INFO Vacuumed table table=closures11242026/10/20 08:18:56 INFO Vacuumed table table=objects11252026/10/20 08:18:56 INFO Received get closure request method=GET path=/api/closures/000000000000000000000000000000001126--- PASS: TestService_createPendingClosureHandler (7.46s)1127=== CONT TestPush_RootsAreLockedInByteOrder11282026/10/20 08:18:56 ERROR Failed to decode narinfo key=3hcdxyjf9yiq7qf3i4548drb6sjmwa1v.narinfo limit=16777216 error=<nil>1129--- PASS: TestReadProxyNarinfo (5.46s)1130=== CONT TestMultipartCleanup11312026/10/20 08:18:57 WARN readiness check failed error="closed pool"1132--- PASS: TestService_readinessHandler (5.33s)1133=== CONT TestPush_RepeatedRootCommitsOnce11342026/10/20 08:18:57 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11352026/10/20 08:18:57 INFO Completed multipart upload object_key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhh0100000000000000000000.nar.zst upload_id=YzU0ZWNiMzAtMDYyNy00M2M0LTkwYTktN2QwNmYyZDZmYWRlLjM1M2EwYzIzLTZkNGUtNDQ5NC05MWY4LTJjZjQ1M2JhYTAwMngxNzkyNDg0MzM1Mjc5MDkxMDAw parts=1211362026/10/20 08:18:57 INFO Received uploads request method=POST path=/api/pending_closures1137--- PASS: TestCompletedNarNotReofferedAcrossClosures (7.20s)1138=== CONT TestGCTaskStore_StartNew1139--- PASS: TestGCTaskStore_StartNew (0.00s)1140=== CONT TestGCTaskStore_ConflictDifferentParams1141--- PASS: TestGCTaskStore_ConflictDifferentParams (0.00s)1142=== CONT TestServerTLSConfig1143=== RUN TestServerTLSConfig/no_client_CA1144=== PAUSE TestServerTLSConfig/no_client_CA1145=== RUN TestServerTLSConfig/missing_CA_file1146=== PAUSE TestServerTLSConfig/missing_CA_file1147=== RUN TestServerTLSConfig/not_a_PEM_file1148=== PAUSE TestServerTLSConfig/not_a_PEM_file1149=== CONT TestGCTaskStore_DeduplicateSameParams1150--- PASS: TestGCTaskStore_DeduplicateSameParams (0.00s)1151=== CONT TestService_NativeMTLS1152--- PASS: TestService_healthCheckHandler (5.28s)1153=== CONT TestGCAdvisoryLockBlocksConcurrentRun1154=== NAME TestNARDeduplicationMetadataUploadBug1155 metadata_upload_test.go:48: First store path: /private/var/tb/1/scratch/c8b5f9203adb9a1c/build/TestNARDeduplicationMetadataUploadBug3199460330/001/store/bcf6axfmv1iyxgk64g8w7qnq6i8za8k8-file1.txt11562026/10/20 08:18:57 INFO Received push request method=POST path=/api/pushes11572026/10/20 08:18:57 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)11582026/10/20 08:18:57 INFO Uploading bcf6axfmv1iyxgk64g8w7qnq6i8za8k8-file1.txt (160B)11592026/10/20 08:18:57 WARN Failed to register uploaded object key=nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst error="server returned 404: 404 page not found\n"11602026/10/20 08:18:57 WARN Failed to register uploaded object key=bcf6axfmv1iyxgk64g8w7qnq6i8za8k8.ls error="server returned 404: 404 page not found\n"11612026/10/20 08:18:57 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign11622026/10/20 08:18:57 INFO Signed narinfos id=1 count=111632026/10/20 08:18:57 INFO Uploading 1 narinfos11642026/10/20 08:18:57 INFO Received complete push request method=POST path=/api/pushes/1/complete11652026/10/20 08:18:57 WARN Failed to register uploaded object key=bcf6axfmv1iyxgk64g8w7qnq6i8za8k8.narinfo error="server returned 404: 404 page not found\n"1166--- PASS: TestPresentRefreshesOnlyStaleClosures (5.49s)1167=== CONT TestResolveDBConnectionString1168=== RUN TestResolveDBConnectionString/flag_wins1169=== PAUSE TestResolveDBConnectionString/flag_wins1170=== RUN TestResolveDBConnectionString/file_when_flag_empty1171=== PAUSE TestResolveDBConnectionString/file_when_flag_empty1172=== RUN TestResolveDBConnectionString/missing_file_is_an_error1173=== PAUSE TestResolveDBConnectionString/missing_file_is_an_error1174=== RUN TestResolveDBConnectionString/PGHOST_allows_empty1175=== PAUSE TestResolveDBConnectionString/PGHOST_allows_empty1176=== RUN TestResolveDBConnectionString/nothing_configured1177=== PAUSE TestResolveDBConnectionString/nothing_configured1178=== CONT TestGCSweepSkipsPendingObjects11792026/10/20 08:18:57 INFO Completed push id=1 objects=3 duration=37.465167ms11802026/10/20 08:18:57 INFO Upload complete. (275ms)1181=== NAME TestNARDeduplicationMetadataUploadBug1182 metadata_upload_test.go:54: Retrieved narinfo from S3:1183 StorePath: /private/var/tb/1/scratch/c8b5f9203adb9a1c/build/TestNARDeduplicationMetadataUploadBug3199460330/001/store/bcf6axfmv1iyxgk64g8w7qnq6i8za8k8-file1.txt1184 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1185 Compression: zstd1186 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1187 NarSize: 1601188 References: 1189 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1190 metadata_upload_test.go:55: Retrieved .ls file from S3 (compressed size: 77 bytes)1191 metadata_upload_test.go:55: Decompressed .ls content (64 bytes):1192 {"version":1,"root":{"type":"regular","size":44,"narOffset":96}}1193 metadata_upload_test.go:64: Second store path (same content): /private/var/tb/1/scratch/c8b5f9203adb9a1c/build/TestNARDeduplicationMetadataUploadBug3199460330/001/store/bgi0kcwkga1szxsrdlsf7h3d6np6zs5n-file2.txt11942026/10/20 08:18:58 INFO Received push request method=POST path=/api/pushes11952026/10/20 08:18:58 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)1196--- PASS: TestPresentReportsOnlyClosureRoots (5.78s)1197=== CONT TestDeduplicatedObjectsRecordedAsPending11982026/10/20 08:18:58 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign11992026/10/20 08:18:58 WARN Failed to register uploaded object key=bgi0kcwkga1szxsrdlsf7h3d6np6zs5n.ls error="server returned 404: 404 page not found\n"12002026/10/20 08:18:58 INFO Signed narinfos id=2 count=112012026/10/20 08:18:58 INFO Uploading 1 narinfos12022026/10/20 08:18:58 INFO Received complete push request method=POST path=/api/pushes/2/complete12032026/10/20 08:18:58 WARN Failed to register uploaded object key=bgi0kcwkga1szxsrdlsf7h3d6np6zs5n.narinfo error="server returned 404: 404 page not found\n"12042026/10/20 08:18:58 INFO Completed push id=2 objects=3 duration=1.062458ms12052026/10/20 08:18:58 INFO Upload complete. (341ms)1206=== NAME TestNARDeduplicationMetadataUploadBug1207 metadata_upload_test.go:76: Retrieved narinfo from S3:1208 StorePath: /private/var/tb/1/scratch/c8b5f9203adb9a1c/build/TestNARDeduplicationMetadataUploadBug3199460330/001/store/bgi0kcwkga1szxsrdlsf7h3d6np6zs5n-file2.txt1209 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1210 Compression: zstd1211 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1212 NarSize: 1601213 References: 1214 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1215 metadata_upload_test.go:77: Retrieved .ls file from S3 (compressed size: 62 bytes)1216 metadata_upload_test.go:77: Decompressed .ls content (49 bytes):1217 {"version":1,"root":{"type":"regular","size":44}}1218--- PASS: TestNARDeduplicationMetadataUploadBug (6.58s)1219=== CONT TestLeadEndsOnShutdown12202026/10/20 08:18:58 WARN Rate limiter enabled after throttle name=s3-test rate=512212026/10/20 08:18:58 WARN S3 rate limit hit operation="complete multipart upload" error="Please reduce your request rate."1222=== NAME TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle1223 throttle_test.go:213: Proxy stats: total=13, throttled=10, completeMultipart=101224 throttle_test.go:215: Rate limiter: enabled=true, rate=5.001225--- PASS: TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle (9.49s)1226=== CONT TestClientErrorHandling1227=== RUN TestClientErrorHandling/InvalidStorePath1228=== PAUSE TestClientErrorHandling/InvalidStorePath1229=== RUN TestClientErrorHandling/InvalidAuthToken1230=== PAUSE TestClientErrorHandling/InvalidAuthToken1231=== RUN TestClientErrorHandling/ServerNotAvailable1232=== PAUSE TestClientErrorHandling/ServerNotAvailable1233=== CONT TestPushDedupSurvivesConcurrentGC12342026/10/20 08:18:58 INFO Received push request method=POST path=/api/pushes12352026/10/20 08:18:58 INFO Received complete push request method=POST path=/api/pushes/1/complete12362026/10/20 08:18:58 INFO Completed push id=1 objects=4 duration=38.711625ms12372026/10/20 08:18:58 INFO Received push request method=POST path=/api/pushes12382026/10/20 08:18:58 INFO Aborted multipart uploads count=0 kept=012392026/10/20 08:18:58 WARN Force mode enabled - objects will be deleted immediately without grace period12402026/10/20 08:18:58 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=012412026/10/20 08:18:58 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux12422026/10/20 08:18:58 WARN Refused reserved pin name=worker-x86_64-linux12432026/10/20 08:18:58 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux12442026/10/20 08:18:58 INFO Received create pin request method=POST path=/api/pins/my-app12452026/10/20 08:18:58 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux1246--- PASS: TestCreatePin_ReservedPins (5.84s)1247=== CONT TestLeadIncumbentAnnouncesAtOnce12482026/10/20 08:18:59 INFO Vacuumed table table=pending_closures12492026/10/20 08:18:59 INFO Vacuumed table table=pending_objects12502026/10/20 08:18:59 INFO Vacuumed table table=multipart_uploads12512026/10/20 08:18:59 INFO Vacuumed table table=closures12522026/10/20 08:18:59 INFO Vacuumed table table=objects12532026/10/20 08:18:59 INFO Received complete push request method=POST path=/api/pushes/2/complete12542026/10/20 08:18:59 INFO Completed push id=2 objects=4 duration=11.604666ms1255--- PASS: TestPush_SkippedKeySurvivesGCBeforeCommit (6.51s)1256=== CONT TestConcurrentCommitsSharingObjectsDoNotDeadlock12572026/10/20 08:18:59 INFO Received push request method=POST path=/api/pushes12582026/10/20 08:18:59 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign12592026/10/20 08:18:59 INFO Signed narinfos id=1 count=112602026/10/20 08:18:59 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign12612026/10/20 08:18:59 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign12622026/10/20 08:18:59 ERROR Failed to sign narinfos signer="index 1" error="signing key cannot be nil"12632026/10/20 08:18:59 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign12642026/10/20 08:18:59 ERROR Failed to sign narinfos signer=niks3-test-1 error="signer failed"12652026/10/20 08:18:59 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign12662026/10/20 08:18:59 ERROR Signer returned unexpected signature count signer=niks3-test-1 got=0 want=112672026/10/20 08:18:59 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign12682026/10/20 08:18:59 ERROR Signer returned unexpected object key signer=niks3-test-1 object_key=unexpected.narinfo1269--- PASS: TestPush_SignsNarinfosOfItsPendingObjects (5.95s)1270=== CONT TestGCMetrics1271=== RUN TestPush_RejectsBadRequests/no_roots1272=== PAUSE TestPush_RejectsBadRequests/no_roots1273=== RUN TestPush_RejectsBadRequests/no_objects1274=== PAUSE TestPush_RejectsBadRequests/no_objects1275=== RUN TestPush_RejectsBadRequests/bad_root1276=== PAUSE TestPush_RejectsBadRequests/bad_root1277=== RUN TestPush_RejectsBadRequests/root_not_in_objects1278=== PAUSE TestPush_RejectsBadRequests/root_not_in_objects1279=== CONT TestLeadElectsOneAndHandsOver1280--- PASS: TestObjectStatsTrigger (7.09s)1281=== CONT TestGetExistingObjectsLocksRows12822026/10/20 08:19:02 INFO Received uploads request method=POST path=/api/pending_closures12832026/10/20 08:19:02 INFO Received uploads request method=POST path=/api/pending_closures12842026/10/20 08:19:02 INFO Received cleanup request method=DELETE path=/api/pending_closures1285=== NAME TestOrphanedObjectsGC1286 orphaned_objects_gc_test.go:287: GC Test Summary:1287 orphaned_objects_gc_test.go:288: - Kept: 2 objects from closure A1288 orphaned_objects_gc_test.go:289: - Deleted: 2 objects from closure B1289 orphaned_objects_gc_test.go:290: - Deleted: 6 orphaned chain objects (X1->X2->X3)1290 orphaned_objects_gc_test.go:291: - Deleted: 2 orphaned single objects (Y)1291 orphaned_objects_gc_test.go:292: - Total deleted: 10 objects1292--- PASS: TestOrphanedObjectsGC (8.17s)1293=== CONT TestGCBugBareHashReferences12942026/10/20 08:19:02 INFO Received uploads request method=POST path=/api/pending_closures1295--- PASS: TestMultipartUploadAbortedWhenCancelledBeforeRecorded (7.13s)1296=== CONT TestConnectWaitsForAPeerMigration12972026/10/20 08:19:03 INFO Received push request method=POST path=/api/pushes12982026/10/20 08:19:03 INFO Received complete push request method=POST path=/api/pushes/1/complete12992026/10/20 08:19:03 INFO Completed push id=1 objects=4 duration=62.674666ms13002026/10/20 08:19:03 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete13012026/10/20 08:19:03 INFO Completed upload id=2 objects=2 duration=1.571041ms1302--- PASS: TestMetricsCommit (7.73s)1303=== CONT TestRegisterCompletedObjectNeedsPendingRow13042026/10/20 08:19:03 INFO Aborted multipart uploads count=0 kept=013052026/10/20 08:19:03 WARN Force mode enabled - objects will be deleted immediately without grace period13062026/10/20 08:19:03 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=013072026/10/20 08:19:04 INFO Vacuumed table table=pending_closures13082026/10/20 08:19:04 INFO Vacuumed table table=pending_objects13092026/10/20 08:19:04 INFO Vacuumed table table=multipart_uploads13102026/10/20 08:19:04 INFO Vacuumed table table=closures13112026/10/20 08:19:04 INFO Vacuumed table table=objects1312--- PASS: TestCommitRacingPendingCleanupKeepsObjects (7.67s)1313=== CONT TestSweepSkipsRowsLockedByPush1314--- PASS: TestMetricsInventory (7.84s)1315=== CONT TestService_ReadAuthMiddleware13162026/10/20 08:19:04 INFO Received uploads request method=POST path=/api/pending_closures13172026/10/20 08:19:04 INFO Received push request method=POST path=/api/pushes1318--- PASS: TestPushWaitsForSweepHoldingRow (8.44s)1319=== CONT TestFailedS3DeleteKeepsTombstone13202026/10/20 08:19:05 INFO Received push request method=POST path=/api/pushes13212026-10-20 08:19:05.370 UTC [96466] ERROR: Push does not exist: id=113222026-10-20 08:19:05.370 UTC [96466] CONTEXT: PL/pgSQL function commit_push(bigint) line 11 at RAISE13232026-10-20 08:19:05.370 UTC [96466] STATEMENT: SELECT commit_push($1)1324--- PASS: TestPush_CompleteWaitsForCleanupOfThePush (8.86s)1325=== CONT TestDeleteClosuresRacingPins13262026-10-20 08:19:05.408 UTC [95741] ERROR: could not obtain lock on row in relation "closures"13272026-10-20 08:19:05.408 UTC [95741] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT13282026-10-20 08:19:05.412 UTC [95741] ERROR: could not obtain lock on row in relation "closures"13292026-10-20 08:19:05.412 UTC [95741] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT13302026-10-20 08:19:05.416 UTC [95741] ERROR: could not obtain lock on row in relation "closures"13312026-10-20 08:19:05.416 UTC [95741] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT13322026-10-20 08:19:05.418 UTC [95741] ERROR: could not obtain lock on row in relation "closures"13332026-10-20 08:19:05.418 UTC [95741] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT13342026-10-20 08:19:05.418 UTC [95741] ERROR: could not obtain lock on row in relation "closures"13352026-10-20 08:19:05.418 UTC [95741] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT1336--- PASS: TestPush_RootsAreLockedInByteOrder (8.83s)1337=== CONT TestForceGCDuringPushOffersSweptObject1338=== RUN TestForceGCDuringPushOffersSweptObject/before_pending_rows1339=== PAUSE TestForceGCDuringPushOffersSweptObject/before_pending_rows1340=== RUN TestForceGCDuringPushOffersSweptObject/after_presence_check1341=== PAUSE TestForceGCDuringPushOffersSweptObject/after_presence_check1342=== CONT TestClientFallsBackToClosures13432026/10/20 08:19:05 WARN mTLS auth: subject not in bound subjects subject="CN=reader"13442026/10/20 08:19:05 WARN mTLS auth: subject not in bound subjects subject="CN=reader"1345--- PASS: TestService_NativeMTLS (8.51s)1346=== CONT TestCreatePendingClosureVerifyS3FailureReleasesConnection13472026/10/20 08:19:06 INFO Received uploads request method=POST path=/api/pending_closures13482026/10/20 08:19:06 INFO Received cleanup request method=DELETE path=/api/pending_closures13492026/10/20 08:19:06 WARN Failed to abort upload, keeping its closure key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst error="Get \"http://127.0.0.1:1/bucket56/?location=\": dial tcp 127.0.0.1:1: connect: connection refused" code=""13502026/10/20 08:19:06 INFO Aborted multipart uploads count=0 kept=113512026/10/20 08:19:06 INFO Received cleanup request method=DELETE path=/api/pending_closures13522026/10/20 08:19:06 INFO Aborted multipart uploads count=1 kept=01353--- PASS: TestMultipartCleanup (9.41s)1354=== CONT TestClientPushesUseOnePush13552026/10/20 08:19:06 INFO Received push request method=POST path=/api/pushes13562026/10/20 08:19:06 INFO Received complete push request method=POST path=/api/pushes/1/complete13572026/10/20 08:19:06 INFO Completed push id=1 objects=4 duration=52.564583ms1358--- PASS: TestPush_RepeatedRootCommitsOnce (9.56s)1359=== CONT TestGCSweepDeliversEachKeyOnce13602026/10/20 08:19:06 ERROR failed to check GC advisory lock error="query pg_locks: failed to connect to `user=_tribuchetbld1 database=niks3`: /nonexistent/.s.PGSQL.5432 (/nonexistent): dial error: dial unix /nonexistent/.s.PGSQL.5432: connect: no such file or directory"1361--- PASS: TestGCAdvisoryLockBlocksConcurrentRun (9.22s)1362=== CONT TestPinProtectsFromGC13632026/10/20 08:19:07 INFO Received uploads request method=POST path=/api/pending_closures13642026/10/20 08:19:07 INFO Aborted multipart uploads count=0 kept=013652026/10/20 08:19:07 WARN Force mode enabled - objects will be deleted immediately without grace period13662026/10/20 08:19:07 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=013672026/10/20 08:19:07 INFO Vacuumed table table=pending_closures13682026/10/20 08:19:07 INFO Vacuumed table table=pending_objects13692026/10/20 08:19:07 INFO Vacuumed table table=multipart_uploads13702026/10/20 08:19:07 INFO Vacuumed table table=closures13712026/10/20 08:19:07 INFO Vacuumed table table=objects13722026/10/20 08:19:07 INFO Received uploads request method=POST path=/api/pending_closures1373--- PASS: TestGCSweepSkipsPendingObjects (9.75s)1374=== CONT TestTombstonedObjectOfferedWithoutWaiting1375--- PASS: TestDeduplicatedObjectsRecordedAsPending (9.39s)1376=== CONT TestService_RequireScope_OIDC13772026/10/20 08:19:07 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:53064/oidc13782026/10/20 08:19:07 INFO lead: acquired remote=192.0.2.1:123413792026/10/20 08:19:08 INFO Aborted multipart uploads count=1 kept=013802026/10/20 08:19:08 INFO Received cleanup request method=DELETE path=/api/pending_closures13812026/10/20 08:19:08 INFO Aborted multipart uploads count=1 kept=01382--- PASS: TestPendingCleanupUsesOneCutoff (13.39s)1383=== CONT TestClientCADerivations13842026/10/20 08:19:08 INFO Received uploads request method=POST path=/api/pending_closures13852026/10/20 08:19:09 INFO Aborted multipart uploads count=0 kept=013862026/10/20 08:19:09 INFO lead: released remote=192.0.2.1:12341387--- PASS: TestLeadEndsOnShutdown (10.41s)1388=== CONT TestService_AuthMiddleware_OIDC13892026/10/20 08:19:09 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=013902026/10/20 08:19:09 INFO Vacuumed table table=pending_closures13912026/10/20 08:19:09 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:53072/oidc13922026/10/20 08:19:09 INFO Vacuumed table table=pending_objects13932026/10/20 08:19:09 INFO Vacuumed table table=multipart_uploads13942026/10/20 08:19:09 INFO Vacuumed table table=closures13952026/10/20 08:19:09 INFO Vacuumed table table=objects13962026/10/20 08:19:09 INFO Aborted multipart uploads count=0 kept=013972026/10/20 08:19:09 WARN Force mode enabled - objects will be deleted immediately without grace period13982026/10/20 08:19:09 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=013992026/10/20 08:19:09 INFO Vacuumed table table=pending_closures14002026/10/20 08:19:09 INFO Vacuumed table table=pending_objects14012026/10/20 08:19:09 INFO Vacuumed table table=multipart_uploads14022026/10/20 08:19:09 INFO lead: acquired remote=192.0.2.1:123414032026/10/20 08:19:09 INFO lead: released remote=192.0.2.1:12341404--- PASS: TestLeadIncumbentAnnouncesAtOnce (10.34s)1405=== CONT TestCacheStatsHandler14062026/10/20 08:19:09 INFO Vacuumed table table=closures14072026/10/20 08:19:09 INFO Vacuumed table table=objects1408--- PASS: TestPushDedupSurvivesConcurrentGC (10.74s)1409=== CONT TestCacheConfigHandler1410=== RUN TestCacheConfigHandler/full_config,_no_issuer1411=== PAUSE TestCacheConfigHandler/full_config,_no_issuer1412=== RUN TestCacheConfigHandler/no_cache_url_configured1413=== PAUSE TestCacheConfigHandler/no_cache_url_configured1414=== RUN TestCacheConfigHandler/no_signing_keys1415=== PAUSE TestCacheConfigHandler/no_signing_keys1416=== RUN TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1417=== PAUSE TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1418=== CONT TestService_ReadScope_PublicByDefault14192026/10/20 08:19:09 INFO Aborted multipart uploads count=0 kept=014202026/10/20 08:19:09 WARN Force mode enabled - objects will be deleted immediately without grace period14212026/10/20 08:19:09 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=014222026/10/20 08:19:09 INFO Vacuumed table table=pending_closures14232026/10/20 08:19:09 INFO Vacuumed table table=pending_objects14242026/10/20 08:19:09 INFO Vacuumed table table=multipart_uploads14252026/10/20 08:19:09 INFO Vacuumed table table=closures14262026/10/20 08:19:09 INFO Vacuumed table table=objects1427--- PASS: TestGCMetrics (10.37s)1428=== CONT TestClientSharedPathCommittedMidPush14292026/10/20 08:19:10 INFO lead: acquired remote=192.0.2.1:12341430--- PASS: TestGetExistingObjectsLocksRows (9.13s)1431=== CONT TestService_AuthMiddleware_MTLSBoundSubjects1432--- PASS: TestConcurrentCommitsSharingObjectsDoNotDeadlock (12.06s)1433=== CONT TestClientMultipleUploads14342026/10/20 08:19:11 INFO lead: released remote=192.0.2.1:123414352026/10/20 08:19:11 INFO lead: acquired remote=192.0.2.1:12341436--- PASS: TestGCBugBareHashReferences (9.31s)1437=== CONT TestClientIntegration1438--- PASS: TestRegisterCompletedObjectNeedsPendingRow (8.60s)1439=== CONT TestService_AuthMiddleware_MTLSProxyHeader14402026/10/20 08:19:12 INFO lead: released remote=192.0.2.1:12341441--- PASS: TestLeadElectsOneAndHandsOver (12.27s)1442=== CONT TestClientWithDependencies14432026/10/20 08:19:12 INFO Aborted multipart uploads count=0 kept=014442026/10/20 08:19:12 WARN Force mode enabled - objects will be deleted immediately without grace period14452026/10/20 08:19:12 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=014462026/10/20 08:19:12 INFO Vacuumed table table=pending_closures14472026/10/20 08:19:12 INFO Vacuumed table table=pending_objects14482026/10/20 08:19:12 INFO Vacuumed table table=multipart_uploads14492026/10/20 08:19:12 INFO Vacuumed table table=closures1450--- PASS: TestConnectWaitsForAPeerMigration (10.13s)1451=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info14522026/10/20 08:19:13 INFO Received uploads request method=POST path=/1453=== CONT TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key14542026/10/20 08:19:13 INFO Received request for more parts method=POST path=/1455=== CONT TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key14562026/10/20 08:19:13 INFO Received complete multipart upload request method=POST path=/1457=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal14582026/10/20 08:19:13 INFO Received uploads request method=POST path=/1459=== CONT TestIsValidUploadKey/narinfo1460=== CONT TestProxyWriteTimeout/narinfo1461=== CONT TestPendingClosureWriteTimeout/empty1462=== CONT TestIsValidUploadKey/unknown_type1463=== CONT TestIsValidUploadKey/empty_key1464=== CONT TestIsValidUploadKey/absolute1465--- PASS: TestUploadHandlersRejectInvalidKeys (0.00s)1466 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info (0.01s)1467 --- PASS: TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key (0.00s)1468 --- PASS: TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key (0.00s)1469 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal (0.00s)1470=== CONT TestIsValidUploadKey/traversal_nar1471=== CONT TestIsValidUploadKey/traversal1472=== CONT TestIsValidUploadKey/listing_key,_narinfo_type1473=== CONT TestIsValidUploadKey/nar_key,_narinfo_type1474=== CONT TestIsValidUploadKey/narinfo_key,_nar_type1475=== CONT TestIsValidUploadKey/index.html1476=== CONT TestIsValidUploadKey/nix-cache-info1477=== CONT TestIsValidUploadKey/realisation_plus_in_output1478=== CONT TestIsValidUploadKey/realisation1479=== CONT TestIsValidUploadKey/build_log_equals1480=== CONT TestIsValidUploadKey/build_log_question_mark1481=== CONT TestIsValidUploadKey/build_log_plus_in_name1482=== CONT TestIsValidUploadKey/build_log_home-manager_file1483=== CONT TestIsValidUploadKey/build_log1484=== CONT TestIsValidUploadKey/listing1485=== CONT TestIsValidUploadKey/nar_plain1486=== CONT TestIsValidUploadKey/nar_xz1487=== CONT TestIsValidUploadKey/nar_zst1488--- PASS: TestIsValidUploadKey (0.06s)1489 --- PASS: TestIsValidUploadKey/narinfo (0.00s)1490 --- PASS: TestIsValidUploadKey/unknown_type (0.00s)1491 --- PASS: TestIsValidUploadKey/empty_key (0.00s)1492 --- PASS: TestIsValidUploadKey/absolute (0.00s)1493 --- PASS: TestIsValidUploadKey/traversal_nar (0.00s)1494 --- PASS: TestIsValidUploadKey/traversal (0.00s)1495 --- PASS: TestIsValidUploadKey/listing_key,_narinfo_type (0.00s)1496 --- PASS: TestIsValidUploadKey/nar_key,_narinfo_type (0.00s)1497 --- PASS: TestIsValidUploadKey/narinfo_key,_nar_type (0.00s)1498 --- PASS: TestIsValidUploadKey/index.html (0.00s)1499 --- PASS: TestIsValidUploadKey/nix-cache-info (0.00s)1500 --- PASS: TestIsValidUploadKey/realisation_plus_in_output (0.00s)1501 --- PASS: TestIsValidUploadKey/realisation (0.00s)1502 --- PASS: TestIsValidUploadKey/build_log_equals (0.00s)1503 --- PASS: TestIsValidUploadKey/build_log_question_mark (0.00s)1504 --- PASS: TestIsValidUploadKey/build_log_plus_in_name (0.00s)1505 --- PASS: TestIsValidUploadKey/build_log_home-manager_file (0.00s)1506 --- PASS: TestIsValidUploadKey/build_log (0.00s)1507 --- PASS: TestIsValidUploadKey/listing (0.00s)1508 --- PASS: TestIsValidUploadKey/nar_plain (0.00s)1509 --- PASS: TestIsValidUploadKey/nar_xz (0.00s)1510 --- PASS: TestIsValidUploadKey/nar_zst (0.00s)1511=== CONT TestProxyWriteTimeout/10_GiB_nar1512=== CONT TestProxyWriteTimeout/unknown_size1513=== CONT TestPendingClosureWriteTimeout/670k_objects1514=== CONT TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline15152026/10/20 08:19:13 INFO Vacuumed table table=objects15162026/10/20 08:19:13 INFO Aborted multipart uploads count=0 kept=015172026/10/20 08:19:13 WARN Force mode enabled - objects will be deleted immediately without grace period15182026/10/20 08:19:13 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=015192026/10/20 08:19:13 INFO Vacuumed table table=pending_closures15202026/10/20 08:19:13 INFO Vacuumed table table=pending_objects1521--- PASS: TestService_ReadAuthMiddleware (8.98s)15222026/10/20 08:19:13 INFO Vacuumed table table=multipart_uploads1523=== CONT TestPendingClosureWriteTimeout/400_objects1524=== CONT TestProxyWriteTimeout/1_GiB_nar15252026/10/20 08:19:13 INFO Vacuumed table table=closures1526=== CONT TestUploadHandlersRejectOversizedBody/request_more_parts15272026/10/20 08:19:13 INFO Received request for more parts method=POST path=/1528--- PASS: TestProxyWriteTimeout (0.05s)1529 --- PASS: TestProxyWriteTimeout/narinfo (0.00s)1530 --- PASS: TestProxyWriteTimeout/10_GiB_nar (0.00s)1531 --- PASS: TestProxyWriteTimeout/unknown_size (0.00s)1532 --- PASS: TestProxyWriteTimeout/1_GiB_nar (0.00s)15332026/10/20 08:19:13 INFO Vacuumed table table=objects1534--- PASS: TestSweepSkipsRowsLockedByPush (9.05s)1535=== CONT TestUploadHandlersRejectOversizedBody/complete_multipart15362026/10/20 08:19:13 INFO Received complete multipart upload request method=POST path=/1537=== CONT TestUploadHandlersRejectOversizedBody/create_pending_closure15382026/10/20 08:19:13 INFO Received uploads request method=POST path=/1539=== CONT TestIsValidCachePath/narinfo1540=== CONT TestIsValidCachePath/index.html1541=== CONT TestIsValidCachePath/short_hash1542=== CONT TestIsValidCachePath/wrong_extension1543=== CONT TestIsValidCachePath/leading_slash1544=== CONT TestIsValidCachePath/empty1545=== CONT TestIsValidCachePath/random_path1546=== CONT TestIsValidCachePath/invalid_char_u1547=== CONT TestIsValidCachePath/invalid_char_e1548=== CONT TestIsValidCachePath/traversal_in_middle1549=== CONT TestIsValidCachePath/traversal_parent1550=== CONT TestIsValidCachePath/nar_uncompressed1551=== CONT TestIsValidCachePath/nix-cache-info1552=== CONT TestIsValidCachePath/realisation1553=== CONT TestIsValidCachePath/log1554=== CONT TestIsValidCachePath/ls1555=== CONT TestIsValidCachePath/nar_xz1556=== CONT TestIsValidCachePath/nar_bz21557=== CONT TestIsValidCachePath/nar_zst1558=== CONT TestIsValidCachePath/narinfo_all_nix_base32_chars1559--- PASS: TestIsValidCachePath (0.00s)1560 --- PASS: TestIsValidCachePath/narinfo (0.00s)1561 --- PASS: TestIsValidCachePath/index.html (0.00s)1562 --- PASS: TestIsValidCachePath/short_hash (0.00s)1563 --- PASS: TestIsValidCachePath/wrong_extension (0.00s)1564 --- PASS: TestIsValidCachePath/leading_slash (0.00s)1565 --- PASS: TestIsValidCachePath/empty (0.00s)1566 --- PASS: TestIsValidCachePath/random_path (0.00s)1567 --- PASS: TestIsValidCachePath/invalid_char_u (0.00s)1568 --- PASS: TestIsValidCachePath/invalid_char_e (0.00s)1569 --- PASS: TestIsValidCachePath/traversal_in_middle (0.00s)1570 --- PASS: TestIsValidCachePath/traversal_parent (0.00s)1571 --- PASS: TestIsValidCachePath/nar_uncompressed (0.00s)1572 --- PASS: TestIsValidCachePath/nix-cache-info (0.00s)1573 --- PASS: TestIsValidCachePath/realisation (0.00s)1574 --- PASS: TestIsValidCachePath/log (0.00s)1575 --- PASS: TestIsValidCachePath/ls (0.00s)1576 --- PASS: TestIsValidCachePath/nar_xz (0.00s)1577 --- PASS: TestIsValidCachePath/nar_bz2 (0.00s)1578 --- PASS: TestIsValidCachePath/nar_zst (0.00s)1579 --- PASS: TestIsValidCachePath/narinfo_all_nix_base32_chars (0.00s)1580=== CONT TestParseSingleRange/none1581=== CONT TestParseSingleRange/open-ended1582=== CONT TestParseSingleRange/start_far_past_EOF1583=== CONT TestParseSingleRange/start_past_EOF1584=== CONT TestParseSingleRange/single_byte1585=== CONT TestParseSingleRange/suffix_exceeds_size1586=== CONT TestParseSingleRange/suffix1587=== CONT TestParseSingleRange/end_clamped_to_size1588=== CONT TestParseSingleRange/malformed_both_empty1589=== CONT TestParseSingleRange/closed1590=== CONT TestParseSingleRange/malformed_end_before_start1591=== CONT TestParseSingleRange/multi-range_ignored1592=== CONT TestParseSingleRange/malformed_no_dash1593=== CONT TestParseSingleRange/unknown_unit1594--- PASS: TestParseSingleRange (0.00s)1595 --- PASS: TestParseSingleRange/none (0.00s)1596 --- PASS: TestParseSingleRange/open-ended (0.00s)1597 --- PASS: TestParseSingleRange/start_far_past_EOF (0.00s)1598 --- PASS: TestParseSingleRange/start_past_EOF (0.00s)1599 --- PASS: TestParseSingleRange/single_byte (0.00s)1600 --- PASS: TestParseSingleRange/suffix_exceeds_size (0.00s)1601 --- PASS: TestParseSingleRange/suffix (0.00s)1602 --- PASS: TestParseSingleRange/end_clamped_to_size (0.00s)1603 --- PASS: TestParseSingleRange/malformed_both_empty (0.00s)1604 --- PASS: TestParseSingleRange/closed (0.00s)1605 --- PASS: TestParseSingleRange/malformed_end_before_start (0.00s)1606 --- PASS: TestParseSingleRange/multi-range_ignored (0.00s)1607 --- PASS: TestParseSingleRange/malformed_no_dash (0.00s)1608 --- PASS: TestParseSingleRange/unknown_unit (0.00s)1609=== CONT TestPresentNotReportedWhileGCDeletesClosure/stale1610--- PASS: TestUploadHandlersRejectOversizedBody (0.08s)1611 --- PASS: TestUploadHandlersRejectOversizedBody/request_more_parts (0.02s)1612 --- PASS: TestUploadHandlersRejectOversizedBody/complete_multipart (0.02s)1613 --- PASS: TestUploadHandlersRejectOversizedBody/create_pending_closure (0.30s)1614=== CONT TestPresentNotReportedWhileGCDeletesClosure/fresh16152026/10/20 08:19:13 INFO Received uploads request method=POST path=/api/pending_closures16162026/10/20 08:19:14 INFO Aborted multipart uploads count=0 kept=016172026/10/20 08:19:14 WARN Force mode enabled - objects will be deleted immediately without grace period16182026/10/20 08:19:14 ERROR failed to remove object object=nar/dddddddddddddddddddddddddddddddddddddddddddddddddddd.nar.zst error="Access Denied."16192026/10/20 08:19:14 ERROR failed to remove object object=dddddddddddddddddddddddddddddddd.narinfo error="Access Denied."1620--- PASS: TestFailedS3DeleteKeepsTombstone (9.16s)1621=== CONT TestGCEndsOnShutdown/before_the_run16222026/10/20 08:19:15 INFO Received uploads request method=POST path=/api/pending_closures16232026/10/20 08:19:15 INFO Received uploads request method=POST path=/api/pending_closures16242026/10/20 08:19:15 INFO Received uploads request method=POST path=/api/pending_closures16252026/10/20 08:19:15 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)16262026/10/20 08:19:15 INFO Uploading k44992ra3fzfhz0bhd8mnhw5kximzrj7-a (256B)16272026/10/20 08:19:15 INFO Uploading hdflcpw1hcvrnljrpaln10z7lxx29jim-shared-dep (136B)1628--- PASS: TestCreatePendingClosureVerifyS3FailureReleasesConnection (9.70s)1629=== CONT TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark16302026/10/20 08:19:15 WARN Failed to register uploaded object key=mghv44s29dvif503vh56npmn9rbfzd35.ls error="server returned 404: 404 page not found\n"16312026/10/20 08:19:15 WARN Failed to register uploaded object key=k44992ra3fzfhz0bhd8mnhw5kximzrj7.ls error="server returned 404: 404 page not found\n"16322026/10/20 08:19:15 WARN Failed to register uploaded object key=nar/0m1kml76ddnjklwf224i2hg1msjms87ibmhqy9byc9wr8q23nfvl.nar.zst error="server returned 404: 404 page not found\n"16332026/10/20 08:19:15 WARN Failed to register uploaded object key=hdflcpw1hcvrnljrpaln10z7lxx29jim.ls error="server returned 404: 404 page not found\n"16342026/10/20 08:19:15 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign16352026/10/20 08:19:15 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"16362026/10/20 08:19:15 INFO Signed narinfos id=1 count=216372026/10/20 08:19:15 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign16382026/10/20 08:19:15 INFO Signed narinfos id=2 count=216392026/10/20 08:19:15 INFO Uploading 4 narinfos16402026/10/20 08:19:15 WARN Failed to register uploaded object key=mghv44s29dvif503vh56npmn9rbfzd35.narinfo error="server returned 404: 404 page not found\n"16412026/10/20 08:19:15 WARN Failed to register uploaded object key=k44992ra3fzfhz0bhd8mnhw5kximzrj7.narinfo error="server returned 404: 404 page not found\n"16422026/10/20 08:19:15 WARN Failed to register uploaded object key=hdflcpw1hcvrnljrpaln10z7lxx29jim.narinfo error="server returned 404: 404 page not found\n"16432026/10/20 08:19:15 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete16442026/10/20 08:19:15 WARN Failed to register uploaded object key=hdflcpw1hcvrnljrpaln10z7lxx29jim.narinfo error="server returned 404: 404 page not found\n"16452026/10/20 08:19:15 INFO Completed upload id=2 objects=6 duration=39.919417ms16462026/10/20 08:19:15 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete16472026/10/20 08:19:15 INFO Completed upload id=1 objects=6 duration=714.625µs16482026/10/20 08:19:15 INFO Upload complete. (523ms)1649=== NAME TestClientFallsBackToClosures1650 client_pushes_test.go:112: Retrieved narinfo from S3:1651 StorePath: /private/var/tb/1/scratch/c8b5f9203adb9a1c/build/TestClientFallsBackToClosures1174877914/001/store/hdflcpw1hcvrnljrpaln10z7lxx29jim-shared-dep1652 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1653 Compression: zstd1654 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821655 NarSize: 1361656 References: 1657 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1658 client_pushes_test.go:112: Retrieved narinfo from S3:1659 StorePath: /private/var/tb/1/scratch/c8b5f9203adb9a1c/build/TestClientFallsBackToClosures1174877914/001/store/k44992ra3fzfhz0bhd8mnhw5kximzrj7-a1660 URL: nar/0m1kml76ddnjklwf224i2hg1msjms87ibmhqy9byc9wr8q23nfvl.nar.zst1661 Compression: zstd1662 NarHash: sha256:0m1kml76ddnjklwf224i2hg1msjms87ibmhqy9byc9wr8q23nfvl1663 NarSize: 2561664 References: /private/var/tb/1/scratch/c8b5f9203adb9a1c/build/TestClientFallsBackToClosures1174877914/001/store/hdflcpw1hcvrnljrpaln10z7lxx29jim-shared-dep1665 CA: text:sha256:1nka923nrgdpy9jn31z9p6hh50zj4my24s81crrh6fj20z0zi8c41666 client_pushes_test.go:112: Retrieved narinfo from S3:1667 StorePath: /private/var/tb/1/scratch/c8b5f9203adb9a1c/build/TestClientFallsBackToClosures1174877914/001/store/mghv44s29dvif503vh56npmn9rbfzd35-b1668 URL: nar/0m1kml76ddnjklwf224i2hg1msjms87ibmhqy9byc9wr8q23nfvl.nar.zst1669 Compression: zstd1670 NarHash: sha256:0m1kml76ddnjklwf224i2hg1msjms87ibmhqy9byc9wr8q23nfvl1671 NarSize: 2561672 References: /private/var/tb/1/scratch/c8b5f9203adb9a1c/build/TestClientFallsBackToClosures1174877914/001/store/hdflcpw1hcvrnljrpaln10z7lxx29jim-shared-dep1673 CA: text:sha256:1nka923nrgdpy9jn31z9p6hh50zj4my24s81crrh6fj20z0zi8c41674--- PASS: TestClientFallsBackToClosures (10.46s)1675=== CONT TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete16762026/10/20 08:19:16 INFO Aborted multipart uploads count=0 kept=016772026/10/20 08:19:16 WARN Force mode enabled - objects will be deleted immediately without grace period16782026/10/20 08:19:16 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=016792026/10/20 08:19:16 INFO Vacuumed table table=pending_closures16802026/10/20 08:19:16 INFO Vacuumed table table=pending_objects16812026/10/20 08:19:16 INFO Vacuumed table table=multipart_uploads16822026/10/20 08:19:16 INFO Vacuumed table table=closures16832026/10/20 08:19:16 INFO Vacuumed table table=objects1684--- PASS: TestGCSweepDeliversEachKeyOnce (9.74s)1685=== CONT TestServerTLSConfig/no_client_CA1686=== CONT TestServerTLSConfig/not_a_PEM_file1687=== CONT TestServerTLSConfig/missing_CA_file1688=== CONT TestResolveDBConnectionString/flag_wins1689=== CONT TestResolveDBConnectionString/PGHOST_allows_empty1690=== CONT TestResolveDBConnectionString/nothing_configured1691--- PASS: TestServerTLSConfig (0.00s)1692 --- PASS: TestServerTLSConfig/no_client_CA (0.00s)1693 --- PASS: TestServerTLSConfig/not_a_PEM_file (0.03s)1694 --- PASS: TestServerTLSConfig/missing_CA_file (0.00s)1695=== CONT TestResolveDBConnectionString/missing_file_is_an_error1696=== CONT TestResolveDBConnectionString/file_when_flag_empty1697=== CONT TestClientErrorHandling/InvalidStorePath1698--- PASS: TestResolveDBConnectionString (0.04s)1699 --- PASS: TestResolveDBConnectionString/flag_wins (0.00s)1700 --- PASS: TestResolveDBConnectionString/PGHOST_allows_empty (0.00s)1701 --- PASS: TestResolveDBConnectionString/nothing_configured (0.00s)1702 --- PASS: TestResolveDBConnectionString/missing_file_is_an_error (0.00s)1703 --- PASS: TestResolveDBConnectionString/file_when_flag_empty (0.00s)17042026/10/20 08:19:16 INFO Received push request method=POST path=/api/pushes17052026/10/20 08:19:16 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)17062026/10/20 08:19:16 INFO Uploading y548jyh55dfa2avi95k0c914qxk2p8ng-b (256B)17072026/10/20 08:19:16 INFO Uploading 0mnbxw5k7pj3i8yni36qwpbnaj6dxdv2-shared-dep (136B)17082026/10/20 08:19:16 WARN Failed to register uploaded object key=37xlah2dalmjhwjjpcxys7cimq7f67na.ls error="server returned 404: 404 page not found\n"17092026/10/20 08:19:16 WARN Failed to register uploaded object key=nar/1752dp8j7bjsd42ga9qb77vkk2l8mfl5645c8lw61amxlvm1lssg.nar.zst error="server returned 404: 404 page not found\n"17102026/10/20 08:19:16 WARN Failed to register uploaded object key=0mnbxw5k7pj3i8yni36qwpbnaj6dxdv2.ls error="server returned 404: 404 page not found\n"17112026/10/20 08:19:16 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"17122026/10/20 08:19:16 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign17132026/10/20 08:19:16 WARN Failed to register uploaded object key=y548jyh55dfa2avi95k0c914qxk2p8ng.ls error="server returned 404: 404 page not found\n"17142026/10/20 08:19:16 INFO Signed narinfos id=1 count=317152026/10/20 08:19:16 INFO Uploading 3 narinfos1716=== NAME TestOrphanedObjectsGCStressTest1717 orphaned_objects_gc_test.go:422: Created 10 active closures, 5 to-delete closures, 20 orphaned chains17182026/10/20 08:19:16 WARN Failed to register uploaded object key=37xlah2dalmjhwjjpcxys7cimq7f67na.narinfo error="server returned 404: 404 page not found\n"17192026/10/20 08:19:16 WARN Failed to register uploaded object key=y548jyh55dfa2avi95k0c914qxk2p8ng.narinfo error="server returned 404: 404 page not found\n"17202026/10/20 08:19:16 INFO Received complete push request method=POST path=/api/pushes/1/complete17212026/10/20 08:19:16 WARN Failed to register uploaded object key=0mnbxw5k7pj3i8yni36qwpbnaj6dxdv2.narinfo error="server returned 404: 404 page not found\n"17222026/10/20 08:19:16 INFO Completed push id=1 objects=8 duration=8.556833ms17232026/10/20 08:19:16 INFO Upload complete. (369ms)1724 orphaned_objects_gc_test.go:440: Marked 210 objects for deletion1725=== NAME TestClientPushesUseOnePush1726 client_pushes_test.go:97: Retrieved narinfo from S3:1727 StorePath: /private/var/tb/1/scratch/c8b5f9203adb9a1c/build/TestClientPushesUseOnePush3211298225/001/store/0mnbxw5k7pj3i8yni36qwpbnaj6dxdv2-shared-dep1728 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1729 Compression: zstd1730 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821731 NarSize: 1361732 References: 1733 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1734 client_pushes_test.go:97: Retrieved narinfo from S3:1735 StorePath: /private/var/tb/1/scratch/c8b5f9203adb9a1c/build/TestClientPushesUseOnePush3211298225/001/store/37xlah2dalmjhwjjpcxys7cimq7f67na-a1736 URL: nar/1752dp8j7bjsd42ga9qb77vkk2l8mfl5645c8lw61amxlvm1lssg.nar.zst1737 Compression: zstd1738 NarHash: sha256:1752dp8j7bjsd42ga9qb77vkk2l8mfl5645c8lw61amxlvm1lssg1739 NarSize: 2561740 References: /private/var/tb/1/scratch/c8b5f9203adb9a1c/build/TestClientPushesUseOnePush3211298225/001/store/0mnbxw5k7pj3i8yni36qwpbnaj6dxdv2-shared-dep1741 CA: text:sha256:1s05w1myvrradfylkcclp4yc5915cmzhfdc777cjc2lf3z5i68l91742 client_pushes_test.go:97: Retrieved narinfo from S3:1743 StorePath: /private/var/tb/1/scratch/c8b5f9203adb9a1c/build/TestClientPushesUseOnePush3211298225/001/store/y548jyh55dfa2avi95k0c914qxk2p8ng-b1744 URL: nar/1752dp8j7bjsd42ga9qb77vkk2l8mfl5645c8lw61amxlvm1lssg.nar.zst1745 Compression: zstd1746 NarHash: sha256:1752dp8j7bjsd42ga9qb77vkk2l8mfl5645c8lw61amxlvm1lssg1747 NarSize: 2561748 References: /private/var/tb/1/scratch/c8b5f9203adb9a1c/build/TestClientPushesUseOnePush3211298225/001/store/0mnbxw5k7pj3i8yni36qwpbnaj6dxdv2-shared-dep1749 CA: text:sha256:1s05w1myvrradfylkcclp4yc5915cmzhfdc777cjc2lf3z5i68l91750--- PASS: TestClientPushesUseOnePush (10.52s)1751=== CONT TestClientErrorHandling/ServerNotAvailable1752=== NAME TestPinProtectsFromGC1753 client_integration_test.go:731: Pinned store path: /private/var/tb/1/scratch/c8b5f9203adb9a1c/build/TestPinProtectsFromGC624871103/001/store/3dlb5bk96h1v73ky7z6z8hcsi21kbfdb-pinned-file.txt1754 client_integration_test.go:732: Unpinned store path: /private/var/tb/1/scratch/c8b5f9203adb9a1c/build/TestPinProtectsFromGC624871103/001/store/270hlhp76b96ks7hk6l1fchpip8h7r4r-unpinned-file.txt17552026/10/20 08:19:16 INFO Received push request method=POST path=/api/pushes17562026/10/20 08:19:17 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present17572026/10/20 08:19:17 INFO Received uploads request method=POST path=/api/pending_closures17582026/10/20 08:19:17 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)17592026/10/20 08:19:17 INFO Uploading 3dlb5bk96h1v73ky7z6z8hcsi21kbfdb-pinned-file.txt (128B)1760=== NAME TestObjectStatsLargeCommit1761 object_stats_test.go:99: committing 60000 objects took 9.393566125s1762--- FAIL: TestObjectStatsLargeCommit (22.57s)1763=== CONT TestClientErrorHandling/InvalidAuthToken1764--- PASS: TestTombstonedObjectOfferedWithoutWaiting (9.39s)1765=== CONT TestPush_RejectsBadRequests/no_roots17662026/10/20 08:19:17 INFO Received push request method=POST path=/api/pushes1767=== CONT TestPush_RejectsBadRequests/bad_root17682026/10/20 08:19:17 INFO Received push request method=POST path=/api/pushes1769=== CONT TestPush_RejectsBadRequests/root_not_in_objects17702026/10/20 08:19:17 INFO Received push request method=POST path=/api/pushes1771=== CONT TestPush_RejectsBadRequests/no_objects17722026/10/20 08:19:17 INFO Received push request method=POST path=/api/pushes1773=== CONT TestForceGCDuringPushOffersSweptObject/before_pending_rows1774--- PASS: TestPush_RejectsBadRequests (6.22s)1775 --- PASS: TestPush_RejectsBadRequests/no_roots (0.00s)1776 --- PASS: TestPush_RejectsBadRequests/bad_root (0.00s)1777 --- PASS: TestPush_RejectsBadRequests/root_not_in_objects (0.00s)1778 --- PASS: TestPush_RejectsBadRequests/no_objects (0.00s)17792026/10/20 08:19:17 WARN Failed to register uploaded object key=nar/0qmhsg42pqsz7x6hh02j8gznnac3yi3qpjhrqbwvz88i194jbb5s.nar.zst error="server returned 404: 404 page not found\n"17802026/10/20 08:19:17 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign17812026/10/20 08:19:17 WARN Failed to register uploaded object key=3dlb5bk96h1v73ky7z6z8hcsi21kbfdb.ls error="server returned 404: 404 page not found\n"17822026/10/20 08:19:17 INFO Signed narinfos id=1 count=117832026/10/20 08:19:17 INFO Uploading 1 narinfos17842026/10/20 08:19:17 WARN Request failed, retrying attempt=2 backoff=210.258926ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present17852026/10/20 08:19:17 INFO Received complete push request method=POST path=/api/pushes/1/complete17862026/10/20 08:19:17 WARN Failed to register uploaded object key=3dlb5bk96h1v73ky7z6z8hcsi21kbfdb.narinfo error="server returned 404: 404 page not found\n"17872026/10/20 08:19:17 INFO Completed push id=1 objects=3 duration=14.829ms17882026/10/20 08:19:17 INFO Upload complete. (254ms)1789=== NAME TestClientCADerivations1790 client_ca_test.go:136: Built CA derivation: /private/var/tb/1/scratch/c8b5f9203adb9a1c/build/TestClientCADerivations258420365/001/store/0wgb3hhx5557pyaj066vv0gfwp47858q-ca-test1791 client_ca_test.go:139: Found 1 dependencies (including self)1792=== RUN TestService_RequireScope_OIDC/builder_may_write1793=== PAUSE TestService_RequireScope_OIDC/builder_may_write1794=== RUN TestService_RequireScope_OIDC/builder_may_not_admin1795=== PAUSE TestService_RequireScope_OIDC/builder_may_not_admin17962026/10/20 08:19:17 INFO Received push request method=POST path=/api/pushes1797=== RUN TestService_RequireScope_OIDC/ops_may_admin17982026/10/20 08:19:17 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)1799=== PAUSE TestService_RequireScope_OIDC/ops_may_admin18002026/10/20 08:19:17 INFO Uploading 270hlhp76b96ks7hk6l1fchpip8h7r4r-unpinned-file.txt (128B)1801=== RUN TestService_RequireScope_OIDC/ops_may_not_write1802=== PAUSE TestService_RequireScope_OIDC/ops_may_not_write1803=== RUN TestService_RequireScope_OIDC/reader_may_not_write1804=== PAUSE TestService_RequireScope_OIDC/reader_may_not_write1805=== RUN TestService_RequireScope_OIDC/static_token_may_admin1806=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin1807=== RUN TestService_RequireScope_OIDC/static_token_may_write1808=== PAUSE TestService_RequireScope_OIDC/static_token_may_write1809=== RUN TestService_RequireScope_OIDC/reader_may_read1810=== PAUSE TestService_RequireScope_OIDC/reader_may_read1811=== RUN TestService_RequireScope_OIDC/writer_implies_read1812=== PAUSE TestService_RequireScope_OIDC/writer_implies_read1813=== RUN TestService_RequireScope_OIDC/anonymous_may_not_read1814=== PAUSE TestService_RequireScope_OIDC/anonymous_may_not_read1815=== RUN TestService_RequireScope_OIDC/reader_may_read_with_netrc1816=== PAUSE TestService_RequireScope_OIDC/reader_may_read_with_netrc1817=== RUN TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1818=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1819=== RUN TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read1820=== PAUSE TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read1821=== RUN TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1822=== PAUSE TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1823=== CONT TestForceGCDuringPushOffersSweptObject/after_presence_check18242026/10/20 08:19:17 WARN Failed to register uploaded object key=270hlhp76b96ks7hk6l1fchpip8h7r4r.ls error="server returned 404: 404 page not found\n"18252026/10/20 08:19:17 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign18262026/10/20 08:19:17 WARN Failed to register uploaded object key=nar/0gh0wdnr6gmk4r5sfzzh12isnl14rgmkrwy1ws41hpsrlndclg5h.nar.zst error="server returned 404: 404 page not found\n"18272026/10/20 08:19:17 INFO Signed narinfos id=2 count=118282026/10/20 08:19:17 INFO Uploading 1 narinfos18292026/10/20 08:19:17 WARN Request failed, retrying attempt=3 backoff=378.507038ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present18302026/10/20 08:19:17 INFO Received complete push request method=POST path=/api/pushes/2/complete18312026/10/20 08:19:17 WARN Failed to register uploaded object key=270hlhp76b96ks7hk6l1fchpip8h7r4r.narinfo error="server returned 404: 404 page not found\n"18322026/10/20 08:19:17 INFO Completed push id=2 objects=3 duration=1.292333ms18332026/10/20 08:19:17 INFO Upload complete. (155ms)18342026/10/20 08:19:17 INFO Received push request method=POST path=/api/pushes18352026/10/20 08:19:17 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)18362026/10/20 08:19:17 INFO Uploading 0wgb3hhx5557pyaj066vv0gfwp47858q-ca-test (144B)18372026/10/20 08:19:17 INFO Starting cleanup of old closures method=DELETE path=/api/closures18382026/10/20 08:19:17 INFO Garbage collection started18392026/10/20 08:19:17 INFO Aborted multipart uploads count=0 kept=018402026/10/20 08:19:17 WARN Force mode enabled - objects will be deleted immediately without grace period18412026/10/20 08:19:17 WARN Failed to register uploaded object key=0wgb3hhx5557pyaj066vv0gfwp47858q.ls error="server returned 404: 404 page not found\n"18422026/10/20 08:19:17 WARN Failed to register uploaded object key=nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst error="server returned 404: 404 page not found\n"18432026/10/20 08:19:17 WARN Failed to register uploaded object key=log/yny9mz42afv0djlpk0aa056nwa5x6vp1-ca-test.drv error="server returned 404: 404 page not found\n"18442026/10/20 08:19:17 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign18452026/10/20 08:19:17 INFO Signed narinfos id=1 count=118462026/10/20 08:19:17 INFO Uploading 1 narinfos1847=== RUN TestService_AuthMiddleware_OIDC/valid_OIDC_token1848=== PAUSE TestService_AuthMiddleware_OIDC/valid_OIDC_token1849=== RUN TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1850=== PAUSE TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1851=== RUN TestService_AuthMiddleware_OIDC/malformed_token_rejected1852=== PAUSE TestService_AuthMiddleware_OIDC/malformed_token_rejected1853=== RUN TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1854=== PAUSE TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1855=== CONT TestCacheConfigHandler/full_config,_no_issuer1856=== CONT TestCacheConfigHandler/no_signing_keys18572026/10/20 08:19:17 INFO Received complete push request method=POST path=/api/pushes/1/complete18582026/10/20 08:19:17 WARN Failed to register uploaded object key=0wgb3hhx5557pyaj066vv0gfwp47858q.narinfo error="server returned 404: 404 page not found\n"1859=== CONT TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1860=== CONT TestCacheConfigHandler/no_cache_url_configured1861--- PASS: TestCacheConfigHandler (0.00s)1862 --- PASS: TestCacheConfigHandler/full_config,_no_issuer (0.00s)1863 --- PASS: TestCacheConfigHandler/no_signing_keys (0.00s)1864 --- PASS: TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator (0.00s)1865 --- PASS: TestCacheConfigHandler/no_cache_url_configured (0.00s)1866=== CONT TestService_RequireScope_OIDC/builder_may_write18672026/10/20 08:19:17 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=1 objects-marked-for-deletion=3 objects-deleted-after-grace-period=3 objects-failed-to-delete=01868=== CONT TestService_RequireScope_OIDC/reader_may_read1869=== CONT TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1870=== CONT TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read18712026/10/20 08:19:17 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]1872=== CONT TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1873=== CONT TestService_RequireScope_OIDC/reader_may_read_with_netrc1874=== CONT TestService_RequireScope_OIDC/anonymous_may_not_read1875=== CONT TestService_RequireScope_OIDC/writer_implies_read1876=== CONT TestService_RequireScope_OIDC/reader_may_not_write1877=== CONT TestService_RequireScope_OIDC/static_token_may_write18782026/10/20 08:19:17 INFO Completed push id=1 objects=4 duration=32.1755ms1879=== CONT TestService_RequireScope_OIDC/static_token_may_admin1880=== CONT TestService_RequireScope_OIDC/ops_may_admin18812026/10/20 08:19:17 INFO Upload complete. (276ms)1882=== CONT TestService_RequireScope_OIDC/ops_may_not_write1883=== CONT TestService_RequireScope_OIDC/builder_may_not_admin1884=== CONT TestService_AuthMiddleware_OIDC/valid_OIDC_token1885=== NAME TestClientCADerivations1886 client_ca_test.go:180: Narinfo contains CA field: StorePath: /private/var/tb/1/scratch/c8b5f9203adb9a1c/build/TestClientCADerivations258420365/001/store/0wgb3hhx5557pyaj066vv0gfwp47858q-ca-test1887 URL: nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst1888 Compression: zstd1889 NarHash: sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1890 NarSize: 1441891 References: 1892 Deriver: /private/var/tb/1/scratch/c8b5f9203adb9a1c/build/TestClientCADerivations258420365/001/store/yny9mz42afv0djlpk0aa056nwa5x6vp1-ca-test.drv1893 CA: fixed:r:sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1894 client_ca_test.go:185: Checking for realisation files in S3...1895 client_ca_test.go:207: No realisation files uploaded - this is expected for locally built CA derivations1896 client_ca_test.go:208: Locally built CA derivations don't have DrvOutput IDs until they're substituted from a cache1897--- PASS: TestService_RequireScope_OIDC (9.57s)1898 --- PASS: TestService_RequireScope_OIDC/builder_may_write (0.00s)1899 --- PASS: TestService_RequireScope_OIDC/reader_may_read (0.00s)1900 --- PASS: TestService_RequireScope_OIDC/empty_netrc_password_may_not_read (0.00s)1901 --- PASS: TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read (0.01s)1902 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin_with_netrc (0.00s)1903 --- PASS: TestService_RequireScope_OIDC/reader_may_read_with_netrc (0.00s)1904 --- PASS: TestService_RequireScope_OIDC/anonymous_may_not_read (0.00s)1905 --- PASS: TestService_RequireScope_OIDC/writer_implies_read (0.00s)1906 --- PASS: TestService_RequireScope_OIDC/reader_may_not_write (0.00s)1907 --- PASS: TestService_RequireScope_OIDC/static_token_may_write (0.00s)1908 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin (0.00s)1909 --- PASS: TestService_RequireScope_OIDC/ops_may_admin (0.00s)1910 --- PASS: TestService_RequireScope_OIDC/ops_may_not_write (0.00s)1911 --- PASS: TestService_RequireScope_OIDC/builder_may_not_admin (0.00s)1912=== CONT TestService_AuthMiddleware_OIDC/malformed_token_rejected19132026/10/20 08:19:17 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]1914=== CONT TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1915=== CONT TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected19162026/10/20 08:19:17 INFO Vacuumed table table=pending_closures19172026/10/20 08:19:17 WARN Authentication failed token_preview=eyJhbGciOi...UQ0tcXTSjA token_length=701 oidc_error="no rule matched: claim \"repository_owner\" value [otherorg] not in allowed patterns [myorg]" oidc_provider=test tried_providers=[test]1918--- PASS: TestService_AuthMiddleware_OIDC (8.49s)1919 --- PASS: TestService_AuthMiddleware_OIDC/valid_OIDC_token (0.00s)1920 --- PASS: TestService_AuthMiddleware_OIDC/malformed_token_rejected (0.00s)1921 --- PASS: TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured (0.00s)1922 --- PASS: TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected (0.00s)19232026/10/20 08:19:17 INFO Vacuumed table table=pending_objects19242026/10/20 08:19:17 INFO Vacuumed table table=multipart_uploads19252026/10/20 08:19:17 INFO Vacuumed table table=closures19262026/10/20 08:19:17 INFO Vacuumed table table=objects1927=== NAME TestClientCADerivations1928 client_ca_test.go:258: nix copy output: error: binary cache 's3://bucket79?endpoint=http://localhost:52759®ion=eu-west-1' is for Nix stores with prefix '/nix/store', not '/private/var/tb/1/scratch/c8b5f9203adb9a1c/build/TestClientCADerivations258420365/001/store'1929 client_ca_test.go:259: nix copy failed (might be expected with isolated stores): exit status 11930--- PASS: TestClientCADerivations (9.21s)19312026/10/20 08:19:17 WARN Request failed, retrying attempt=4 backoff=780.524302ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present1932--- PASS: TestService_ReadScope_PublicByDefault (8.34s)1933--- PASS: TestCacheStatsHandler (8.61s)19342026-10-20 08:19:18.103 UTC [88933] LOG: checkpoint starting: wal19352026/10/20 08:19:18 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted,O=Other"19362026/10/20 08:19:18 WARN mTLS auth: bound subjects configured but subject DN unavailable19372026/10/20 08:19:18 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted"1938--- PASS: TestService_AuthMiddleware_MTLSBoundSubjects (7.47s)19392026/10/20 08:19:18 INFO Received push request method=POST path=/api/pushes19402026/10/20 08:19:18 INFO Uploading 2 paths to 127.0.0.1 (0 already cached)19412026/10/20 08:19:18 INFO Uploading a2gabvp2a79wk8r3bqp1wsi64pjacr0n-shared-dep (136B)19422026/10/20 08:19:18 INFO Uploading qscwa697h4wy6hhpi2bgnx5nigay128m-top (264B)19432026/10/20 08:19:18 WARN Failed to register uploaded object key=a2gabvp2a79wk8r3bqp1wsi64pjacr0n.ls error="server returned 404: 404 page not found\n"19442026/10/20 08:19:18 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"19452026/10/20 08:19:18 WARN Request failed, retrying attempt=5 backoff=1.502580116s error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present19462026/10/20 08:19:18 WARN Failed to register uploaded object key=qscwa697h4wy6hhpi2bgnx5nigay128m.ls error="server returned 404: 404 page not found\n"19472026/10/20 08:19:18 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign19482026/10/20 08:19:18 WARN Failed to register uploaded object key=nar/0hqq3zfnjd9dzvbxggdda8c6xk902v9acswqczlvchgb70bahdgm.nar.zst error="server returned 404: 404 page not found\n"19492026/10/20 08:19:18 INFO Signed narinfos id=1 count=219502026/10/20 08:19:18 INFO Uploading 2 narinfos19512026/10/20 08:19:18 WARN Failed to register uploaded object key=qscwa697h4wy6hhpi2bgnx5nigay128m.narinfo error="server returned 404: 404 page not found\n"19522026/10/20 08:19:18 INFO Received complete push request method=POST path=/api/pushes/1/complete19532026/10/20 08:19:18 WARN Failed to register uploaded object key=a2gabvp2a79wk8r3bqp1wsi64pjacr0n.narinfo error="server returned 404: 404 page not found\n"19542026/10/20 08:19:18 INFO Completed push id=1 objects=6 duration=10.890542ms19552026/10/20 08:19:18 INFO Upload complete. (186ms)1956--- PASS: TestDeleteClosuresRacingPins (13.20s)1957=== NAME TestClientSharedPathCommittedMidPush1958 client_integration_test.go:680: Retrieved narinfo from S3:1959 StorePath: /private/var/tb/1/scratch/c8b5f9203adb9a1c/build/TestClientSharedPathCommittedMidPush1567318265/001/store/a2gabvp2a79wk8r3bqp1wsi64pjacr0n-shared-dep1960 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1961 Compression: zstd1962 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821963 NarSize: 1361964 References: 1965 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1966 client_integration_test.go:680: Retrieved narinfo from S3:1967 StorePath: /private/var/tb/1/scratch/c8b5f9203adb9a1c/build/TestClientSharedPathCommittedMidPush1567318265/001/store/qscwa697h4wy6hhpi2bgnx5nigay128m-top1968 URL: nar/0hqq3zfnjd9dzvbxggdda8c6xk902v9acswqczlvchgb70bahdgm.nar.zst1969 Compression: zstd1970 NarHash: sha256:0hqq3zfnjd9dzvbxggdda8c6xk902v9acswqczlvchgb70bahdgm1971 NarSize: 2641972 References: /private/var/tb/1/scratch/c8b5f9203adb9a1c/build/TestClientSharedPathCommittedMidPush1567318265/001/store/a2gabvp2a79wk8r3bqp1wsi64pjacr0n-shared-dep1973 CA: text:sha256:1s3h595v8zg0yq9cswczs638da5hc3mzqmad6m8124h7la47njim1974--- PASS: TestClientSharedPathCommittedMidPush (8.74s)1975=== NAME TestClientMultipleUploads1976 client_integration_test.go:358: Created store path 0: /private/var/tb/1/scratch/c8b5f9203adb9a1c/build/TestClientMultipleUploads2787562238/001/store/ff5amly9ibidk8ijs9ldfz3ziq2xvky6-test-file-0.txt1977 client_integration_test.go:358: Created store path 1: /private/var/tb/1/scratch/c8b5f9203adb9a1c/build/TestClientMultipleUploads2787562238/001/store/gr25663l7g361bfil1cbjx1rny2kyl6c-test-file-1.txt1978 client_integration_test.go:358: Created store path 2: /private/var/tb/1/scratch/c8b5f9203adb9a1c/build/TestClientMultipleUploads2787562238/001/store/lxzxwwvs8iy1v0jawbz7j6fira5s68r2-test-file-2.txt1979=== NAME TestClientIntegration1980 client_integration_test.go:286: Created store path: /private/var/tb/1/scratch/c8b5f9203adb9a1c/build/TestClientIntegration1355106779/002/store/r1q1sxq7i21dk78sx00jc8qbphav300k-test-file.txt1981--- PASS: TestService_AuthMiddleware_MTLSProxyHeader (6.90s)19822026/10/20 08:19:19 INFO Received push request method=POST path=/api/pushes19832026/10/20 08:19:19 INFO Received push request method=POST path=/api/pushes19842026/10/20 08:19:19 INFO Uploading 3 paths to 127.0.0.1 (0 already cached)19852026/10/20 08:19:19 INFO Uploading ff5amly9ibidk8ijs9ldfz3ziq2xvky6-test-file-0.txt (160B)19862026/10/20 08:19:19 INFO Uploading gr25663l7g361bfil1cbjx1rny2kyl6c-test-file-1.txt (160B)19872026/10/20 08:19:19 INFO Uploading lxzxwwvs8iy1v0jawbz7j6fira5s68r2-test-file-2.txt (160B)19882026/10/20 08:19:19 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)19892026/10/20 08:19:19 INFO Uploading r1q1sxq7i21dk78sx00jc8qbphav300k-test-file.txt (152B)19902026/10/20 08:19:19 WARN Failed to register uploaded object key=lxzxwwvs8iy1v0jawbz7j6fira5s68r2.ls error="server returned 404: 404 page not found\n"19912026/10/20 08:19:19 WARN Failed to register uploaded object key=ff5amly9ibidk8ijs9ldfz3ziq2xvky6.ls error="server returned 404: 404 page not found\n"19922026/10/20 08:19:19 WARN Failed to register uploaded object key=nar/13p9pqi0ga6fx2apcwls9hjnv7nmf740ggpn5zvfzdsp5vz2bbg4.nar.zst error="server returned 404: 404 page not found\n"19932026/10/20 08:19:19 WARN Failed to register uploaded object key=gr25663l7g361bfil1cbjx1rny2kyl6c.ls error="server returned 404: 404 page not found\n"19942026/10/20 08:19:19 WARN Failed to register uploaded object key=nar/0ahq3izw3h0b0c08p3xdfclh758fwxnp85ccvflasb4vnfsv50ri.nar.zst error="server returned 404: 404 page not found\n"19952026/10/20 08:19:19 WARN Failed to register uploaded object key=nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst error="server returned 404: 404 page not found\n"19962026/10/20 08:19:19 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign19972026/10/20 08:19:19 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign19982026/10/20 08:19:19 WARN Failed to register uploaded object key=nar/1823g6vx4q5zqvr73m7lkq1wpk40fin7bsc792di430yk7sg4lka.nar.zst error="server returned 404: 404 page not found\n"19992026/10/20 08:19:19 WARN Failed to register uploaded object key=r1q1sxq7i21dk78sx00jc8qbphav300k.ls error="server returned 404: 404 page not found\n"20002026/10/20 08:19:19 INFO Signed narinfos id=1 count=120012026/10/20 08:19:19 INFO Signed narinfos id=1 count=320022026/10/20 08:19:19 INFO Uploading 1 narinfos20032026/10/20 08:19:19 INFO Uploading 3 narinfos20042026/10/20 08:19:19 INFO Received complete push request method=POST path=/api/pushes/1/complete20052026/10/20 08:19:19 WARN Failed to register uploaded object key=r1q1sxq7i21dk78sx00jc8qbphav300k.narinfo error="server returned 404: 404 page not found\n"20062026/10/20 08:19:19 WARN Failed to register uploaded object key=ff5amly9ibidk8ijs9ldfz3ziq2xvky6.narinfo error="server returned 404: 404 page not found\n"20072026/10/20 08:19:19 WARN Failed to register uploaded object key=gr25663l7g361bfil1cbjx1rny2kyl6c.narinfo error="server returned 404: 404 page not found\n"20082026/10/20 08:19:19 INFO Completed push id=1 objects=3 duration=7.211583ms20092026/10/20 08:19:19 INFO Upload complete. (207ms)20102026/10/20 08:19:19 INFO Received complete push request method=POST path=/api/pushes/1/complete20112026/10/20 08:19:19 WARN Failed to register uploaded object key=lxzxwwvs8iy1v0jawbz7j6fira5s68r2.narinfo error="server returned 404: 404 page not found\n"20122026/10/20 08:19:19 INFO Completed push id=1 objects=9 duration=4.091458ms20132026/10/20 08:19:19 INFO Upload complete. (218ms)2014=== NAME TestClientMultipleUploads2015 client_integration_test.go:369: Uploaded 3 paths in 257.357042ms20162026/10/20 08:19:19 INFO All 1 paths already cached2017=== NAME TestClientIntegration2018 client_integration_test.go:312: Retrieved narinfo from S3:2019 StorePath: /private/var/tb/1/scratch/c8b5f9203adb9a1c/build/TestClientIntegration1355106779/002/store/r1q1sxq7i21dk78sx00jc8qbphav300k-test-file.txt2020 URL: nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst2021 Compression: zstd2022 NarHash: sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk12023 NarSize: 1522024 References: 2025 CA: fixed:r:sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk12026 client_integration_test.go:313: Retrieved .ls file from S3 (compressed size: 77 bytes)2027 client_integration_test.go:313: Decompressed .ls content (64 bytes):2028 {"version":1,"root":{"type":"regular","size":39,"narOffset":96}}2029 client_integration_test.go:316: Testing garbage collection...2030--- PASS: TestClientMultipleUploads (8.01s)20312026/10/20 08:19:19 INFO Received uploads request method=POST path=/api/pending_closures20322026/10/20 08:19:19 INFO Starting cleanup of old closures method=DELETE path=/api/closures20332026/10/20 08:19:19 INFO Garbage collection started20342026/10/20 08:19:19 INFO Aborted multipart uploads count=0 kept=020352026/10/20 08:19:19 WARN Force mode enabled - objects will be deleted immediately without grace period2036=== NAME TestOrphanedObjectsGCStressTest2037 orphaned_objects_gc_test.go:503: Stress test completed successfully:2038 orphaned_objects_gc_test.go:504: - Active objects preserved: 202039 orphaned_objects_gc_test.go:505: - Objects deleted: 2102040 orphaned_objects_gc_test.go:506: - Total GC'd: 2102041--- PASS: TestOrphanedObjectsGCStressTest (25.42s)20422026/10/20 08:19:19 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=020432026/10/20 08:19:19 INFO Vacuumed table table=pending_closures20442026/10/20 08:19:19 INFO Vacuumed table table=pending_objects20452026/10/20 08:19:19 INFO Vacuumed table table=multipart_uploads20462026/10/20 08:19:19 INFO Vacuumed table table=closures20472026/10/20 08:19:19 INFO Vacuumed table table=objects20482026/10/20 08:19:19 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=020492026/10/20 08:19:19 INFO Received create pin request method=POST path=/api/pins/myapp20502026/10/20 08:19:19 INFO Created/updated pin name=myapp store_path=/private/var/tb/1/scratch/c8b5f9203adb9a1c/build/TestPinProtectsFromGC624871103/001/store/3dlb5bk96h1v73ky7z6z8hcsi21kbfdb-pinned-file.txt narinfo_key=3dlb5bk96h1v73ky7z6z8hcsi21kbfdb.narinfo20512026/10/20 08:19:19 INFO Starting cleanup of old closures method=DELETE path=/api/closures20522026/10/20 08:19:19 INFO Garbage collection started20532026/10/20 08:19:19 INFO Aborted multipart uploads count=0 kept=020542026/10/20 08:19:19 WARN Force mode enabled - objects will be deleted immediately without grace period20552026/10/20 08:19:19 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=020562026/10/20 08:19:19 INFO Vacuumed table table=pending_closures20572026/10/20 08:19:19 INFO Vacuumed table table=pending_objects20582026/10/20 08:19:19 INFO Vacuumed table table=multipart_uploads20592026/10/20 08:19:19 INFO Vacuumed table table=closures20602026/10/20 08:19:19 INFO Vacuumed table table=objects2061=== NAME TestClientWithDependencies2062 client_integration_test.go:613: Built derivation: /private/var/tb/1/scratch/c8b5f9203adb9a1c/build/TestClientWithDependencies71075456/001/store/pfdkjz6gfgrp75zjxkagkddhd2mg4nfr-test-script2063 client_integration_test.go:615: Found 1 dependencies (including self)20642026/10/20 08:19:19 INFO Received push request method=POST path=/api/pushes20652026/10/20 08:19:19 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)20662026/10/20 08:19:19 INFO Uploading pfdkjz6gfgrp75zjxkagkddhd2mg4nfr-test-script (136B)20672026/10/20 08:19:19 WARN Failed to register uploaded object key=pfdkjz6gfgrp75zjxkagkddhd2mg4nfr.ls error="server returned 404: 404 page not found\n"20682026/10/20 08:19:19 WARN Failed to register uploaded object key=nar/1s7yghixzpinyqm7g59kyn3sav81pmnsdi5v63m6x4r2vacy907j.nar.zst error="server returned 404: 404 page not found\n"20692026/10/20 08:19:19 WARN Failed to register uploaded object key=log/197x8378baxamy8d198ydibq3zpc0986-test-script.drv error="server returned 404: 404 page not found\n"20702026/10/20 08:19:19 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign20712026/10/20 08:19:19 INFO Signed narinfos id=1 count=120722026/10/20 08:19:19 INFO Uploading 1 narinfos20732026/10/20 08:19:19 INFO Received complete push request method=POST path=/api/pushes/1/complete20742026/10/20 08:19:19 WARN Failed to register uploaded object key=pfdkjz6gfgrp75zjxkagkddhd2mg4nfr.narinfo error="server returned 404: 404 page not found\n"20752026/10/20 08:19:19 INFO Completed push id=1 objects=4 duration=3.181416ms20762026/10/20 08:19:19 INFO Upload complete. (176ms)2077 client_integration_test.go:617: Skipping nix copy test - isolated store (/private/var/tb/1/scratch/c8b5f9203adb9a1c/build/TestClientWithDependencies71075456/001/store) requires matching store prefix2078--- PASS: TestClientWithDependencies (7.46s)20792026/10/20 08:19:20 INFO Aborted multipart uploads count=0 kept=020802026/10/20 08:19:20 WARN Force mode enabled - objects will be deleted immediately without grace period20812026-10-20 08:19:20.027 UTC [99496] ERROR: canceling statement due to user request20822026-10-20 08:19:20.027 UTC [99496] CONTEXT: SQL statement "UPDATE object_stats s2083 SET object_count = s.object_count + n.n - o.n,2084 total_bytes = s.total_bytes + n.bytes - o.bytes2085 FROM (2086 SELECT count(*) AS n, coalesce(sum(size), 0) AS bytes2087 FROM new_rows WHERE deleted_at IS NULL2088 ) AS n,2089 (2090 SELECT count(*) AS n, coalesce(sum(size), 0) AS bytes2091 FROM old_rows WHERE deleted_at IS NULL2092 ) AS o2093 WHERE s.id AND (n.n <> o.n OR n.bytes <> o.bytes)"2094 PL/pgSQL function object_stats_update() line 3 at SQL statement20952026-10-20 08:19:20.027 UTC [99496] STATEMENT: -- name: MarkStaleObjects :execrows2096 WITH RECURSIVE ct AS (2097 SELECT timezone('UTC', now()) AS now2098 ),2099 closure_reach AS (2100 -- Start with all closure keys2101 SELECT o.key, o.refs2102 FROM objects o2103 INNER JOIN closures c ON o.key = c.key2104 UNION2105 -- Recursively add all referenced objects2106 SELECT o.key, o.refs2107 FROM objects o2108 INNER JOIN closure_reach cr ON o.key = ANY(cr.refs)2109 ),2110 reachable_objects AS (2111 SELECT DISTINCT key FROM closure_reach2112 ),2113 stale_objects AS (2114 SELECT o.key2115 FROM objects AS o, ct2116 WHERE2117 NOT EXISTS (2118 SELECT 12119 FROM reachable_objects ro2120 WHERE ro.key = o.key2121 )2122 AND NOT EXISTS (2123 SELECT 12124 FROM pending_objects AS po2125 WHERE po.key = o.key2126 )2127 AND o.deleted_at IS NULL -- Only mark fresh objects2128 ORDER BY o.key COLLATE "C" -- lock in key order, like commit_pending_closure2129 FOR UPDATE2130 )2131 UPDATE objects2132 SET2133 deleted_at = ct.now,2134 first_deleted_at = COALESCE(first_deleted_at, ct.now)2135 FROM stale_objects, ct2136 WHERE objects.key = stale_objects.key2137 21382026/10/20 08:19:20 WARN Request failed, retrying attempt=1 backoff=100ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config2139--- PASS: TestPendingClosureWriteTimeout (0.00s)2140 --- PASS: TestPendingClosureWriteTimeout/empty (0.00s)2141 --- PASS: TestPendingClosureWriteTimeout/670k_objects (0.00s)2142 --- PASS: TestPendingClosureWriteTimeout/400_objects (0.00s)2143 --- PASS: TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline (7.03s)21442026/10/20 08:19:20 INFO Aborted multipart uploads count=0 kept=021452026/10/20 08:19:20 WARN Force mode enabled - objects will be deleted immediately without grace period2146--- PASS: TestPresentNotReportedWhileGCDeletesClosure (0.00s)2147 --- PASS: TestPresentNotReportedWhileGCDeletesClosure/stale (6.86s)2148 --- PASS: TestPresentNotReportedWhileGCDeletesClosure/fresh (6.68s)21492026/10/20 08:19:20 WARN Request failed, retrying attempt=2 backoff=186.963825ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21502026/10/20 08:19:20 ERROR failed to remove object object=nar/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa.nar.zst error="Post \"http://localhost:52759/bucket96/?delete=\": context canceled"2151--- PASS: TestGCEndsOnShutdown (0.02s)2152 --- PASS: TestGCEndsOnShutdown/before_the_run (5.63s)2153 --- PASS: TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark (4.67s)2154 --- PASS: TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete (4.25s)21552026/10/20 08:19:20 WARN Request failed, retrying attempt=3 backoff=396.582393ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21562026/10/20 08:19:20 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"21572026/10/20 08:19:20 INFO Received uploads request method=POST path=/api/pending_closures21582026/10/20 08:19:20 INFO Aborted multipart uploads count=0 kept=021592026/10/20 08:19:20 WARN Force mode enabled - objects will be deleted immediately without grace period21602026/10/20 08:19:20 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=1 objects-deleted-after-grace-period=1 objects-failed-to-delete=021612026/10/20 08:19:20 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"21622026/10/20 08:19:20 INFO Vacuumed table table=pending_closures21632026/10/20 08:19:20 INFO Vacuumed table table=pending_objects21642026/10/20 08:19:20 INFO Vacuumed table table=multipart_uploads21652026/10/20 08:19:20 INFO Vacuumed table table=closures21662026/10/20 08:19:20 INFO Vacuumed table table=objects21672026/10/20 08:19:20 INFO Received uploads request method=POST path=/api/pending_closures21682026/10/20 08:19:20 INFO Aborted multipart uploads count=0 kept=021692026/10/20 08:19:20 WARN Force mode enabled - objects will be deleted immediately without grace period21702026/10/20 08:19:20 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=021712026/10/20 08:19:20 INFO Vacuumed table table=pending_closures21722026/10/20 08:19:20 INFO Vacuumed table table=pending_objects21732026/10/20 08:19:20 INFO Vacuumed table table=multipart_uploads21742026/10/20 08:19:20 INFO Vacuumed table table=closures21752026/10/20 08:19:20 INFO Vacuumed table table=objects2176--- PASS: TestForceGCDuringPushOffersSweptObject (0.00s)2177 --- PASS: TestForceGCDuringPushOffersSweptObject/before_pending_rows (3.50s)2178 --- PASS: TestForceGCDuringPushOffersSweptObject/after_presence_check (3.39s)21792026/10/20 08:19:20 WARN Request failed, retrying attempt=4 backoff=735.655294ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21802026/10/20 08:19:21 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=02181=== NAME TestClientIntegration2182 client_integration_test.go:323: Objects in database after GC:2183 client_integration_test.go:323: Successfully deleted all objects with GC --force2184--- PASS: TestClientIntegration (9.57s)2185=== NAME TestPinProtectsFromGC2186 client_integration_test.go:840: Pin successfully protected closure from garbage collection2187--- PASS: TestPinProtectsFromGC (14.70s)21882026/10/20 08:19:21 WARN Request failed, retrying attempt=5 backoff=1.489323788s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21892026/10/20 08:19:22 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: sending request: request failed after retries: Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused"21902026/10/20 08:19:22 WARN Request failed, retrying attempt=1 backoff=100ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21912026/10/20 08:19:23 WARN Request failed, retrying attempt=2 backoff=190.150463ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21922026/10/20 08:19:23 WARN Request failed, retrying attempt=3 backoff=410.656934ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21932026/10/20 08:19:23 WARN Request failed, retrying attempt=4 backoff=806.364781ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21942026/10/20 08:19:24 WARN Request failed, retrying attempt=5 backoff=1.575145303s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21952026/10/20 08:19:26 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures21962026/10/20 08:19:26 WARN Request failed, retrying attempt=2 backoff=209.957676ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures21972026/10/20 08:19:26 WARN Request failed, retrying attempt=3 backoff=405.421775ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures21982026/10/20 08:19:26 WARN Request failed, retrying attempt=4 backoff=751.676801ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures21992026/10/20 08:19:27 WARN Request failed, retrying attempt=5 backoff=1.45115656s error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures2200--- PASS: TestClientErrorHandling (0.01s)2201 --- PASS: TestClientErrorHandling/InvalidStorePath (3.85s)2202 --- PASS: TestClientErrorHandling/InvalidAuthToken (3.50s)2203 --- PASS: TestClientErrorHandling/ServerNotAvailable (12.17s)2204FAIL2205{"timestamp":"2026-10-20T08:19:29.004088Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:52878","error_kind":"io_error","error":"Cancelled","result":"transport_error","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":2386,"threadName":"rustfs-worker","threadId":"ThreadId(2)"}22062026-10-20 08:19:29.120 UTC [88923] LOG: received smart shutdown request22072026-10-20 08:19:29.121 UTC [88923] LOG: background worker "logical replication launcher" (PID 88942) exited with exit code 122082026-10-20 08:19:30.471 UTC [88933] LOG: checkpoint complete: wrote 10431 buffers (63.7%), wrote 5 SLRU buffers; 0 WAL file(s) added, 0 removed, 33 recycled; write=11.349 s, sync=0.870 s, total=12.368 s; sync files=34045, longest=0.002 s, average=0.001 s; distance=533920 kB, estimate=533920 kB; lsn=0/228DA7F0, redo lsn=0/220F4F8822092026-10-20 08:19:30.472 UTC [88933] LOG: shutting down22102026-10-20 08:19:30.472 UTC [88933] LOG: checkpoint starting: shutdown immediate22112026-10-20 08:19:30.481 UTC [88933] LOG: checkpoint complete: wrote 251 buffers (1.5%), wrote 1 SLRU buffers; 0 WAL file(s) added, 0 removed, 0 recycled; write=0.004 s, sync=0.004 s, total=0.009 s; sync files=169, longest=0.001 s, average=0.001 s; distance=8086 kB, estimate=481336 kB; lsn=0/228DA868, redo lsn=0/228DA86822122026-10-20 08:19:30.488 UTC [88923] LOG: database system is shut down