niks3-go-unit-tests
checks.aarch64-darwin.go-unit-tests
· build #460
· raw
1tribuchet: building on mac022Running client tests...3=== RUN TestDoServerRequestAttachesToken4=== PAUSE TestDoServerRequestAttachesToken5=== RUN TestUploadBuildLog_FileBodyReplayedOnRetry6=== PAUSE TestUploadBuildLog_FileBodyReplayedOnRetry7=== RUN TestRegisterUploadedObjectReusesConnections8=== PAUSE TestRegisterUploadedObjectReusesConnections9=== RUN TestRunGarbageCollection_FinishedOnAnotherReplica10=== PAUSE TestRunGarbageCollection_FinishedOnAnotherReplica11=== RUN TestRunGarbageCollection_NotFoundAfterLocalRun12=== PAUSE TestRunGarbageCollection_NotFoundAfterLocalRun13=== RUN TestCaseHackSuffix14=== PAUSE TestCaseHackSuffix15=== RUN TestFilterOversizedClosures16=== PAUSE TestFilterOversizedClosures17=== RUN TestUploadMultipart_PartsInParallel18=== PAUSE TestUploadMultipart_PartsInParallel19=== RUN TestUploadMultipart_FailedPartBufferNotReused20=== PAUSE TestUploadMultipart_FailedPartBufferNotReused21=== RUN TestUploadMultipart_ReturnsAfterDroppedBody22=== PAUSE TestUploadMultipart_ReturnsAfterDroppedBody23=== RUN TestPartSizeForNAR24=== PAUSE TestPartSizeForNAR25=== RUN TestUploadMultipart_SupersededByPeer26=== PAUSE TestUploadMultipart_SupersededByPeer27=== RUN TestDumpPathCaseHackMatchesNix28--- PASS: TestDumpPathCaseHackMatchesNix (0.10s)29=== RUN TestDumpPathCaseHackCollision30--- PASS: TestDumpPathCaseHackCollision (0.00s)31=== RUN TestSupersededNARStillUploadsListing32=== PAUSE TestSupersededNARStillUploadsListing33=== RUN TestDumpPathMatchesNix34=== PAUSE TestDumpPathMatchesNix35=== RUN TestDumpPathSingleFile36=== PAUSE TestDumpPathSingleFile37=== RUN TestDumpPathWriterError38=== PAUSE TestDumpPathWriterError39=== RUN TestEncodeNixBase3240=== PAUSE TestEncodeNixBase3241=== RUN TestEncodeNixBase32WithRealHash42=== PAUSE TestEncodeNixBase32WithRealHash43=== RUN TestConvertHashToNix3244=== PAUSE TestConvertHashToNix3245=== RUN TestGetStorePathHash46=== PAUSE TestGetStorePathHash47=== RUN TestPathInfoHashCompatibility48=== PAUSE TestPathInfoHashCompatibility49=== RUN TestParsePathInfoJSON50=== PAUSE TestParsePathInfoJSON51=== RUN TestParsePathInfoJSONMultiplePaths52=== PAUSE TestParsePathInfoJSONMultiplePaths53=== RUN TestPathInfoCACompatibility54=== PAUSE TestPathInfoCACompatibility55=== RUN TestRateLimiterFeedback56=== PAUSE TestRateLimiterFeedback57=== RUN TestRateLimiterFeedback_400DoesNotCountAsSuccess58=== PAUSE TestRateLimiterFeedback_400DoesNotCountAsSuccess59=== RUN TestRegisterUploadedObject_BoundedAgainstSilentServer60=== PAUSE TestRegisterUploadedObject_BoundedAgainstSilentServer61=== RUN TestResolveStorePath62=== PAUSE TestResolveStorePath63=== RUN TestDoWithRetry_BodyReplayedViaGetBody64=== PAUSE TestDoWithRetry_BodyReplayedViaGetBody65=== RUN TestRetryTimeoutOutlastsMaxRetries66=== PAUSE TestRetryTimeoutOutlastsMaxRetries67=== RUN TestDoWithRetry_FinalResponseBodyReadable68=== PAUSE TestDoWithRetry_FinalResponseBodyReadable69=== RUN TestShellSplit70=== PAUSE TestShellSplit71=== RUN TestShellSplitErrors72=== PAUSE TestShellSplitErrors73=== RUN TestStreamPushReportsEveryPath74=== PAUSE TestStreamPushReportsEveryPath75=== RUN TestStreamPushBatchesUnderLoad76=== PAUSE TestStreamPushBatchesUnderLoad77=== RUN TestStreamPushIsolatesFailures78=== PAUSE TestStreamPushIsolatesFailures79=== RUN TestStreamPushGivesUpOnDeadServer80=== PAUSE TestStreamPushGivesUpOnDeadServer81=== RUN TestStreamPushRequestLine82=== PAUSE TestStreamPushRequestLine83=== RUN TestStreamPushReportsSignatures84=== PAUSE TestStreamPushReportsSignatures85=== RUN TestStreamPushReportsSkippedPaths86=== PAUSE TestStreamPushReportsSkippedPaths87=== RUN TestClientSignaturesByStorePath88=== PAUSE TestClientSignaturesByStorePath89=== RUN TestStreamPushStopsWhenCanceled90=== PAUSE TestStreamPushStopsWhenCanceled91=== RUN TestSetClientTLS92=== PAUSE TestSetClientTLS93=== RUN TestSetClientTLSDoesNotMutateDefaultTransport94=== PAUSE TestSetClientTLSDoesNotMutateDefaultTransport95=== RUN TestSetClientTLSErrors96=== PAUSE TestSetClientTLSErrors97=== RUN TestStaticToken98=== PAUSE TestStaticToken99=== RUN TestFileTokenReadsAndCaches100=== PAUSE TestFileTokenReadsAndCaches101=== RUN TestFileTokenMissing102=== PAUSE TestFileTokenMissing103=== RUN TestFileTokenEmpty104=== PAUSE TestFileTokenEmpty105=== RUN TestScriptTokenNoExpiryRerunsEveryCall106=== PAUSE TestScriptTokenNoExpiryRerunsEveryCall107=== RUN TestScriptTokenCachesUntilRefresh108=== PAUSE TestScriptTokenCachesUntilRefresh109=== RUN TestScriptTokenEmptyToken110=== PAUSE TestScriptTokenEmptyToken111=== RUN TestScriptTokenBadJSON112=== PAUSE TestScriptTokenBadJSON113=== RUN TestScriptTokenScriptFails114=== PAUSE TestScriptTokenScriptFails115=== RUN TestScriptTokenEmptyCommand116=== PAUSE TestScriptTokenEmptyCommand117=== CONT TestDoServerRequestAttachesToken118=== CONT TestDoWithRetry_BodyReplayedViaGetBody119=== CONT TestSetClientTLS120=== CONT TestScriptTokenEmptyCommand121=== CONT TestScriptTokenScriptFails122--- PASS: TestScriptTokenEmptyCommand (0.00s)123=== CONT TestGetStorePathHash124=== RUN TestGetStorePathHash/valid_store_path125=== PAUSE TestGetStorePathHash/valid_store_path126=== RUN TestGetStorePathHash/basename_without_hyphen_should_error127=== PAUSE TestGetStorePathHash/basename_without_hyphen_should_error128=== RUN TestGetStorePathHash/hash_with_invalid_characters_should_error129=== PAUSE TestGetStorePathHash/hash_with_invalid_characters_should_error130=== RUN TestGetStorePathHash/hash_with_wrong_length_should_error131=== PAUSE TestGetStorePathHash/hash_with_wrong_length_should_error132=== CONT TestConvertHashToNix32133=== RUN TestConvertHashToNix32/SRI_format_to_Nix32134=== PAUSE TestConvertHashToNix32/SRI_format_to_Nix32135=== RUN TestConvertHashToNix32/already_Nix32_format136=== PAUSE TestConvertHashToNix32/already_Nix32_format137=== RUN TestConvertHashToNix32/invalid_format138=== PAUSE TestConvertHashToNix32/invalid_format139=== CONT TestEncodeNixBase32WithRealHash140--- PASS: TestEncodeNixBase32WithRealHash (0.00s)141=== CONT TestEncodeNixBase32142=== RUN TestEncodeNixBase32/test_string_hash143=== PAUSE TestEncodeNixBase32/test_string_hash144=== CONT TestScriptTokenBadJSON145=== CONT TestScriptTokenEmptyToken146=== CONT TestScriptTokenCachesUntilRefresh147=== CONT TestScriptTokenNoExpiryRerunsEveryCall148=== CONT TestFileTokenEmpty149=== CONT TestFileTokenMissing150=== CONT TestFileTokenReadsAndCaches151=== CONT TestStaticToken152=== CONT TestSetClientTLSErrors153=== CONT TestSetClientTLSDoesNotMutateDefaultTransport154=== CONT TestDumpPathSingleFile155=== CONT TestResolveStorePath156=== CONT TestRegisterUploadedObject_BoundedAgainstSilentServer157=== CONT TestRateLimiterFeedback_400DoesNotCountAsSuccess158=== CONT TestRateLimiterFeedback159=== CONT TestPathInfoCACompatibility160=== CONT TestParsePathInfoJSONMultiplePaths161=== CONT TestParsePathInfoJSON162=== CONT TestPathInfoHashCompatibility163=== RUN TestEncodeNixBase32/empty_input164--- PASS: TestStaticToken (0.00s)165=== CONT TestDumpPathWriterError166--- PASS: TestFileTokenEmpty (0.00s)167=== CONT TestStreamPushReportsSkippedPaths168=== RUN TestRateLimiterFeedback/429_enables_limiter169=== RUN TestSetClientTLSErrors/missing_cert_file1702026/11/04 20:13:31 WARN Rate limiter enabled after throttle name=server-test rate=5171--- PASS: TestFileTokenReadsAndCaches (0.01s)172--- PASS: TestFileTokenMissing (0.01s)173=== PAUSE TestRateLimiterFeedback/429_enables_limiter174=== RUN TestPathInfoCACompatibility/null_ca_field175=== RUN TestRateLimiterFeedback/503_enables_limiter176=== RUN TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths177=== PAUSE TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths178=== RUN TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths179=== PAUSE TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths180=== RUN TestParsePathInfoJSON/Nix_format181=== PAUSE TestParsePathInfoJSON/Nix_format182=== RUN TestParsePathInfoJSON/Lix_format183=== PAUSE TestParsePathInfoJSON/Lix_format184=== RUN TestParsePathInfoJSON/empty_input185=== CONT TestStreamPushIsolatesFailures186=== RUN TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)187=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)188=== RUN TestPathInfoHashCompatibility/old_string_format_with_colon189=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_colon190=== PAUSE TestRateLimiterFeedback/503_enables_limiter191=== RUN TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI192=== PAUSE TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI193=== RUN TestPathInfoHashCompatibility/new_structured_format_with_sha512194=== PAUSE TestPathInfoHashCompatibility/new_structured_format_with_sha512195--- PASS: TestSetClientTLSDoesNotMutateDefaultTransport (0.00s)196--- PASS: TestResolveStorePath (0.00s)197=== PAUSE TestEncodeNixBase32/empty_input198=== PAUSE TestParsePathInfoJSON/empty_input199=== RUN TestParsePathInfoJSON/whitespace_only200=== CONT TestShellSplitErrors2012026/11/04 20:13:31 ERROR Upload failed error="bad path" count=3202--- PASS: TestShellSplitErrors (0.00s)203=== CONT TestStreamPushBatchesUnderLoad204=== RUN TestStreamPushBatchesUnderLoad/oneAtATime=false205=== PAUSE TestStreamPushBatchesUnderLoad/oneAtATime=false206=== RUN TestStreamPushBatchesUnderLoad/oneAtATime=true207--- PASS: TestScriptTokenScriptFails (0.01s)208=== RUN TestRateLimiterFeedback/200_does_not_enable_limiter209=== PAUSE TestRateLimiterFeedback/200_does_not_enable_limiter210=== RUN TestRateLimiterFeedback/400_does_not_enable_limiter211=== PAUSE TestRateLimiterFeedback/400_does_not_enable_limiter212=== PAUSE TestStreamPushBatchesUnderLoad/oneAtATime=true213=== RUN TestSetClientTLS/rejects_connection_without_client_cert214=== CONT TestDoWithRetry_FinalResponseBodyReadable215=== PAUSE TestSetClientTLS/rejects_connection_without_client_cert216=== RUN TestSetClientTLS/succeeds_with_client_cert_and_CA217=== PAUSE TestSetClientTLS/succeeds_with_client_cert_and_CA218=== RUN TestSetClientTLS/preserves_debug_logging_transport219=== PAUSE TestSetClientTLS/preserves_debug_logging_transport220=== CONT TestStreamPushRequestLine221=== PAUSE TestParsePathInfoJSON/whitespace_only222=== CONT TestShellSplit223=== RUN TestParsePathInfoJSON/invalid_JSON224--- PASS: TestShellSplit (0.00s)225--- PASS: TestStreamPushReportsSkippedPaths (0.00s)226=== CONT TestDumpPathMatchesNix227=== PAUSE TestParsePathInfoJSON/invalid_JSON228=== CONT TestStreamPushReportsSignatures229=== CONT TestSupersededNARStillUploadsListing230--- PASS: TestStreamPushIsolatesFailures (0.00s)231=== RUN TestSupersededNARStillUploadsListing/small_NAR232=== PAUSE TestPathInfoCACompatibility/null_ca_field233=== PAUSE TestSupersededNARStillUploadsListing/small_NAR234=== CONT TestRetryTimeoutOutlastsMaxRetries235=== RUN TestSupersededNARStillUploadsListing/dump_cut_short236=== PAUSE TestSupersededNARStillUploadsListing/dump_cut_short237=== RUN TestPathInfoCACompatibility/old_string_format_-_text238=== PAUSE TestPathInfoCACompatibility/old_string_format_-_text239=== RUN TestPathInfoCACompatibility/old_string_format_-_fixed_recursive240=== PAUSE TestPathInfoCACompatibility/old_string_format_-_fixed_recursive241=== RUN TestPathInfoCACompatibility/new_structured_format_-_text242=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_text243=== PAUSE TestSetClientTLSErrors/missing_cert_file244=== RUN TestSetClientTLSErrors/missing_key_file245=== CONT TestUploadMultipart_PartsInParallel2462026/11/04 20:13:31 WARN Rate limiter enabled after throttle name=server-test rate=5247=== CONT TestStreamPushStopsWhenCanceled2482026/11/04 20:13:31 ERROR Upload failed error=boom count=1249=== CONT TestUploadMultipart_SupersededByPeer2502026/11/04 20:13:31 ERROR Upload failed error=boom count=1251=== RUN TestUploadMultipart_SupersededByPeer/exists252--- PASS: TestStreamPushReportsSignatures (0.00s)253=== PAUSE TestUploadMultipart_SupersededByPeer/exists254=== RUN TestUploadMultipart_SupersededByPeer/missing255=== PAUSE TestUploadMultipart_SupersededByPeer/missing256=== CONT TestStreamPushGivesUpOnDeadServer257=== RUN TestPathInfoCACompatibility/new_structured_format_-_nar_method258=== CONT TestClientSignaturesByStorePath259=== RUN TestSupersededNARStillUploadsListing/listing_upload_fails260=== CONT TestStreamPushReportsEveryPath2612026/11/04 20:13:31 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:65101262=== PAUSE TestSetClientTLSErrors/missing_key_file263=== RUN TestSetClientTLSErrors/missing_ca_file264=== PAUSE TestSetClientTLSErrors/missing_ca_file265=== RUN TestSetClientTLSErrors/invalid_ca_file266=== PAUSE TestSetClientTLSErrors/invalid_ca_file267=== CONT TestCaseHackSuffix268=== CONT TestRunGarbageCollection_NotFoundAfterLocalRun269--- PASS: TestDoServerRequestAttachesToken (0.01s)270=== CONT TestUploadMultipart_ReturnsAfterDroppedBody271--- PASS: TestClientSignaturesByStorePath (0.00s)272=== CONT TestPartSizeForNAR273=== PAUSE TestSupersededNARStillUploadsListing/listing_upload_fails274=== RUN TestPartSizeForNAR/zero_stays_at_minimum275=== PAUSE TestPartSizeForNAR/zero_stays_at_minimum276=== CONT TestRegisterUploadedObjectReusesConnections277--- PASS: TestStreamPushReportsEveryPath (0.00s)278=== CONT TestUploadMultipart_FailedPartBufferNotReused279=== CONT TestFilterOversizedClosures280=== RUN TestFilterOversizedClosures/no_limit_keeps_everything281=== RUN TestPartSizeForNAR/small_stays_at_minimum282=== PAUSE TestPartSizeForNAR/small_stays_at_minimum283=== RUN TestPartSizeForNAR/80_GiB_fits_at_minimum284=== PAUSE TestFilterOversizedClosures/no_limit_keeps_everything285=== RUN TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped286=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_nar_method2872026/11/04 20:13:31 WARN Rate limiter backed off name=server-test rate=52882026/11/04 20:13:31 WARN Request returned retryable status, retrying attempt=2 backoff=0s status=503 url=http://127.0.0.1:65101289=== CONT TestRunGarbageCollection_FinishedOnAnotherReplica2902026/11/04 20:13:31 INFO Garbage collection started291--- PASS: TestDoWithRetry_BodyReplayedViaGetBody (0.02s)292=== CONT TestUploadBuildLog_FileBodyReplayedOnRetry293=== PAUSE TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped294=== RUN TestFilterOversizedClosures/all_closures_skipped295=== PAUSE TestFilterOversizedClosures/all_closures_skipped296=== PAUSE TestPartSizeForNAR/80_GiB_fits_at_minimum2972026/11/04 20:13:31 ERROR Upload failed error="connection refused" count=20298=== RUN TestPartSizeForNAR/115_GiB_needs_larger_parts299=== PAUSE TestPartSizeForNAR/115_GiB_needs_larger_parts300=== RUN TestPartSizeForNAR/1_TiB301=== PAUSE TestPartSizeForNAR/1_TiB302=== RUN TestPartSizeForNAR/5_TiB_S3_max_object303=== PAUSE TestPartSizeForNAR/5_TiB_S3_max_object304=== RUN TestPartSizeForNAR/capped_at_5_GiB305=== PAUSE TestPartSizeForNAR/capped_at_5_GiB306=== CONT TestGetStorePathHash/valid_store_path307--- PASS: TestStreamPushStopsWhenCanceled (0.03s)308=== CONT TestGetStorePathHash/hash_with_invalid_characters_should_error309=== CONT TestGetStorePathHash/basename_without_hyphen_should_error310=== CONT TestGetStorePathHash/hash_with_wrong_length_should_error311--- PASS: TestGetStorePathHash (0.00s)312 --- PASS: TestGetStorePathHash/valid_store_path (0.00s)313 --- PASS: TestGetStorePathHash/hash_with_invalid_characters_should_error (0.00s)314 --- PASS: TestGetStorePathHash/basename_without_hyphen_should_error (0.00s)315 --- PASS: TestGetStorePathHash/hash_with_wrong_length_should_error (0.00s)316=== CONT TestConvertHashToNix32/invalid_format317=== CONT TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths318=== CONT TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)319=== CONT TestPathInfoHashCompatibility/new_structured_format_with_sha512320=== CONT TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI321=== CONT TestEncodeNixBase32/test_string_hash322=== CONT TestEncodeNixBase32/empty_input323=== CONT TestRateLimiterFeedback/429_enables_limiter324=== CONT TestConvertHashToNix32/SRI_format_to_Nix32325=== CONT TestStreamPushBatchesUnderLoad/oneAtATime=false326=== CONT TestConvertHashToNix32/already_Nix32_format327=== CONT TestRateLimiterFeedback/503_enables_limiter328=== CONT TestRateLimiterFeedback/400_does_not_enable_limiter329--- PASS: TestScriptTokenEmptyToken (0.04s)330--- PASS: TestScriptTokenBadJSON (0.04s)331=== CONT TestPathInfoHashCompatibility/old_string_format_with_colon332=== CONT TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths333=== CONT TestSetClientTLS/rejects_connection_without_client_cert3342026/11/04 20:13:31 ERROR Server seems unavailable, giving up on batch untried=17335--- PASS: TestParsePathInfoJSONMultiplePaths (0.00s)336 --- PASS: TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths (0.00s)337 --- PASS: TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths (0.00s)338=== CONT TestRateLimiterFeedback/200_does_not_enable_limiter339--- PASS: TestStreamPushGivesUpOnDeadServer (0.03s)340--- PASS: TestPathInfoHashCompatibility (0.00s)341 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) (0.00s)342 --- PASS: TestPathInfoHashCompatibility/new_structured_format_with_sha512 (0.00s)343 --- PASS: TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI (0.00s)344 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_colon (0.00s)345=== CONT TestStreamPushBatchesUnderLoad/oneAtATime=true346--- PASS: TestEncodeNixBase32 (0.01s)347 --- PASS: TestEncodeNixBase32/test_string_hash (0.00s)348 --- PASS: TestEncodeNixBase32/empty_input (0.00s)349--- PASS: TestConvertHashToNix32 (0.00s)350 --- PASS: TestConvertHashToNix32/invalid_format (0.00s)351 --- PASS: TestConvertHashToNix32/SRI_format_to_Nix32 (0.00s)352 --- PASS: TestConvertHashToNix32/already_Nix32_format (0.00s)353--- PASS: TestStreamPushBatchesUnderLoad (0.00s)354 --- PASS: TestStreamPushBatchesUnderLoad/oneAtATime=false (0.00s)355 --- PASS: TestStreamPushBatchesUnderLoad/oneAtATime=true (0.00s)356=== CONT TestSetClientTLS/preserves_debug_logging_transport357--- PASS: TestRunGarbageCollection_NotFoundAfterLocalRun (0.03s)358=== CONT TestSetClientTLS/succeeds_with_client_cert_and_CA3592026/11/04 20:13:31 WARN Rate limiter enabled after throttle name=server-test rate=53602026/11/04 20:13:31 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:651073612026/11/04 20:13:31 WARN Request returned retryable status, retrying attempt=1 backoff=1ms status=502 url=http://127.0.0.1:651113622026/11/04 20:13:31 WARN Rate limiter backed off name=server-test rate=53632026/11/04 20:13:31 WARN Rate limiter enabled after throttle name=server-test rate=53642026/11/04 20:13:31 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=429 url=http://127.0.0.1:651843652026/11/04 20:13:31 WARN Rate limiter enabled after throttle name=server-test rate=53662026/11/04 20:13:31 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:65186367=== CONT TestParsePathInfoJSON/Nix_format368=== CONT TestParsePathInfoJSON/whitespace_only369=== CONT TestParsePathInfoJSON/empty_input370=== CONT TestParsePathInfoJSON/Lix_format371--- PASS: TestDoWithRetry_FinalResponseBodyReadable (0.04s)372=== CONT TestUploadMultipart_SupersededByPeer/missing3732026/11/04 20:13:31 WARN Rate limiter enabled after throttle name=s3-test rate=5374=== CONT TestParsePathInfoJSON/invalid_JSON3752026/11/04 20:13:31 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:65199376=== CONT TestSetClientTLSErrors/missing_cert_file377=== CONT TestUploadMultipart_SupersededByPeer/exists378=== CONT TestSetClientTLSErrors/invalid_ca_file379--- PASS: TestUploadBuildLog_FileBodyReplayedOnRetry (0.03s)3802026/11/04 20:13:31 INFO Garbage collection started381=== CONT TestSetClientTLSErrors/missing_ca_file382--- PASS: TestParsePathInfoJSON (0.00s)383 --- PASS: TestParsePathInfoJSON/Nix_format (0.00s)384 --- PASS: TestParsePathInfoJSON/whitespace_only (0.00s)385 --- PASS: TestParsePathInfoJSON/empty_input (0.00s)386 --- PASS: TestParsePathInfoJSON/Lix_format (0.00s)387 --- PASS: TestParsePathInfoJSON/invalid_JSON (0.00s)3882026/11/04 20:13:31 WARN Request returned retryable status, retrying attempt=2 backoff=1ms status=502 url=http://127.0.0.1:651113892026/11/04 20:13:31 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=0390=== CONT TestSetClientTLSErrors/missing_key_file3912026/11/04 20:13:31 WARN Rate limiter backed off name=server-test rate=53922026/11/04 20:13:31 WARN Rate limiter backed off name=server-test rate=5393=== CONT TestSupersededNARStillUploadsListing/small_NAR394=== CONT TestSupersededNARStillUploadsListing/dump_cut_short395--- PASS: TestRateLimiterFeedback (0.00s)396 --- PASS: TestRateLimiterFeedback/400_does_not_enable_limiter (0.01s)397 --- PASS: TestRateLimiterFeedback/200_does_not_enable_limiter (0.01s)398 --- PASS: TestRateLimiterFeedback/503_enables_limiter (0.02s)399 --- PASS: TestRateLimiterFeedback/429_enables_limiter (0.02s)400=== CONT TestSupersededNARStillUploadsListing/listing_upload_fails401--- PASS: TestUploadMultipart_ReturnsAfterDroppedBody (0.05s)4022026/11/04 20:13:31 INFO Uploading abc-hello (1.0GB)4032026/11/04 20:13:31 WARN Garbage collection finished on another replica. Its statistics are not available here404--- PASS: TestRunGarbageCollection_FinishedOnAnotherReplica (0.04s)405=== CONT TestPathInfoCACompatibility/old_string_format_-_fixed_recursive406=== CONT TestPathInfoCACompatibility/old_string_format_-_text407=== CONT TestPathInfoCACompatibility/new_structured_format_-_nar_method408=== CONT TestPartSizeForNAR/zero_stays_at_minimum409=== CONT TestFilterOversizedClosures/no_limit_keeps_everything410=== CONT TestFilterOversizedClosures/all_closures_skipped411=== CONT TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped4122026/11/04 20:13:31 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=50413=== CONT TestPartSizeForNAR/1_TiB414=== CONT TestPartSizeForNAR/115_GiB_needs_larger_parts415=== CONT TestPartSizeForNAR/80_GiB_fits_at_minimum416=== CONT TestPartSizeForNAR/small_stays_at_minimum417=== CONT TestPathInfoCACompatibility/null_ca_field418=== CONT TestPartSizeForNAR/capped_at_5_GiB419=== CONT TestPartSizeForNAR/5_TiB_S3_max_object420=== CONT TestPathInfoCACompatibility/new_structured_format_-_text4212026/11/04 20:13:31 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=2000422--- PASS: TestPartSizeForNAR (0.03s)423 --- PASS: TestPartSizeForNAR/zero_stays_at_minimum (0.00s)424 --- PASS: TestPartSizeForNAR/1_TiB (0.00s)425 --- PASS: TestPartSizeForNAR/115_GiB_needs_larger_parts (0.00s)426 --- PASS: TestPartSizeForNAR/80_GiB_fits_at_minimum (0.00s)427 --- PASS: TestPartSizeForNAR/small_stays_at_minimum (0.00s)428 --- PASS: TestPartSizeForNAR/capped_at_5_GiB (0.00s)429 --- PASS: TestPartSizeForNAR/5_TiB_S3_max_object (0.00s)430--- PASS: TestFilterOversizedClosures (0.03s)431 --- PASS: TestFilterOversizedClosures/no_limit_keeps_everything (0.00s)432 --- PASS: TestFilterOversizedClosures/all_closures_skipped (0.00s)433 --- PASS: TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped (0.00s)434--- PASS: TestPathInfoCACompatibility (0.01s)435 --- PASS: TestPathInfoCACompatibility/old_string_format_-_fixed_recursive (0.00s)436 --- PASS: TestPathInfoCACompatibility/old_string_format_-_text (0.00s)437 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_nar_method (0.00s)438 --- PASS: TestPathInfoCACompatibility/null_ca_field (0.00s)439 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_text (0.00s)440--- PASS: TestSetClientTLSErrors (0.01s)441 --- PASS: TestSetClientTLSErrors/missing_cert_file (0.00s)442 --- PASS: TestSetClientTLSErrors/invalid_ca_file (0.00s)443 --- PASS: TestSetClientTLSErrors/missing_ca_file (0.00s)444 --- PASS: TestSetClientTLSErrors/missing_key_file (0.00s)445--- PASS: TestStreamPushRequestLine (0.05s)4462026/11/04 20:13:31 WARN Request returned retryable status, retrying attempt=1 backoff=1ms status=502 url=http://127.0.0.1:65111447--- PASS: TestUploadMultipart_SupersededByPeer (0.00s)448 --- PASS: TestUploadMultipart_SupersededByPeer/missing (0.01s)449 --- PASS: TestUploadMultipart_SupersededByPeer/exists (0.01s)4502026/11/04 20:13:31 INFO Uploading abc-hello (1.0GB)4512026/11/04 20:13:31 WARN Request returned retryable status, retrying attempt=2 backoff=1ms status=502 url=http://127.0.0.1:651114522026/11/04 20:13:31 WARN Request returned retryable status, retrying attempt=3 backoff=1ms status=502 url=http://127.0.0.1:651114532026/11/04 20:13:31 WARN Rate limiter enabled after throttle name=s3-test rate=54542026/11/04 20:13:31 WARN Request returned retryable status, retrying attempt=4 backoff=1ms status=502 url=http://127.0.0.1:65111455--- PASS: TestScriptTokenNoExpiryRerunsEveryCall (0.07s)4562026/11/04 20:13:31 WARN Request returned retryable status, retrying attempt=5 backoff=1ms status=502 url=http://127.0.0.1:651114572026/11/04 20:13:31 WARN Request returned retryable status, retrying attempt=6 backoff=1ms status=502 url=http://127.0.0.1:65111458--- PASS: TestScriptTokenCachesUntilRefresh (0.07s)4592026/11/04 20:13:31 WARN Request returned retryable status, retrying attempt=7 backoff=1ms status=502 url=http://127.0.0.1:651114602026/11/04 20:13:31 WARN Request returned retryable status, retrying attempt=8 backoff=1ms status=502 url=http://127.0.0.1:651114612026/11/04 20:13:31 WARN Request returned retryable status, retrying attempt=9 backoff=1ms status=502 url=http://127.0.0.1:65111462--- PASS: TestRegisterUploadedObjectReusesConnections (0.07s)4632026/11/04 20:13:31 WARN Request returned retryable status, retrying attempt=10 backoff=1ms status=502 url=http://127.0.0.1:651114642026/11/04 20:13:31 WARN Request returned retryable status, retrying attempt=11 backoff=1ms status=502 url=http://127.0.0.1:651114652026/11/04 20:13:31 WARN Request returned retryable status, retrying attempt=12 backoff=1ms status=502 url=http://127.0.0.1:651114662026/11/04 20:13:31 WARN Request returned retryable status, retrying attempt=13 backoff=1ms status=502 url=http://127.0.0.1:651114672026/11/04 20:13:31 WARN Request returned retryable status, retrying attempt=14 backoff=1ms status=502 url=http://127.0.0.1:65111468--- PASS: TestDumpPathSingleFile (0.08s)4692026/11/04 20:13:31 WARN Request returned retryable status, retrying attempt=15 backoff=1ms status=502 url=http://127.0.0.1:651114702026/11/04 20:13:31 http: TLS handshake error from 127.0.0.1:65190: remote error: tls: bad certificate4712026/11/04 20:13:31 WARN Request returned retryable status, retrying attempt=16 backoff=1ms status=502 url=http://127.0.0.1:65111472--- PASS: TestSetClientTLS (0.01s)473 --- PASS: TestSetClientTLS/preserves_debug_logging_transport (0.04s)474 --- PASS: TestSetClientTLS/succeeds_with_client_cert_and_CA (0.04s)475 --- PASS: TestSetClientTLS/rejects_connection_without_client_cert (0.05s)4762026/11/04 20:13:31 WARN Request returned retryable status, retrying attempt=17 backoff=1ms status=502 url=http://127.0.0.1:65111477--- PASS: TestRetryTimeoutOutlastsMaxRetries (0.08s)478--- PASS: TestDumpPathWriterError (0.10s)4792026/11/04 20:13:31 INFO Uploading abc-hello (1.0GB)4802026/11/04 20:13:31 WARN Request failed, retrying attempt=1 backoff=100ms error="Put \"http://127.0.0.1:65208/part/2\": uploading part 1: server returned 404: no such upload\n" url=http://127.0.0.1:65208/part/24812026/11/04 20:13:31 ERROR Failed to close zstd encoder error="io: read/write on closed pipe"482--- PASS: TestCaseHackSuffix (0.12s)483--- PASS: TestDumpPathMatchesNix (0.13s)484--- PASS: TestUploadMultipart_FailedPartBufferNotReused (0.61s)485--- PASS: TestSupersededNARStillUploadsListing (0.00s)486 --- PASS: TestSupersededNARStillUploadsListing/listing_upload_fails (0.01s)487 --- PASS: TestSupersededNARStillUploadsListing/small_NAR (0.01s)488 --- PASS: TestSupersededNARStillUploadsListing/dump_cut_short (0.57s)489--- PASS: TestUploadMultipart_PartsInParallel (0.65s)4902026/11/04 20:13:32 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:65105/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:65105/api/uploads/complete4912026/11/04 20:13:32 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"4922026/11/04 20:13:32 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:65105/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:65105/api/uploads/complete4932026/11/04 20:13:32 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"4942026/11/04 20:13:32 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:65105/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:65105/api/uploads/complete495--- PASS: TestRateLimiterFeedback_400DoesNotCountAsSuccess (1.00s)4962026/11/04 20:13:32 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"497--- PASS: TestRegisterUploadedObject_BoundedAgainstSilentServer (1.00s)498PASS499Running server tests...500The files belonging to this database system will be owned by user "_tribuchetbld7".501This user must also own the server process.502503The database cluster will be initialized with locale "C".504The default database encoding has accordingly been set to "SQL_ASCII".505The default text search configuration will be set to "english".506507Data page checksums are enabled.508509creating directory /private/var/tb/7/scratch/63b205a296af2db3/build/postgres1531803411/data ... ok510creating subdirectories ... ok511selecting dynamic shared memory implementation ... posix512selecting default "max_connections" ... 100513selecting default "shared_buffers" ... 128MB514selecting default time zone ... UTC515creating configuration files ... ok516running bootstrap script ... ok517performing post-bootstrap initialization ... ok518syncing data to disk ... ok519520initdb: warning: enabling "trust" authentication for local connections521initdb: 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.522523Success. You can now start the database server using:524525 pg_ctl -D /private/var/tb/7/scratch/63b205a296af2db3/build/postgres1531803411/data -l logfile start5265272026-11-04 20:13:34.352 UTC [55136] LOG: starting PostgreSQL 18.6 on aarch64-apple-darwin25.6.0, compiled by clang version 21.1.8, 64-bit5282026-11-04 20:13:34.352 UTC [55136] LOG: listening on Unix socket "/private/var/tb/7/scratch/63b205a296af2db3/build/postgres1531803411/.s.PGSQL.5432"5292026-11-04 20:13:34.355 UTC [55143] LOG: database system was shut down at 2026-11-04 20:13:34 UTC5302026-11-04 20:13:34.356 UTC [55136] LOG: database system is ready to accept connections531/private/var/tb/7/scratch/63b205a296af2db3/build/postgres1531803411:5432 - accepting connections532{"timestamp":"2026-11-04T20:13:40.498677Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"57c7d40c-f8c2-488e-95cd-fa4f6084bf7b","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":1,"result":"server_error","target":"rustfs::server::http","filename":"rustfs/src/server/layer.rs","line_number":502,"threadName":"rustfs-worker","threadId":"ThreadId(3)"}533{"timestamp":"2026-11-04T20:13:40.603772Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"e2adba87-b586-4c6f-ae1f-6f53baea1dc7","trace_id":"unknown","span_id":"unknown","peer_addr":"127.0.0.1","method":"GET","uri":"/health/ready","status_code":503,"suppressed_errors":0,"duration_ms":0,"result":"server_error","target":"rustfs::server::http","filename":"rustfs/src/server/layer.rs","line_number":502,"threadName":"rustfs-worker","threadId":"ThreadId(4)"}534=== RUN TestService_AuthMiddleware535=== PAUSE TestService_AuthMiddleware536=== RUN TestService_AuthMiddleware_MTLSProxyHeader537=== PAUSE TestService_AuthMiddleware_MTLSProxyHeader538=== RUN TestService_AuthMiddleware_MTLSBoundSubjects539=== PAUSE TestService_AuthMiddleware_MTLSBoundSubjects540=== RUN TestService_ReadAuthMiddleware541=== PAUSE TestService_ReadAuthMiddleware542=== RUN TestService_AuthMiddleware_OIDC543=== PAUSE TestService_AuthMiddleware_OIDC544=== RUN TestService_RequireScope_OIDC545=== PAUSE TestService_RequireScope_OIDC546=== RUN TestService_ReadScope_PublicByDefault547=== PAUSE TestService_ReadScope_PublicByDefault548=== RUN TestCacheConfigHandler549=== PAUSE TestCacheConfigHandler550=== RUN TestCacheStatsHandler551=== PAUSE TestCacheStatsHandler552=== RUN TestClientCADerivations553=== PAUSE TestClientCADerivations554=== RUN TestClientErrorHandling555=== PAUSE TestClientErrorHandling556=== RUN TestClientIntegration557=== PAUSE TestClientIntegration558=== RUN TestClientMultipleUploads559=== PAUSE TestClientMultipleUploads560=== RUN TestClientWithDependencies561=== PAUSE TestClientWithDependencies562=== RUN TestClientSharedPathCommittedMidPush563=== PAUSE TestClientSharedPathCommittedMidPush564=== RUN TestPinProtectsFromGC565=== PAUSE TestPinProtectsFromGC566=== RUN TestClientPushesUseOnePush567=== PAUSE TestClientPushesUseOnePush568=== RUN TestClientFallsBackToClosures569=== PAUSE TestClientFallsBackToClosures570=== RUN TestDeleteClosuresRacingPins571=== PAUSE TestDeleteClosuresRacingPins572=== RUN TestConcurrentCommitsSharingObjectsDoNotDeadlock573=== PAUSE TestConcurrentCommitsSharingObjectsDoNotDeadlock574=== RUN TestResolveDBConnectionString575=== PAUSE TestResolveDBConnectionString576=== RUN TestConnectWaitsForAPeerMigration577=== PAUSE TestConnectWaitsForAPeerMigration578=== RUN TestLeadElectsOneAndHandsOver579=== PAUSE TestLeadElectsOneAndHandsOver580=== RUN TestLeadIncumbentWinsAfterRestart5812026/11/04 20:13:41 INFO lead: acquired remote=192.0.2.1:12345822026/11/04 20:13:41 INFO lead: released remote=192.0.2.1:12345832026/11/04 20:13:41 INFO lead: acquired remote=192.0.2.1:12345842026/11/04 20:13:42 INFO lead: released remote=192.0.2.1:1234585--- PASS: TestLeadIncumbentWinsAfterRestart (2.16s)586=== RUN TestLeadIncumbentAnnouncesAtOnce587=== PAUSE TestLeadIncumbentAnnouncesAtOnce588=== RUN TestLeadEndsOnShutdown589=== PAUSE TestLeadEndsOnShutdown590=== RUN TestLeadEndsWhenItsConnectionHangs5912026/11/04 20:13:43 INFO lead: acquired remote=192.0.2.1:12345922026-11-04 20:13:44.442 UTC [55184] FATAL: terminating connection due to administrator command5932026/11/04 20:13:44 INFO lead: acquired remote=192.0.2.1:12345942026/11/04 20:13:45 WARN lead: lock connection lost error="timeout: context deadline exceeded"5952026/11/04 20:13:45 INFO lead: released remote=192.0.2.1:12345962026/11/04 20:13:45 INFO lead: released remote=192.0.2.1:1234597--- PASS: TestLeadEndsWhenItsConnectionHangs (2.97s)598=== RUN TestGCAdvisoryLockBlocksConcurrentRun599=== PAUSE TestGCAdvisoryLockBlocksConcurrentRun600=== RUN TestGCBugBareHashReferences601=== PAUSE TestGCBugBareHashReferences602=== RUN TestGCMetrics603=== PAUSE TestGCMetrics604=== RUN TestPushDedupSurvivesConcurrentGC605=== PAUSE TestPushDedupSurvivesConcurrentGC606=== RUN TestDeduplicatedObjectsRecordedAsPending607=== PAUSE TestDeduplicatedObjectsRecordedAsPending608=== RUN TestGCSweepSkipsPendingObjects609=== PAUSE TestGCSweepSkipsPendingObjects610=== RUN TestTombstonedObjectOfferedWithoutWaiting611=== PAUSE TestTombstonedObjectOfferedWithoutWaiting612=== RUN TestGCSweepDeliversEachKeyOnce613=== PAUSE TestGCSweepDeliversEachKeyOnce614=== RUN TestCreatePendingClosureVerifyS3FailureReleasesConnection615=== PAUSE TestCreatePendingClosureVerifyS3FailureReleasesConnection616=== RUN TestForceGCDuringPushOffersSweptObject617=== PAUSE TestForceGCDuringPushOffersSweptObject618=== RUN TestFailedS3DeleteKeepsTombstone619=== PAUSE TestFailedS3DeleteKeepsTombstone620=== RUN TestSweepSkipsRowsLockedByPush621=== PAUSE TestSweepSkipsRowsLockedByPush622=== RUN TestRegisterCompletedObjectNeedsPendingRow623=== PAUSE TestRegisterCompletedObjectNeedsPendingRow624=== RUN TestGetExistingObjectsLocksRows625=== PAUSE TestGetExistingObjectsLocksRows626=== RUN TestSweepRechecksPendingAfterLocking627=== PAUSE TestSweepRechecksPendingAfterLocking628=== RUN TestPushWaitsForSweepHoldingRow629=== PAUSE TestPushWaitsForSweepHoldingRow630=== RUN TestCommitRacingPendingCleanupKeepsObjects631=== PAUSE TestCommitRacingPendingCleanupKeepsObjects632=== RUN TestGCEndsOnShutdown633=== PAUSE TestGCEndsOnShutdown634=== RUN TestGCTaskStore_StartNew635=== PAUSE TestGCTaskStore_StartNew636=== RUN TestGCTaskStore_DeduplicateSameParams637=== PAUSE TestGCTaskStore_DeduplicateSameParams638=== RUN TestGCTaskStore_ConflictDifferentParams639=== PAUSE TestGCTaskStore_ConflictDifferentParams640=== RUN TestGCTaskStore_GetEmpty641=== PAUSE TestGCTaskStore_GetEmpty642=== RUN TestGCTaskStore_GetReturnsLatest643=== PAUSE TestGCTaskStore_GetReturnsLatest644=== RUN TestGCTaskStore_CompletedAllowsNewTask645=== PAUSE TestGCTaskStore_CompletedAllowsNewTask646=== RUN TestGCTaskStore_PhaseUpdates647=== PAUSE TestGCTaskStore_PhaseUpdates648=== RUN TestGCTaskStore_Fail649=== PAUSE TestGCTaskStore_Fail650=== RUN TestGracefulShutdownDrainsInflight651=== PAUSE TestGracefulShutdownDrainsInflight652=== RUN TestService_healthCheckHandler653=== PAUSE TestService_healthCheckHandler654=== RUN TestService_readinessHandler655=== PAUSE TestService_readinessHandler656=== RUN TestGenerateLandingPage657=== PAUSE TestGenerateLandingPage658=== RUN TestCacheConfigHandlerMaxNarSize659=== PAUSE TestCacheConfigHandlerMaxNarSize660=== RUN TestCreatePendingClosureRejectsOversizedNAR661=== PAUSE TestCreatePendingClosureRejectsOversizedNAR662=== RUN TestNARDeduplicationMetadataUploadBug663=== PAUSE TestNARDeduplicationMetadataUploadBug664=== RUN TestMetricsInventory665=== PAUSE TestMetricsInventory666=== RUN TestMetricsCommit667=== PAUSE TestMetricsCommit668=== RUN TestService_NativeMTLS669=== PAUSE TestService_NativeMTLS670=== RUN TestServerTLSConfig671=== PAUSE TestServerTLSConfig672=== RUN TestMultipartCleanup673=== PAUSE TestMultipartCleanup674=== RUN TestMultipartUploadAbortedWhenCancelledBeforeRecorded675=== PAUSE TestMultipartUploadAbortedWhenCancelledBeforeRecorded676=== RUN TestPendingCleanupUsesOneCutoff677=== PAUSE TestPendingCleanupUsesOneCutoff678=== RUN TestObjectStatsTrigger679=== PAUSE TestObjectStatsTrigger680=== RUN TestObjectStatsUpdatedOncePerCommit681=== PAUSE TestObjectStatsUpdatedOncePerCommit682=== RUN TestOrphanedObjectsGC683=== PAUSE TestOrphanedObjectsGC684=== RUN TestOrphanedObjectsGCStressTest685=== PAUSE TestOrphanedObjectsGCStressTest686=== RUN TestCreatePin_ReservedPins687=== PAUSE TestCreatePin_ReservedPins688=== RUN TestPresentReportsOnlyClosureRoots689=== PAUSE TestPresentReportsOnlyClosureRoots690=== RUN TestPresentRefreshesOnlyStaleClosures691=== PAUSE TestPresentRefreshesOnlyStaleClosures692=== RUN TestPresentNotReportedWhileGCDeletesClosure693=== PAUSE TestPresentNotReportedWhileGCDeletesClosure694=== RUN TestParseSingleRange695=== PAUSE TestParseSingleRange696=== RUN TestProxyHeadersOnlyTrustedOnSocket6972026/11/04 20:13:45 INFO Starting HTTP server address=proxy.sock6982026/11/04 20:13:45 INFO Starting HTTP server address=127.0.0.1:653616992026/11/04 20:13:46 WARN mTLS auth: subject not in bound subjects subject="CN=someone"7002026/11/04 20:13:46 INFO Shutdown signal received, draining in-flight requests timeout=10s701--- PASS: TestProxyHeadersOnlyTrustedOnSocket (0.17s)702=== RUN TestIsValidCachePath703=== PAUSE TestIsValidCachePath704=== RUN TestReadProxyNarinfo705=== PAUSE TestReadProxyNarinfo706=== RUN TestReadProxyNarinfoAlreadyDecompressed707=== PAUSE TestReadProxyNarinfoAlreadyDecompressed708=== RUN TestReadProxyContentNegotiation709=== PAUSE TestReadProxyContentNegotiation710=== RUN TestReadProxyNarStreaming711=== PAUSE TestReadProxyNarStreaming712=== RUN TestReadProxy404713=== PAUSE TestReadProxy404714=== RUN TestReadProxyInvalidPath715=== PAUSE TestReadProxyInvalidPath716=== RUN TestReadProxyHead717=== PAUSE TestReadProxyHead718=== RUN TestReadProxyOutlastsServerWriteTimeout719=== PAUSE TestReadProxyOutlastsServerWriteTimeout720=== RUN TestReadProxyConditionalGet721=== PAUSE TestReadProxyConditionalGet722=== RUN TestReadProxyRootRedirectsToIndexHTML723=== PAUSE TestReadProxyRootRedirectsToIndexHTML724=== RUN TestReadProxyDisabled725=== PAUSE TestReadProxyDisabled726=== RUN TestReadRedirectNar727=== PAUSE TestReadRedirectNar728=== RUN TestReadRedirectKeepsNarinfoProxied729=== PAUSE TestReadRedirectKeepsNarinfoProxied730=== RUN TestReadProxyRangeRequest731=== PAUSE TestReadProxyRangeRequest732=== RUN TestReadRedirectUsesPublicS3URL733=== PAUSE TestReadRedirectUsesPublicS3URL734=== RUN TestPush_OverlappingRootsStoreOneRowPerKey735=== PAUSE TestPush_OverlappingRootsStoreOneRowPerKey736=== RUN TestPush_CompleteCommitsEveryRoot737=== PAUSE TestPush_CompleteCommitsEveryRoot738=== RUN TestPush_RepeatedRootCommitsOnce739=== PAUSE TestPush_RepeatedRootCommitsOnce740=== RUN TestPush_CompleteWaitsForCleanupOfThePush741=== PAUSE TestPush_CompleteWaitsForCleanupOfThePush742=== RUN TestPush_RootsAreLockedInByteOrder743=== PAUSE TestPush_RootsAreLockedInByteOrder744=== RUN TestPush_SkippedKeySurvivesGCBeforeCommit745=== PAUSE TestPush_SkippedKeySurvivesGCBeforeCommit746=== RUN TestPush_RejectsBadRequests747=== PAUSE TestPush_RejectsBadRequests748=== RUN TestPush_SignsNarinfosOfItsPendingObjects749=== PAUSE TestPush_SignsNarinfosOfItsPendingObjects750=== RUN TestRedundantMultipartUpload751=== PAUSE TestRedundantMultipartUpload752=== RUN TestCompleteMultipartUpload_ErrorButObjectExists753=== PAUSE TestCompleteMultipartUpload_ErrorButObjectExists754=== RUN TestCompletedNarNotReofferedAcrossClosures755=== PAUSE TestCompletedNarNotReofferedAcrossClosures756=== RUN TestPresignedUploadRegisteredBeforeCommit757=== PAUSE TestPresignedUploadRegisteredBeforeCommit758=== RUN TestService_Rustfstest759=== PAUSE TestService_Rustfstest760=== RUN TestParseSize761=== PAUSE TestParseSize762=== RUN TestSkippedUploadsHandler763=== PAUSE TestSkippedUploadsHandler764=== RUN TestSystemdListenerNotActivated765--- PASS: TestSystemdListenerNotActivated (0.00s)766=== RUN TestWatchdogBeatsWhenHealthy767--- PASS: TestWatchdogBeatsWhenHealthy (0.03s)768=== RUN TestWatchdogSkipsWhenUnhealthy7692026/11/04 20:13:46 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7702026/11/04 20:13:46 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7712026/11/04 20:13:46 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7722026/11/04 20:13:46 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7732026/11/04 20:13:46 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7742026/11/04 20:13:46 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7752026/11/04 20:13:46 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7762026/11/04 20:13:46 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7772026/11/04 20:13:46 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7782026/11/04 20:13:46 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"779--- PASS: TestWatchdogSkipsWhenUnhealthy (0.21s)780=== RUN TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle781=== PAUSE TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle782=== RUN TestProxyWriteTimeout783=== PAUSE TestProxyWriteTimeout784=== RUN TestPendingClosureWriteTimeout785=== PAUSE TestPendingClosureWriteTimeout786=== RUN TestIsValidUploadKey787=== PAUSE TestIsValidUploadKey788=== RUN TestUploadHandlersRejectInvalidKeys789=== PAUSE TestUploadHandlersRejectInvalidKeys790=== RUN TestUploadHandlersRejectOversizedBody791=== PAUSE TestUploadHandlersRejectOversizedBody792=== RUN TestService_cleanupPendingClosuresHandler793=== PAUSE TestService_cleanupPendingClosuresHandler794=== RUN TestService_createPendingClosureHandler795=== PAUSE TestService_createPendingClosureHandler796=== RUN TestService_verifyS3Integrity797=== PAUSE TestService_verifyS3Integrity798=== RUN TestService_verifyS3ReuploadsStaleNarinfo799=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo800=== RUN TestCompleteMultipartUnregistered801=== PAUSE TestCompleteMultipartUnregistered802=== RUN TestCreatePendingClosure_SmallNARUsesSimplePUT803=== PAUSE TestCreatePendingClosure_SmallNARUsesSimplePUT804=== CONT TestReadProxyRootRedirectsToIndexHTML805=== CONT TestCommitRacingPendingCleanupKeepsObjects806=== CONT TestSweepRechecksPendingAfterLocking807=== CONT TestReadProxyConditionalGet808=== CONT TestReadProxyOutlastsServerWriteTimeout809=== CONT TestPushWaitsForSweepHoldingRow810=== CONT TestGetExistingObjectsLocksRows811=== CONT TestRegisterCompletedObjectNeedsPendingRow812=== CONT TestSweepSkipsRowsLockedByPush813=== CONT TestFailedS3DeleteKeepsTombstone814=== CONT TestForceGCDuringPushOffersSweptObject815=== RUN TestForceGCDuringPushOffersSweptObject/before_pending_rows816=== CONT TestClientPushesUseOnePush817=== PAUSE TestForceGCDuringPushOffersSweptObject/before_pending_rows818=== CONT TestClientFallsBackToClosures819=== RUN TestForceGCDuringPushOffersSweptObject/after_presence_check820=== PAUSE TestForceGCDuringPushOffersSweptObject/after_presence_check821=== CONT TestService_ReadScope_PublicByDefault822=== CONT TestCreatePendingClosureVerifyS3FailureReleasesConnection823=== CONT TestGCSweepDeliversEachKeyOnce824=== CONT TestTombstonedObjectOfferedWithoutWaiting825=== CONT TestGCSweepSkipsPendingObjects826=== CONT TestDeduplicatedObjectsRecordedAsPending827=== CONT TestPushDedupSurvivesConcurrentGC828=== CONT TestPinProtectsFromGC829=== CONT TestGCMetrics830=== CONT TestClientSharedPathCommittedMidPush831=== CONT TestGCBugBareHashReferences832=== CONT TestService_AuthMiddleware8332026/11/04 20:13:47 INFO Aborted multipart uploads count=0 kept=08342026/11/04 20:13:47 WARN Force mode enabled - objects will be deleted immediately without grace period8352026/11/04 20:13:47 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=08362026/11/04 20:13:47 INFO Vacuumed table table=pending_closures8372026/11/04 20:13:47 INFO Vacuumed table table=pending_objects8382026/11/04 20:13:47 INFO Vacuumed table table=multipart_uploads8392026/11/04 20:13:47 INFO Vacuumed table table=closures8402026/11/04 20:13:47 INFO Vacuumed table table=objects841--- PASS: TestSweepRechecksPendingAfterLocking (1.24s)842=== CONT TestService_RequireScope_OIDC8432026/11/04 20:13:47 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:65369/oidc8442026/11/04 20:13:47 INFO Aborted multipart uploads count=0 kept=08452026/11/04 20:13:47 WARN Force mode enabled - objects will be deleted immediately without grace period8462026/11/04 20:13:47 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=08472026/11/04 20:13:47 INFO Vacuumed table table=pending_closures8482026/11/04 20:13:47 INFO Vacuumed table table=pending_objects8492026/11/04 20:13:47 INFO Vacuumed table table=multipart_uploads8502026/11/04 20:13:47 INFO Vacuumed table table=closures8512026/11/04 20:13:47 INFO Vacuumed table table=objects852--- PASS: TestCommitRacingPendingCleanupKeepsObjects (1.57s)853=== CONT TestGCAdvisoryLockBlocksConcurrentRun854--- PASS: TestReadProxyRootRedirectsToIndexHTML (1.94s)855=== CONT TestLeadEndsOnShutdown856--- PASS: TestGetExistingObjectsLocksRows (2.14s)857=== CONT TestLeadIncumbentAnnouncesAtOnce858--- PASS: TestRegisterCompletedObjectNeedsPendingRow (2.27s)859=== CONT TestCacheConfigHandler860=== RUN TestCacheConfigHandler/full_config,_no_issuer861=== PAUSE TestCacheConfigHandler/full_config,_no_issuer862=== RUN TestCacheConfigHandler/no_cache_url_configured863=== PAUSE TestCacheConfigHandler/no_cache_url_configured864=== RUN TestCacheConfigHandler/no_signing_keys865=== PAUSE TestCacheConfigHandler/no_signing_keys866=== RUN TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator867=== PAUSE TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator868=== CONT TestService_AuthMiddleware_OIDC8692026/11/04 20:13:48 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:65383/oidc870--- PASS: TestReadProxyConditionalGet (2.42s)871=== CONT TestService_ReadAuthMiddleware8722026/11/04 20:13:48 INFO Received uploads request method=POST path=/api/pending_closures8732026/11/04 20:13:49 INFO Aborted multipart uploads count=0 kept=08742026/11/04 20:13:49 WARN Force mode enabled - objects will be deleted immediately without grace period8752026/11/04 20:13:49 ERROR failed to remove object object=nar/dddddddddddddddddddddddddddddddddddddddddddddddddddd.nar.zst error="Access Denied."8762026/11/04 20:13:49 ERROR failed to remove object object=dddddddddddddddddddddddddddddddd.narinfo error="Access Denied."877--- PASS: TestFailedS3DeleteKeepsTombstone (2.77s)878=== CONT TestClientWithDependencies8792026/11/04 20:13:49 INFO Received uploads request method=POST path=/api/pending_closures880--- PASS: TestService_ReadScope_PublicByDefault (2.96s)881=== CONT TestClientMultipleUploads882--- PASS: TestPushWaitsForSweepHoldingRow (3.31s)883=== CONT TestClientIntegration8842026/11/04 20:13:49 INFO Aborted multipart uploads count=0 kept=08852026/11/04 20:13:49 WARN Force mode enabled - objects will be deleted immediately without grace period8862026/11/04 20:13:49 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=08872026/11/04 20:13:49 INFO Vacuumed table table=pending_closures8882026/11/04 20:13:49 INFO Vacuumed table table=pending_objects8892026/11/04 20:13:49 INFO Vacuumed table table=multipart_uploads8902026/11/04 20:13:49 INFO Vacuumed table table=closures8912026/11/04 20:13:49 INFO Vacuumed table table=objects8922026/11/04 20:13:49 INFO Aborted multipart uploads count=0 kept=08932026/11/04 20:13:49 WARN Force mode enabled - objects will be deleted immediately without grace period8942026/11/04 20:13:49 INFO Received uploads request method=POST path=/api/pending_closures8952026/11/04 20:13:49 INFO Received push request method=POST path=/api/pushes8962026/11/04 20:13:49 INFO Uploading 2 paths to 127.0.0.1 (0 already cached)8972026/11/04 20:13:49 INFO Uploading jiwgr9yxzq4ycx7rnn3vqxbm8i43vq99-shared-dep (136B)8982026/11/04 20:13:49 INFO Uploading 9n4xlp8srncjddgsy2ql1iykl7cqvh1p-top (264B)8992026/11/04 20:13:49 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=09002026/11/04 20:13:49 INFO Vacuumed table table=pending_closures9012026/11/04 20:13:49 INFO Vacuumed table table=pending_objects9022026/11/04 20:13:49 INFO Vacuumed table table=multipart_uploads9032026/11/04 20:13:49 INFO Vacuumed table table=closures9042026/11/04 20:13:49 WARN Failed to register uploaded object key=jiwgr9yxzq4ycx7rnn3vqxbm8i43vq99.ls error="server returned 404: 404 page not found\n"9052026/11/04 20:13:49 INFO Vacuumed table table=objects9062026/11/04 20:13:49 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"907--- PASS: TestSweepSkipsRowsLockedByPush (3.63s)908=== CONT TestClientErrorHandling909=== RUN TestClientErrorHandling/InvalidStorePath910=== PAUSE TestClientErrorHandling/InvalidStorePath911=== RUN TestClientErrorHandling/InvalidAuthToken912=== PAUSE TestClientErrorHandling/InvalidAuthToken913=== RUN TestClientErrorHandling/ServerNotAvailable914=== PAUSE TestClientErrorHandling/ServerNotAvailable915=== CONT TestClientCADerivations9162026/11/04 20:13:49 WARN Failed to register uploaded object key=nar/0cb4h0kb6h247x29i2zm15p06bc78aw40zkgwckykjwxscm3zylj.nar.zst error="server returned 404: 404 page not found\n"9172026/11/04 20:13:49 WARN Failed to register uploaded object key=9n4xlp8srncjddgsy2ql1iykl7cqvh1p.ls error="server returned 404: 404 page not found\n"9182026/11/04 20:13:49 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign9192026/11/04 20:13:49 INFO Signed narinfos id=1 count=29202026/11/04 20:13:49 INFO Uploading 2 narinfos9212026/11/04 20:13:49 WARN Failed to register uploaded object key=9n4xlp8srncjddgsy2ql1iykl7cqvh1p.narinfo error="server returned 404: 404 page not found\n"9222026/11/04 20:13:49 INFO Received complete push request method=POST path=/api/pushes/1/complete9232026/11/04 20:13:49 WARN Failed to register uploaded object key=jiwgr9yxzq4ycx7rnn3vqxbm8i43vq99.narinfo error="server returned 404: 404 page not found\n"9242026/11/04 20:13:49 INFO Completed push id=1 objects=6 duration=7.177834ms9252026/11/04 20:13:49 INFO Upload complete. (193ms)926=== NAME TestClientSharedPathCommittedMidPush927 client_integration_test.go:727: Retrieved narinfo from S3:928 StorePath: /private/var/tb/7/scratch/63b205a296af2db3/build/TestClientSharedPathCommittedMidPush2502264708/001/store/jiwgr9yxzq4ycx7rnn3vqxbm8i43vq99-shared-dep929 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst930 Compression: zstd931 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82932 NarSize: 136933 References: 934 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n935 client_integration_test.go:727: Retrieved narinfo from S3:936 StorePath: /private/var/tb/7/scratch/63b205a296af2db3/build/TestClientSharedPathCommittedMidPush2502264708/001/store/9n4xlp8srncjddgsy2ql1iykl7cqvh1p-top937 URL: nar/0cb4h0kb6h247x29i2zm15p06bc78aw40zkgwckykjwxscm3zylj.nar.zst938 Compression: zstd939 NarHash: sha256:0cb4h0kb6h247x29i2zm15p06bc78aw40zkgwckykjwxscm3zylj940 NarSize: 264941 References: /private/var/tb/7/scratch/63b205a296af2db3/build/TestClientSharedPathCommittedMidPush2502264708/001/store/jiwgr9yxzq4ycx7rnn3vqxbm8i43vq99-shared-dep942 CA: text:sha256:0ablhqbcrcz2066y11j2jid2jyjr1djqxwvi5p128jdparnf9n10943--- PASS: TestClientSharedPathCommittedMidPush (3.71s)944=== CONT TestService_AuthMiddleware_MTLSBoundSubjects945--- PASS: TestCreatePendingClosureVerifyS3FailureReleasesConnection (3.74s)946=== CONT TestCacheStatsHandler9472026/11/04 20:13:50 INFO Aborted multipart uploads count=0 kept=09482026/11/04 20:13:50 WARN Force mode enabled - objects will be deleted immediately without grace period9492026/11/04 20:13:50 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=09502026/11/04 20:13:50 INFO Vacuumed table table=pending_closures9512026/11/04 20:13:50 INFO Vacuumed table table=pending_objects9522026/11/04 20:13:50 INFO Vacuumed table table=multipart_uploads9532026/11/04 20:13:50 INFO Vacuumed table table=closures9542026/11/04 20:13:50 INFO Vacuumed table table=objects955--- PASS: TestGCMetrics (3.92s)956=== CONT TestService_AuthMiddleware_MTLSProxyHeader9572026/11/04 20:13:50 INFO Received push request method=POST path=/api/pushes9582026/11/04 20:13:50 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)9592026/11/04 20:13:50 INFO Uploading z8yq023vlnc2y0q1s4syn6qyhr7d61jj-b (256B)9602026/11/04 20:13:50 INFO Uploading 0gwvc84cg4495yc8xibbsz4hsvgk3nps-shared-dep (136B)9612026/11/04 20:13:50 WARN Failed to register uploaded object key=gz3mrqp6c1icwnlmlw33fs9inp73awc8.ls error="server returned 404: 404 page not found\n"9622026/11/04 20:13:50 WARN Failed to register uploaded object key=0gwvc84cg4495yc8xibbsz4hsvgk3nps.ls error="server returned 404: 404 page not found\n"9632026/11/04 20:13:50 WARN Failed to register uploaded object key=z8yq023vlnc2y0q1s4syn6qyhr7d61jj.ls error="server returned 404: 404 page not found\n"9642026/11/04 20:13:50 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"9652026/11/04 20:13:50 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign9662026/11/04 20:13:50 WARN Failed to register uploaded object key=nar/1ff5lvb15z17rb2l8fkd4zbwh55gyhidc38fw078m0ahf0r01z3q.nar.zst error="server returned 404: 404 page not found\n"9672026/11/04 20:13:50 INFO Signed narinfos id=1 count=39682026/11/04 20:13:50 INFO Uploading 3 narinfos9692026/11/04 20:13:50 WARN Failed to register uploaded object key=gz3mrqp6c1icwnlmlw33fs9inp73awc8.narinfo error="server returned 404: 404 page not found\n"9702026/11/04 20:13:50 WARN Failed to register uploaded object key=z8yq023vlnc2y0q1s4syn6qyhr7d61jj.narinfo error="server returned 404: 404 page not found\n"9712026/11/04 20:13:50 INFO Received complete push request method=POST path=/api/pushes/1/complete9722026/11/04 20:13:50 WARN Failed to register uploaded object key=0gwvc84cg4495yc8xibbsz4hsvgk3nps.narinfo error="server returned 404: 404 page not found\n"9732026/11/04 20:13:50 INFO Completed push id=1 objects=8 duration=15.836209ms9742026/11/04 20:13:50 INFO Upload complete. (220ms)975=== NAME TestClientPushesUseOnePush976 client_pushes_test.go:97: Retrieved narinfo from S3:977 StorePath: /private/var/tb/7/scratch/63b205a296af2db3/build/TestClientPushesUseOnePush2254679110/001/store/0gwvc84cg4495yc8xibbsz4hsvgk3nps-shared-dep978 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst979 Compression: zstd980 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82981 NarSize: 136982 References: 983 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n984 client_pushes_test.go:97: Retrieved narinfo from S3:985 StorePath: /private/var/tb/7/scratch/63b205a296af2db3/build/TestClientPushesUseOnePush2254679110/001/store/gz3mrqp6c1icwnlmlw33fs9inp73awc8-a986 URL: nar/1ff5lvb15z17rb2l8fkd4zbwh55gyhidc38fw078m0ahf0r01z3q.nar.zst987 Compression: zstd988 NarHash: sha256:1ff5lvb15z17rb2l8fkd4zbwh55gyhidc38fw078m0ahf0r01z3q989 NarSize: 256990 References: /private/var/tb/7/scratch/63b205a296af2db3/build/TestClientPushesUseOnePush2254679110/001/store/0gwvc84cg4495yc8xibbsz4hsvgk3nps-shared-dep991 CA: text:sha256:1kvdzh4ww2k3y84l6drym3qsg1s1b2xblq1b3jbl1mjq2c9d0yg1992 client_pushes_test.go:97: Retrieved narinfo from S3:993 StorePath: /private/var/tb/7/scratch/63b205a296af2db3/build/TestClientPushesUseOnePush2254679110/001/store/z8yq023vlnc2y0q1s4syn6qyhr7d61jj-b994 URL: nar/1ff5lvb15z17rb2l8fkd4zbwh55gyhidc38fw078m0ahf0r01z3q.nar.zst995 Compression: zstd996 NarHash: sha256:1ff5lvb15z17rb2l8fkd4zbwh55gyhidc38fw078m0ahf0r01z3q997 NarSize: 256998 References: /private/var/tb/7/scratch/63b205a296af2db3/build/TestClientPushesUseOnePush2254679110/001/store/0gwvc84cg4495yc8xibbsz4hsvgk3nps-shared-dep999 CA: text:sha256:1kvdzh4ww2k3y84l6drym3qsg1s1b2xblq1b3jbl1mjq2c9d0yg11000--- PASS: TestClientPushesUseOnePush (4.22s)1001=== CONT TestPresignedUploadRegisteredBeforeCommit1002--- PASS: TestGCBugBareHashReferences (4.32s)1003=== CONT TestCreatePendingClosure_SmallNARUsesSimplePUT10042026/11/04 20:13:50 INFO Aborted multipart uploads count=0 kept=010052026/11/04 20:13:50 WARN Force mode enabled - objects will be deleted immediately without grace period10062026/11/04 20:13:50 INFO Received uploads request method=POST path=/api/pending_closures1007--- PASS: TestDeduplicatedObjectsRecordedAsPending (4.55s)1008=== CONT TestCompleteMultipartUnregistered10092026/11/04 20:13:51 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=010102026/11/04 20:13:51 INFO Vacuumed table table=pending_closures10112026/11/04 20:13:51 INFO Vacuumed table table=pending_objects10122026/11/04 20:13:51 INFO Vacuumed table table=multipart_uploads10132026/11/04 20:13:51 INFO Vacuumed table table=closures10142026/11/04 20:13:51 INFO Vacuumed table table=objects1015--- PASS: TestGCSweepDeliversEachKeyOnce (4.84s)1016=== CONT TestService_verifyS3ReuploadsStaleNarinfo1017=== RUN TestService_verifyS3ReuploadsStaleNarinfo/lost,_other_NAR_pushed1018=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo/lost,_other_NAR_pushed1019=== RUN TestService_verifyS3ReuploadsStaleNarinfo/intact,_other_NAR_pushed1020=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo/intact,_other_NAR_pushed1021=== RUN TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost1022=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost1023=== RUN TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost,_second_pushed1024=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost,_second_pushed1025=== RUN TestService_verifyS3ReuploadsStaleNarinfo/lost,_same_NAR_pushed1026=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo/lost,_same_NAR_pushed1027=== CONT TestPush_CompleteWaitsForCleanupOfThePush10282026/11/04 20:13:51 INFO Received uploads request method=POST path=/api/pending_closures10292026/11/04 20:13:51 INFO Aborted multipart uploads count=0 kept=010302026/11/04 20:13:51 WARN Force mode enabled - objects will be deleted immediately without grace period10312026/11/04 20:13:51 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=010322026/11/04 20:13:51 INFO Vacuumed table table=pending_closures10332026/11/04 20:13:51 INFO Vacuumed table table=pending_objects10342026/11/04 20:13:51 INFO Vacuumed table table=multipart_uploads10352026/11/04 20:13:51 INFO Vacuumed table table=closures10362026/11/04 20:13:51 INFO Vacuumed table table=objects1037--- PASS: TestGCSweepSkipsPendingObjects (5.04s)1038=== CONT TestService_verifyS3Integrity10392026/11/04 20:13:51 INFO Received uploads request method=POST path=/api/pending_closures1040=== NAME TestPinProtectsFromGC1041 client_integration_test.go:778: Pinned store path: /private/var/tb/7/scratch/63b205a296af2db3/build/TestPinProtectsFromGC2048845498/001/store/3ph864qlrif8mf5k0jjck1lvyk6ixysw-pinned-file.txt1042 client_integration_test.go:779: Unpinned store path: /private/var/tb/7/scratch/63b205a296af2db3/build/TestPinProtectsFromGC2048845498/001/store/xn2bbzp274il0y3v84lf18zq4f196260-unpinned-file.txt10432026/11/04 20:13:51 INFO Received uploads request method=POST path=/api/pending_closures10442026/11/04 20:13:51 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)10452026/11/04 20:13:51 INFO Uploading yyybx3dnpnqng5rzlfa4w11ar5ialm24-shared-dep (136B)10462026/11/04 20:13:51 INFO Uploading wl7fg10s1lw6yd8w0q4a063p81kxg3rd-b (256B)10472026/11/04 20:13:51 WARN Failed to register uploaded object key=qzvm6ayybc9sfqz4m70d8ym030nidwm0.ls error="server returned 404: 404 page not found\n"10482026/11/04 20:13:51 WARN Failed to register uploaded object key=nar/1g4ls036lkqj10avgw2zwqr7y2bl2br978fjw6wgm22xgja7nxsg.nar.zst error="server returned 404: 404 page not found\n"10492026/11/04 20:13:51 WARN Failed to register uploaded object key=yyybx3dnpnqng5rzlfa4w11ar5ialm24.ls error="server returned 404: 404 page not found\n"10502026/11/04 20:13:51 WARN Failed to register uploaded object key=wl7fg10s1lw6yd8w0q4a063p81kxg3rd.ls error="server returned 404: 404 page not found\n"10512026/11/04 20:13:51 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign10522026/11/04 20:13:51 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"10532026/11/04 20:13:51 INFO Signed narinfos id=1 count=210542026/11/04 20:13:51 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign10552026/11/04 20:13:51 INFO Received push request method=POST path=/api/pushes10562026/11/04 20:13:51 INFO Signed narinfos id=2 count=210572026/11/04 20:13:51 INFO Uploading 4 narinfos10582026/11/04 20:13:51 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)10592026/11/04 20:13:51 INFO Uploading 3ph864qlrif8mf5k0jjck1lvyk6ixysw-pinned-file.txt (128B)10602026/11/04 20:13:51 WARN Failed to register uploaded object key=qzvm6ayybc9sfqz4m70d8ym030nidwm0.narinfo error="server returned 404: 404 page not found\n"10612026/11/04 20:13:51 INFO Received uploads request method=POST path=/api/pending_closures10622026/11/04 20:13:51 WARN Failed to register uploaded object key=yyybx3dnpnqng5rzlfa4w11ar5ialm24.narinfo error="server returned 404: 404 page not found\n"10632026/11/04 20:13:51 WARN Failed to register uploaded object key=wl7fg10s1lw6yd8w0q4a063p81kxg3rd.narinfo error="server returned 404: 404 page not found\n"10642026/11/04 20:13:51 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete10652026/11/04 20:13:51 WARN Failed to register uploaded object key=3ph864qlrif8mf5k0jjck1lvyk6ixysw.ls error="server returned 404: 404 page not found\n"10662026/11/04 20:13:51 WARN Failed to register uploaded object key=yyybx3dnpnqng5rzlfa4w11ar5ialm24.narinfo error="server returned 404: 404 page not found\n"10672026/11/04 20:13:51 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign10682026/11/04 20:13:51 WARN Failed to register uploaded object key=nar/0qmhsg42pqsz7x6hh02j8gznnac3yi3qpjhrqbwvz88i194jbb5s.nar.zst error="server returned 404: 404 page not found\n"10692026/11/04 20:13:51 INFO Signed narinfos id=1 count=110702026/11/04 20:13:51 INFO Uploading 1 narinfos10712026/11/04 20:13:51 INFO Completed upload id=1 objects=6 duration=10.317917ms10722026/11/04 20:13:51 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete10732026/11/04 20:13:51 INFO Completed upload id=2 objects=6 duration=572.5µs10742026/11/04 20:13:51 INFO Upload complete. (316ms)1075=== NAME TestClientFallsBackToClosures1076 client_pushes_test.go:112: Retrieved narinfo from S3:1077 StorePath: /private/var/tb/7/scratch/63b205a296af2db3/build/TestClientFallsBackToClosures4265060489/001/store/yyybx3dnpnqng5rzlfa4w11ar5ialm24-shared-dep1078 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1079 Compression: zstd1080 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821081 NarSize: 1361082 References: 1083 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1084 client_pushes_test.go:112: Retrieved narinfo from S3:1085 StorePath: /private/var/tb/7/scratch/63b205a296af2db3/build/TestClientFallsBackToClosures4265060489/001/store/qzvm6ayybc9sfqz4m70d8ym030nidwm0-a1086 URL: nar/1g4ls036lkqj10avgw2zwqr7y2bl2br978fjw6wgm22xgja7nxsg.nar.zst1087 Compression: zstd1088 NarHash: sha256:1g4ls036lkqj10avgw2zwqr7y2bl2br978fjw6wgm22xgja7nxsg1089 NarSize: 2561090 References: /private/var/tb/7/scratch/63b205a296af2db3/build/TestClientFallsBackToClosures4265060489/001/store/yyybx3dnpnqng5rzlfa4w11ar5ialm24-shared-dep1091 CA: text:sha256:04j77rspzpn4cx6whkknrhvaqc1s5yn3npd5lbl5gm3hqfbpcdym1092 client_pushes_test.go:112: Retrieved narinfo from S3:1093 StorePath: /private/var/tb/7/scratch/63b205a296af2db3/build/TestClientFallsBackToClosures4265060489/001/store/wl7fg10s1lw6yd8w0q4a063p81kxg3rd-b1094 URL: nar/1g4ls036lkqj10avgw2zwqr7y2bl2br978fjw6wgm22xgja7nxsg.nar.zst1095 Compression: zstd1096 NarHash: sha256:1g4ls036lkqj10avgw2zwqr7y2bl2br978fjw6wgm22xgja7nxsg1097 NarSize: 2561098 References: /private/var/tb/7/scratch/63b205a296af2db3/build/TestClientFallsBackToClosures4265060489/001/store/yyybx3dnpnqng5rzlfa4w11ar5ialm24-shared-dep1099 CA: text:sha256:04j77rspzpn4cx6whkknrhvaqc1s5yn3npd5lbl5gm3hqfbpcdym11002026/11/04 20:13:51 INFO Received complete push request method=POST path=/api/pushes/1/complete11012026/11/04 20:13:51 WARN Failed to register uploaded object key=3ph864qlrif8mf5k0jjck1lvyk6ixysw.narinfo error="server returned 404: 404 page not found\n"11022026/11/04 20:13:52 INFO Completed push id=1 objects=3 duration=24.899708ms11032026/11/04 20:13:52 INFO Upload complete. (257ms)1104--- PASS: TestClientFallsBackToClosures (5.77s)1105=== CONT TestService_createPendingClosureHandler11062026/11/04 20:13:52 INFO Aborted multipart uploads count=0 kept=011072026/11/04 20:13:52 INFO Received uploads request method=POST path=/api/pending_closures11082026/11/04 20:13:52 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=1 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=01109--- PASS: TestTombstonedObjectOfferedWithoutWaiting (5.81s)1110=== CONT TestService_cleanupPendingClosuresHandler11112026/11/04 20:13:52 INFO Vacuumed table table=pending_closures11122026/11/04 20:13:52 INFO Vacuumed table table=pending_objects11132026/11/04 20:13:52 INFO Vacuumed table table=multipart_uploads11142026/11/04 20:13:52 INFO Received push request method=POST path=/api/pushes11152026/11/04 20:13:52 INFO Vacuumed table table=closures11162026/11/04 20:13:52 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)11172026/11/04 20:13:52 INFO Uploading xn2bbzp274il0y3v84lf18zq4f196260-unpinned-file.txt (128B)11182026/11/04 20:13:52 INFO Vacuumed table table=objects11192026/11/04 20:13:52 INFO Aborted multipart uploads count=0 kept=011202026/11/04 20:13:52 WARN Force mode enabled - objects will be deleted immediately without grace period1121--- PASS: TestReadProxyOutlastsServerWriteTimeout (5.86s)1122=== CONT TestUploadHandlersRejectOversizedBody11232026/11/04 20:13:52 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=011242026/11/04 20:13:52 INFO Vacuumed table table=pending_closures11252026/11/04 20:13:52 WARN Failed to register uploaded object key=xn2bbzp274il0y3v84lf18zq4f196260.ls error="server returned 404: 404 page not found\n"11262026/11/04 20:13:52 WARN Failed to register uploaded object key=nar/0gh0wdnr6gmk4r5sfzzh12isnl14rgmkrwy1ws41hpsrlndclg5h.nar.zst error="server returned 404: 404 page not found\n"11272026/11/04 20:13:52 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign11282026/11/04 20:13:52 INFO Signed narinfos id=2 count=111292026/11/04 20:13:52 INFO Uploading 1 narinfos11302026/11/04 20:13:52 INFO Vacuumed table table=pending_objects11312026/11/04 20:13:52 INFO Vacuumed table table=multipart_uploads11322026/11/04 20:13:52 WARN Authentication failed token_preview=wrongtoken token_length=10 reason="static API token mismatch"1133--- PASS: TestService_AuthMiddleware (5.98s)1134=== CONT TestCompletedNarNotReofferedAcrossClosures11352026/11/04 20:13:52 INFO Vacuumed table table=closures11362026/11/04 20:13:52 INFO Vacuumed table table=objects1137--- PASS: TestPushDedupSurvivesConcurrentGC (6.01s)1138=== CONT TestUploadHandlersRejectInvalidKeys1139=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info11402026/11/04 20:13:52 INFO Received complete push request method=POST path=/api/pushes/2/complete11412026/11/04 20:13:52 WARN Failed to register uploaded object key=xn2bbzp274il0y3v84lf18zq4f196260.narinfo error="server returned 404: 404 page not found\n"1142=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info1143=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal11442026/11/04 20:13:52 INFO Completed push id=2 objects=3 duration=1.171292ms1145=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal11462026/11/04 20:13:52 INFO Upload complete. (232ms)1147=== RUN TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key1148=== PAUSE TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key1149=== RUN TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key1150=== PAUSE TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key1151=== CONT TestIsValidUploadKey1152=== RUN TestIsValidUploadKey/narinfo1153=== PAUSE TestIsValidUploadKey/narinfo1154=== RUN TestIsValidUploadKey/nar_zst1155=== PAUSE TestIsValidUploadKey/nar_zst1156=== RUN TestIsValidUploadKey/nar_xz1157=== PAUSE TestIsValidUploadKey/nar_xz1158=== RUN TestIsValidUploadKey/nar_plain1159=== PAUSE TestIsValidUploadKey/nar_plain1160=== RUN TestIsValidUploadKey/listing1161=== PAUSE TestIsValidUploadKey/listing1162=== RUN TestIsValidUploadKey/build_log1163=== PAUSE TestIsValidUploadKey/build_log1164=== RUN TestIsValidUploadKey/build_log_home-manager_file1165=== PAUSE TestIsValidUploadKey/build_log_home-manager_file1166=== RUN TestIsValidUploadKey/build_log_plus_in_name1167=== PAUSE TestIsValidUploadKey/build_log_plus_in_name1168=== RUN TestIsValidUploadKey/build_log_question_mark1169=== PAUSE TestIsValidUploadKey/build_log_question_mark1170=== RUN TestIsValidUploadKey/build_log_equals1171=== PAUSE TestIsValidUploadKey/build_log_equals1172=== RUN TestIsValidUploadKey/realisation1173=== PAUSE TestIsValidUploadKey/realisation1174=== RUN TestIsValidUploadKey/realisation_plus_in_output1175=== PAUSE TestIsValidUploadKey/realisation_plus_in_output1176=== RUN TestIsValidUploadKey/nix-cache-info1177=== PAUSE TestIsValidUploadKey/nix-cache-info1178=== RUN TestIsValidUploadKey/index.html1179=== PAUSE TestIsValidUploadKey/index.html1180=== RUN TestIsValidUploadKey/narinfo_key,_nar_type1181=== PAUSE TestIsValidUploadKey/narinfo_key,_nar_type1182=== RUN TestIsValidUploadKey/nar_key,_narinfo_type1183=== PAUSE TestIsValidUploadKey/nar_key,_narinfo_type1184=== RUN TestIsValidUploadKey/listing_key,_narinfo_type1185=== PAUSE TestIsValidUploadKey/listing_key,_narinfo_type1186=== RUN TestIsValidUploadKey/traversal1187=== PAUSE TestIsValidUploadKey/traversal1188=== RUN TestIsValidUploadKey/traversal_nar1189=== PAUSE TestIsValidUploadKey/traversal_nar1190=== RUN TestIsValidUploadKey/absolute1191=== PAUSE TestIsValidUploadKey/absolute1192=== RUN TestIsValidUploadKey/empty_key1193=== PAUSE TestIsValidUploadKey/empty_key1194=== RUN TestIsValidUploadKey/unknown_type1195=== PAUSE TestIsValidUploadKey/unknown_type1196=== CONT TestPendingClosureWriteTimeout1197=== RUN TestPendingClosureWriteTimeout/empty1198=== PAUSE TestPendingClosureWriteTimeout/empty1199=== RUN TestPendingClosureWriteTimeout/400_objects1200=== PAUSE TestPendingClosureWriteTimeout/400_objects1201=== RUN TestPendingClosureWriteTimeout/670k_objects1202=== PAUSE TestPendingClosureWriteTimeout/670k_objects1203=== RUN TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline1204=== PAUSE TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline1205=== CONT TestProxyWriteTimeout1206=== RUN TestProxyWriteTimeout/narinfo1207=== PAUSE TestProxyWriteTimeout/narinfo1208=== RUN TestProxyWriteTimeout/1_GiB_nar1209=== PAUSE TestProxyWriteTimeout/1_GiB_nar1210=== RUN TestProxyWriteTimeout/10_GiB_nar1211=== PAUSE TestProxyWriteTimeout/10_GiB_nar1212=== RUN TestProxyWriteTimeout/unknown_size1213=== PAUSE TestProxyWriteTimeout/unknown_size1214=== CONT TestCompleteMultipartUpload_ErrorButObjectExists1215=== RUN TestUploadHandlersRejectOversizedBody/create_pending_closure1216=== PAUSE TestUploadHandlersRejectOversizedBody/create_pending_closure1217=== RUN TestUploadHandlersRejectOversizedBody/complete_multipart1218=== PAUSE TestUploadHandlersRejectOversizedBody/complete_multipart1219=== RUN TestUploadHandlersRejectOversizedBody/request_more_parts1220=== PAUSE TestUploadHandlersRejectOversizedBody/request_more_parts1221=== CONT TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle12222026/11/04 20:13:52 INFO Starting cleanup of old closures method=DELETE path=/api/closures12232026/11/04 20:13:52 INFO Garbage collection started12242026/11/04 20:13:52 ERROR failed to check GC advisory lock error="query pg_locks: failed to connect to `user=_tribuchetbld7 database=niks3`: /nonexistent/.s.PGSQL.5432 (/nonexistent): dial error: dial unix /nonexistent/.s.PGSQL.5432: connect: no such file or directory"1225--- PASS: TestGCAdvisoryLockBlocksConcurrentRun (4.61s)1226=== CONT TestLeadElectsOneAndHandsOver12272026/11/04 20:13:52 INFO Aborted multipart uploads count=0 kept=012282026/11/04 20:13:52 WARN Force mode enabled - objects will be deleted immediately without grace period1229=== RUN TestService_RequireScope_OIDC/builder_may_write1230=== PAUSE TestService_RequireScope_OIDC/builder_may_write1231=== RUN TestService_RequireScope_OIDC/builder_may_not_admin1232=== PAUSE TestService_RequireScope_OIDC/builder_may_not_admin1233=== RUN TestService_RequireScope_OIDC/ops_may_admin1234=== PAUSE TestService_RequireScope_OIDC/ops_may_admin1235=== RUN TestService_RequireScope_OIDC/ops_may_not_write1236=== PAUSE TestService_RequireScope_OIDC/ops_may_not_write1237=== RUN TestService_RequireScope_OIDC/reader_may_not_write1238=== PAUSE TestService_RequireScope_OIDC/reader_may_not_write1239=== RUN TestService_RequireScope_OIDC/static_token_may_admin1240=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin1241=== RUN TestService_RequireScope_OIDC/static_token_may_write1242=== PAUSE TestService_RequireScope_OIDC/static_token_may_write1243=== RUN TestService_RequireScope_OIDC/reader_may_read1244=== PAUSE TestService_RequireScope_OIDC/reader_may_read1245=== RUN TestService_RequireScope_OIDC/writer_implies_read1246=== PAUSE TestService_RequireScope_OIDC/writer_implies_read1247=== RUN TestService_RequireScope_OIDC/anonymous_may_not_read1248=== PAUSE TestService_RequireScope_OIDC/anonymous_may_not_read1249=== RUN TestService_RequireScope_OIDC/reader_may_read_with_netrc1250=== PAUSE TestService_RequireScope_OIDC/reader_may_read_with_netrc1251=== RUN TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1252=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1253=== RUN TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read1254=== PAUSE TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read1255=== RUN TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1256=== PAUSE TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1257=== CONT TestRedundantMultipartUpload12582026/11/04 20:13:52 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=012592026/11/04 20:13:52 INFO Vacuumed table table=pending_closures12602026/11/04 20:13:52 INFO Vacuumed table table=pending_objects12612026/11/04 20:13:52 INFO Vacuumed table table=multipart_uploads12622026/11/04 20:13:52 INFO Vacuumed table table=closures12632026/11/04 20:13:52 INFO Vacuumed table table=objects12642026/11/04 20:13:52 INFO lead: acquired remote=192.0.2.1:123412652026/11/04 20:13:53 INFO lead: acquired remote=192.0.2.1:123412662026/11/04 20:13:53 INFO lead: released remote=192.0.2.1:12341267--- PASS: TestLeadIncumbentAnnouncesAtOnce (4.69s)1268=== CONT TestSkippedUploadsHandler12692026/11/04 20:13:53 INFO Client skipped oversized paths paths=3 nar_bytes=50000000001270--- PASS: TestSkippedUploadsHandler (0.00s)1271=== CONT TestConnectWaitsForAPeerMigration1272=== RUN TestService_AuthMiddleware_OIDC/valid_OIDC_token1273=== PAUSE TestService_AuthMiddleware_OIDC/valid_OIDC_token1274=== RUN TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1275=== PAUSE TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1276=== RUN TestService_AuthMiddleware_OIDC/malformed_token_rejected1277=== PAUSE TestService_AuthMiddleware_OIDC/malformed_token_rejected1278=== RUN TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1279=== PAUSE TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1280=== CONT TestResolveDBConnectionString1281=== RUN TestResolveDBConnectionString/flag_wins1282=== PAUSE TestResolveDBConnectionString/flag_wins1283=== RUN TestResolveDBConnectionString/file_when_flag_empty1284=== PAUSE TestResolveDBConnectionString/file_when_flag_empty1285=== RUN TestResolveDBConnectionString/missing_file_is_an_error1286=== PAUSE TestResolveDBConnectionString/missing_file_is_an_error1287=== RUN TestResolveDBConnectionString/PGHOST_allows_empty1288=== PAUSE TestResolveDBConnectionString/PGHOST_allows_empty1289=== RUN TestResolveDBConnectionString/nothing_configured1290=== PAUSE TestResolveDBConnectionString/nothing_configured1291=== CONT TestPush_SignsNarinfosOfItsPendingObjects1292--- PASS: TestService_ReadAuthMiddleware (4.90s)1293=== CONT TestParseSize1294--- PASS: TestParseSize (0.00s)1295=== CONT TestConcurrentCommitsSharingObjectsDoNotDeadlock12962026/11/04 20:13:53 INFO lead: released remote=192.0.2.1:12341297--- PASS: TestLeadEndsOnShutdown (5.75s)1298=== CONT TestDeleteClosuresRacingPins1299=== NAME TestClientMultipleUploads1300 client_integration_test.go:405: Created store path 0: /private/var/tb/7/scratch/63b205a296af2db3/build/TestClientMultipleUploads3728266383/001/store/lp52jg8hmx9r9gzh6rj2a6bgm61dy1q0-test-file-0.txt1301=== NAME TestClientWithDependencies1302 client_integration_test.go:660: Built derivation: /private/var/tb/7/scratch/63b205a296af2db3/build/TestClientWithDependencies381447399/001/store/9298brkbsf1d7kawq7g7457adaj03vc7-test-script1303 client_integration_test.go:662: Found 1 dependencies (including self)1304=== NAME TestClientMultipleUploads13052026/11/04 20:13:54 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=01306 client_integration_test.go:405: Created store path 1: /private/var/tb/7/scratch/63b205a296af2db3/build/TestClientMultipleUploads3728266383/001/store/23fw6aql9w98mp2cbfkbzfbsddb29lg2-test-file-1.txt13072026/11/04 20:13:54 INFO Received create pin request method=POST path=/api/pins/myapp13082026/11/04 20:13:54 INFO Created/updated pin name=myapp store_path=/private/var/tb/7/scratch/63b205a296af2db3/build/TestPinProtectsFromGC2048845498/001/store/3ph864qlrif8mf5k0jjck1lvyk6ixysw-pinned-file.txt narinfo_key=3ph864qlrif8mf5k0jjck1lvyk6ixysw.narinfo13092026/11/04 20:13:54 INFO Starting cleanup of old closures method=DELETE path=/api/closures1310 client_integration_test.go:405: Created store path 2: /private/var/tb/7/scratch/63b205a296af2db3/build/TestClientMultipleUploads3728266383/001/store/abkdrvwrqg95m9dhz011i2d7zajbhl65-test-file-2.txt13112026/11/04 20:13:54 INFO Garbage collection started13122026/11/04 20:13:54 INFO Aborted multipart uploads count=0 kept=013132026/11/04 20:13:54 INFO Received push request method=POST path=/api/pushes13142026/11/04 20:13:54 WARN Force mode enabled - objects will be deleted immediately without grace period13152026/11/04 20:13:54 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=01316=== NAME TestClientIntegration1317 client_integration_test.go:291: Created store path: /private/var/tb/7/scratch/63b205a296af2db3/build/TestClientIntegration1206954624/002/store/36vdn0clva7yivnj4y3zdqai1kgnr92h-test-file.txt13182026/11/04 20:13:54 INFO Vacuumed table table=pending_closures13192026/11/04 20:13:54 INFO Vacuumed table table=pending_objects13202026/11/04 20:13:54 INFO Vacuumed table table=multipart_uploads13212026/11/04 20:13:54 INFO Vacuumed table table=closures13222026/11/04 20:13:54 INFO Vacuumed table table=objects13232026/11/04 20:13:54 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)13242026/11/04 20:13:54 INFO Uploading 9298brkbsf1d7kawq7g7457adaj03vc7-test-script (136B)13252026/11/04 20:13:54 WARN Failed to register uploaded object key=9298brkbsf1d7kawq7g7457adaj03vc7.ls error="server returned 404: 404 page not found\n"13262026/11/04 20:13:54 WARN Failed to register uploaded object key=nar/1s7yghixzpinyqm7g59kyn3sav81pmnsdi5v63m6x4r2vacy907j.nar.zst error="server returned 404: 404 page not found\n"13272026/11/04 20:13:54 WARN Failed to register uploaded object key=log/rc0042rlsg91q06bzrmslzzl2nrrx13q-test-script.drv error="server returned 404: 404 page not found\n"13282026/11/04 20:13:54 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign13292026/11/04 20:13:54 INFO Signed narinfos id=1 count=113302026/11/04 20:13:54 INFO Received push request method=POST path=/api/pushes13312026/11/04 20:13:54 INFO Uploading 1 narinfos13322026/11/04 20:13:54 INFO Received push request method=POST path=/api/pushes13332026/11/04 20:13:54 INFO Uploading 3 paths to 127.0.0.1 (0 already cached)13342026/11/04 20:13:54 INFO Uploading 23fw6aql9w98mp2cbfkbzfbsddb29lg2-test-file-1.txt (160B)13352026/11/04 20:13:54 INFO Uploading abkdrvwrqg95m9dhz011i2d7zajbhl65-test-file-2.txt (160B)13362026/11/04 20:13:54 INFO Uploading lp52jg8hmx9r9gzh6rj2a6bgm61dy1q0-test-file-0.txt (160B)13372026/11/04 20:13:54 INFO Received complete push request method=POST path=/api/pushes/1/complete13382026/11/04 20:13:54 WARN Failed to register uploaded object key=9298brkbsf1d7kawq7g7457adaj03vc7.narinfo error="server returned 404: 404 page not found\n"13392026/11/04 20:13:54 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)13402026/11/04 20:13:54 INFO Uploading 36vdn0clva7yivnj4y3zdqai1kgnr92h-test-file.txt (152B)13412026/11/04 20:13:54 INFO Completed push id=1 objects=4 duration=43.675667ms13422026/11/04 20:13:54 INFO Upload complete. (267ms)1343=== NAME TestClientWithDependencies1344 client_integration_test.go:664: Skipping nix copy test - isolated store (/private/var/tb/7/scratch/63b205a296af2db3/build/TestClientWithDependencies381447399/001/store) requires matching store prefix13452026/11/04 20:13:54 WARN Failed to register uploaded object key=nar/0ahq3izw3h0b0c08p3xdfclh758fwxnp85ccvflasb4vnfsv50ri.nar.zst error="server returned 404: 404 page not found\n"13462026/11/04 20:13:54 WARN Failed to register uploaded object key=23fw6aql9w98mp2cbfkbzfbsddb29lg2.ls error="server returned 404: 404 page not found\n"13472026/11/04 20:13:54 WARN Failed to register uploaded object key=nar/1823g6vx4q5zqvr73m7lkq1wpk40fin7bsc792di430yk7sg4lka.nar.zst error="server returned 404: 404 page not found\n"13482026/11/04 20:13:54 WARN Failed to register uploaded object key=lp52jg8hmx9r9gzh6rj2a6bgm61dy1q0.ls error="server returned 404: 404 page not found\n"13492026/11/04 20:13:54 WARN Failed to register uploaded object key=nar/13p9pqi0ga6fx2apcwls9hjnv7nmf740ggpn5zvfzdsp5vz2bbg4.nar.zst error="server returned 404: 404 page not found\n"13502026/11/04 20:13:54 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign13512026/11/04 20:13:54 WARN Failed to register uploaded object key=abkdrvwrqg95m9dhz011i2d7zajbhl65.ls error="server returned 404: 404 page not found\n"13522026/11/04 20:13:54 INFO Signed narinfos id=1 count=313532026/11/04 20:13:54 INFO Uploading 3 narinfos13542026/11/04 20:13:54 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign13552026/11/04 20:13:54 WARN Failed to register uploaded object key=36vdn0clva7yivnj4y3zdqai1kgnr92h.ls error="server returned 404: 404 page not found\n"13562026/11/04 20:13:54 WARN Failed to register uploaded object key=nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst error="server returned 404: 404 page not found\n"13572026/11/04 20:13:54 INFO Signed narinfos id=1 count=113582026/11/04 20:13:54 INFO Uploading 1 narinfos13592026/11/04 20:13:54 WARN Failed to register uploaded object key=abkdrvwrqg95m9dhz011i2d7zajbhl65.narinfo error="server returned 404: 404 page not found\n"13602026/11/04 20:13:54 INFO Received complete push request method=POST path=/api/pushes/1/complete13612026/11/04 20:13:54 WARN Failed to register uploaded object key=23fw6aql9w98mp2cbfkbzfbsddb29lg2.narinfo error="server returned 404: 404 page not found\n"13622026/11/04 20:13:54 WARN Failed to register uploaded object key=lp52jg8hmx9r9gzh6rj2a6bgm61dy1q0.narinfo error="server returned 404: 404 page not found\n"13632026/11/04 20:13:54 INFO Completed push id=1 objects=9 duration=23.479042ms13642026/11/04 20:13:54 INFO Upload complete. (322ms)1365=== NAME TestClientMultipleUploads1366 client_integration_test.go:416: Uploaded 3 paths in 356.996083ms13672026/11/04 20:13:54 INFO Received complete push request method=POST path=/api/pushes/1/complete13682026/11/04 20:13:54 WARN Failed to register uploaded object key=36vdn0clva7yivnj4y3zdqai1kgnr92h.narinfo error="server returned 404: 404 page not found\n"1369--- PASS: TestClientWithDependencies (5.81s)1370=== CONT TestPush_RejectsBadRequests13712026/11/04 20:13:54 INFO Completed push id=1 objects=3 duration=32.584416ms13722026/11/04 20:13:54 INFO Upload complete. (334ms)13732026/11/04 20:13:54 INFO All 1 paths already cached1374--- PASS: TestClientMultipleUploads (5.71s)1375=== CONT TestService_Rustfstest1376=== NAME TestClientIntegration1377 client_integration_test.go:317: Retrieved narinfo from S3:1378 StorePath: /private/var/tb/7/scratch/63b205a296af2db3/build/TestClientIntegration1206954624/002/store/36vdn0clva7yivnj4y3zdqai1kgnr92h-test-file.txt1379 URL: nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst1380 Compression: zstd1381 NarHash: sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11382 NarSize: 1521383 References: 1384 CA: fixed:r:sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11385 client_integration_test.go:318: Retrieved .ls file from S3 (compressed size: 77 bytes)1386 client_integration_test.go:318: Decompressed .ls content (64 bytes):1387 {"version":1,"root":{"type":"regular","size":39,"narOffset":96}}13882026/11/04 20:13:55 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted,O=Other"13892026/11/04 20:13:55 WARN mTLS auth: bound subjects configured but subject DN unavailable13902026/11/04 20:13:55 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted"1391--- PASS: TestService_AuthMiddleware_MTLSBoundSubjects (5.07s)1392=== CONT TestPush_SkippedKeySurvivesGCBeforeCommit1393=== NAME TestClientCADerivations1394 client_ca_test.go:136: Built CA derivation: /private/var/tb/7/scratch/63b205a296af2db3/build/TestClientCADerivations4015027905/001/store/wjq5db7fy1ayr643ch69n5n8z09hxfga-ca-test13952026/11/04 20:13:55 INFO Received push request method=POST path=/api/pushes13962026/11/04 20:13:55 INFO Object in database but missing from S3 key=36vdn0clva7yivnj4y3zdqai1kgnr92h.ls13972026/11/04 20:13:55 WARN Found objects in DB but missing from S3, will re-upload count=113982026/11/04 20:13:55 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)1399 client_ca_test.go:139: Found 1 dependencies (including self)14002026/11/04 20:13:55 INFO Received complete push request method=POST path=/api/pushes/2/complete14012026/11/04 20:13:55 WARN Failed to register uploaded object key=36vdn0clva7yivnj4y3zdqai1kgnr92h.ls error="server returned 404: 404 page not found\n"14022026/11/04 20:13:55 INFO Completed push id=2 objects=3 duration=1.0045ms14032026/11/04 20:13:55 INFO Upload complete. (118ms)1404=== NAME TestClientIntegration1405 client_integration_test.go:335: Retrieved .ls file from S3 (compressed size: 62 bytes)1406 client_integration_test.go:335: Decompressed .ls content (49 bytes):1407 {"version":1,"root":{"type":"regular","size":39}}1408--- PASS: TestCacheStatsHandler (5.43s)1409=== CONT TestReadRedirectUsesPublicS3URL14102026/11/04 20:13:55 INFO Received push request method=POST path=/api/pushes14112026/11/04 20:13:55 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)14122026/11/04 20:13:55 INFO Uploading wjq5db7fy1ayr643ch69n5n8z09hxfga-ca-test (144B)14132026/11/04 20:13:55 WARN Failed to register uploaded object key=wjq5db7fy1ayr643ch69n5n8z09hxfga.ls error="server returned 404: 404 page not found\n"14142026/11/04 20:13:55 WARN Failed to register uploaded object key=nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst error="server returned 404: 404 page not found\n"14152026/11/04 20:13:55 WARN Failed to register uploaded object key=log/xab2v8qz6ssydimvmn5lyy9847zi9hfn-ca-test.drv error="server returned 404: 404 page not found\n"14162026/11/04 20:13:55 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign14172026/11/04 20:13:55 INFO Signed narinfos id=1 count=114182026/11/04 20:13:55 INFO Uploading 1 narinfos14192026/11/04 20:13:55 INFO Received complete push request method=POST path=/api/pushes/1/complete14202026/11/04 20:13:55 WARN Failed to register uploaded object key=wjq5db7fy1ayr643ch69n5n8z09hxfga.narinfo error="server returned 404: 404 page not found\n"14212026/11/04 20:13:55 INFO Completed push id=1 objects=4 duration=22.59225ms14222026/11/04 20:13:55 INFO Upload complete. (348ms)1423=== NAME TestClientCADerivations1424 client_ca_test.go:180: Narinfo contains CA field: StorePath: /private/var/tb/7/scratch/63b205a296af2db3/build/TestClientCADerivations4015027905/001/store/wjq5db7fy1ayr643ch69n5n8z09hxfga-ca-test1425 URL: nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst1426 Compression: zstd1427 NarHash: sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1428 NarSize: 1441429 References: 1430 Deriver: /private/var/tb/7/scratch/63b205a296af2db3/build/TestClientCADerivations4015027905/001/store/xab2v8qz6ssydimvmn5lyy9847zi9hfn-ca-test.drv1431 CA: fixed:r:sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1432 client_ca_test.go:185: Checking for realisation files in S3...1433--- PASS: TestService_AuthMiddleware_MTLSProxyHeader (5.49s)1434=== CONT TestPush_CompleteCommitsEveryRoot1435=== NAME TestClientCADerivations1436 client_ca_test.go:207: No realisation files uploaded - this is expected for locally built CA derivations1437 client_ca_test.go:208: Locally built CA derivations don't have DrvOutput IDs until they're substituted from a cache14382026/11/04 20:13:55 INFO Received push request method=POST path=/api/pushes14392026/11/04 20:13:55 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)14402026/11/04 20:13:55 INFO Received complete push request method=POST path=/api/pushes/3/complete14412026/11/04 20:13:55 WARN Failed to register uploaded object key=36vdn0clva7yivnj4y3zdqai1kgnr92h.ls error="server returned 404: 404 page not found\n"14422026/11/04 20:13:55 INFO Completed push id=3 objects=3 duration=23.020584ms14432026/11/04 20:13:55 INFO Upload complete. (137ms)1444=== NAME TestClientIntegration1445 client_integration_test.go:352: Retrieved .ls file from S3 (compressed size: 62 bytes)1446 client_integration_test.go:352: Decompressed .ls content (49 bytes):1447 {"version":1,"root":{"type":"regular","size":39}}1448 client_integration_test.go:363: Testing garbage collection...1449=== NAME TestClientCADerivations1450 client_ca_test.go:258: nix copy output: error: binary cache 's3://bucket37?endpoint=http://localhost:65225®ion=eu-west-1' is for Nix stores with prefix '/nix/store', not '/private/var/tb/7/scratch/63b205a296af2db3/build/TestClientCADerivations4015027905/001/store'1451 client_ca_test.go:259: nix copy failed (might be expected with isolated stores): exit status 11452--- PASS: TestClientCADerivations (5.94s)14532026/11/04 20:13:55 INFO Starting cleanup of old closures method=DELETE path=/api/closures1454=== CONT TestPush_RootsAreLockedInByteOrder14552026/11/04 20:13:55 INFO Garbage collection started14562026/11/04 20:13:55 INFO Aborted multipart uploads count=0 kept=014572026/11/04 20:13:55 WARN Force mode enabled - objects will be deleted immediately without grace period14582026/11/04 20:13:55 INFO Received uploads request method=POST path=/api/pending_closures14592026/11/04 20:13:56 INFO Registered completed upload object_key=nar/jjjjjjjjjjjjjjjjjjjjjjjjjjjjjj0100000000000000000000.nar.zst14602026/11/04 20:13:56 INFO Received uploads request method=POST path=/api/pending_closures1461--- PASS: TestPresignedUploadRegisteredBeforeCommit (5.53s)1462=== CONT TestPush_OverlappingRootsStoreOneRowPerKey14632026/11/04 20:13:56 INFO Received uploads request method=POST path=/api/pending_closures14642026/11/04 20:13:56 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=014652026/11/04 20:13:56 INFO Vacuumed table table=pending_closures14662026/11/04 20:13:56 INFO Vacuumed table table=pending_objects14672026/11/04 20:13:56 INFO Vacuumed table table=multipart_uploads1468--- PASS: TestCreatePendingClosure_SmallNARUsesSimplePUT (5.73s)1469=== CONT TestPush_RepeatedRootCommitsOnce14702026/11/04 20:13:56 INFO Vacuumed table table=closures14712026/11/04 20:13:56 INFO Vacuumed table table=objects14722026/11/04 20:13:56 INFO Received complete multipart upload request method=POST path=/api/multipart/complete14732026/11/04 20:13:56 ERROR Failed to get multipart upload error="no rows in result set" upload_id=does-not-exist object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst1474--- PASS: TestCompleteMultipartUnregistered (5.68s)1475=== CONT TestPresentNotReportedWhileGCDeletesClosure1476=== RUN TestPresentNotReportedWhileGCDeletesClosure/stale1477=== PAUSE TestPresentNotReportedWhileGCDeletesClosure/stale1478=== RUN TestPresentNotReportedWhileGCDeletesClosure/fresh1479=== PAUSE TestPresentNotReportedWhileGCDeletesClosure/fresh1480=== CONT TestReadProxyHead1481=== NAME TestPinProtectsFromGC1482 client_integration_test.go:887: Pin successfully protected closure from garbage collection1483--- PASS: TestPinProtectsFromGC (10.31s)1484=== CONT TestReadProxyInvalidPath14852026/11/04 20:13:56 INFO Received push request method=POST path=/api/pushes14862026/11/04 20:13:57 INFO Received uploads request method=POST path=/api/pending_closures14872026-11-04 20:13:57.165 UTC [55448] ERROR: Push does not exist: id=114882026-11-04 20:13:57.165 UTC [55448] CONTEXT: PL/pgSQL function commit_push(bigint) line 11 at RAISE14892026-11-04 20:13:57.165 UTC [55448] STATEMENT: SELECT commit_push($1)1490--- PASS: TestPush_CompleteWaitsForCleanupOfThePush (6.08s)1491=== CONT TestMultipartCleanup14922026/11/04 20:13:57 INFO Received uploads request method=POST path=/api/pending_closures14932026/11/04 20:13:57 INFO Received uploads request method=POST path=/api/pending_closures14942026/11/04 20:13:57 INFO Received uploads request method=POST path=/api/pending_closures14952026/11/04 20:13:57 INFO Received cleanup request method=DELETE path=/api/pending_closures14962026/11/04 20:13:57 INFO Aborted multipart uploads count=0 kept=014972026/11/04 20:13:57 INFO Received uploads request method=POST path=/api/pending_closures14982026/11/04 20:13:57 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=01499=== NAME TestClientIntegration1500 client_integration_test.go:370: Objects in database after GC:15012026/11/04 20:13:57 INFO Received cleanup request method=DELETE path=/api/pending_closures1502 client_integration_test.go:370: Successfully deleted all objects with GC --force15032026/11/04 20:13:57 INFO Aborted multipart uploads count=1 kept=015042026/11/04 20:13:57 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete15052026-11-04 20:13:57.893 UTC [55373] ERROR: Closure does not exist: id=115062026-11-04 20:13:57.893 UTC [55373] CONTEXT: PL/pgSQL function commit_pending_closure(bigint) line 13 at RAISE15072026-11-04 20:13:57.893 UTC [55373] STATEMENT: -- name: CommitPendingClosure :one1508 SELECT commit_pending_closure($1::bigint)::bigint1509 1510--- PASS: TestService_cleanupPendingClosuresHandler (5.82s)1511=== CONT TestReadProxy4041512=== CONT TestReadProxyNarStreaming1513--- PASS: TestClientIntegration (8.34s)15142026/11/04 20:13:58 INFO Received uploads request method=POST path=/api/pending_closures15152026/11/04 20:13:58 INFO Received uploads request method=POST path=/api/pending_closures15162026/11/04 20:13:58 INFO Received complete multipart upload request method=POST path=/api/multipart/complete15172026/11/04 20:13:58 INFO Received uploads request method=POST path=/api/pending_closures15182026/11/04 20:13:58 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst upload_id=MDQ1MzcwMjEtY2E0ZC00NTZkLTkzN2QtNjhlNmE4YmY4YTAwLjQyMWRkYjljLWJlZjgtNGMzZi1hMzBjLWY2MWE1ZTA3MzM4ZngxNzkzODIzMjM3MDc0NjM1MDAw parts=1015192026/11/04 20:13:58 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete15202026/11/04 20:13:58 INFO Completed upload id=1 objects=2 duration=20.745334ms15212026/11/04 20:13:58 INFO Received uploads request method=POST path=/api/pending_closures15222026/11/04 20:13:58 INFO Received complete multipart upload request method=POST path=/api/multipart/complete15232026/11/04 20:13:58 INFO Received uploads request method=POST path=/api/pending_closures15242026/11/04 20:13:58 INFO Object in database but missing from S3 key=dadb44fdadb44fdadb44fdadb44f0000.narinfo15252026/11/04 20:13:58 WARN Found objects in DB but missing from S3, will re-upload count=11526--- PASS: TestService_verifyS3Integrity (7.68s)1527=== CONT TestService_healthCheckHandler15282026/11/04 20:13:59 INFO Received complete multipart upload request method=POST path=/api/multipart/complete15292026/11/04 20:13:59 INFO lead: acquired remote=192.0.2.1:123415302026/11/04 20:13:59 INFO Received complete multipart upload request method=POST path=/api/multipart/complete15312026/11/04 20:13:59 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified key does not exist." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=MDQ1MzcwMjEtY2E0ZC00NTZkLTkzN2QtNjhlNmE4YmY4YTAwLmRkZGI1MzNkLTcyMjktNDM2My1iN2VlLTg5Njk4MzIxY2QxYXgxNzkzODIzMjM4OTE4NzQwMDAw15322026/11/04 20:13:59 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=MDQ1MzcwMjEtY2E0ZC00NTZkLTkzN2QtNjhlNmE4YmY4YTAwLmRkZGI1MzNkLTcyMjktNDM2My1iN2VlLTg5Njk4MzIxY2QxYXgxNzkzODIzMjM4OTE4NzQwMDAw parts=11533--- PASS: TestCompleteMultipartUpload_ErrorButObjectExists (6.84s)1534=== CONT TestReadProxyContentNegotiation15352026/11/04 20:13:59 INFO Completed multipart upload object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst upload_id=MDQ1MzcwMjEtY2E0ZC00NTZkLTkzN2QtNjhlNmE4YmY4YTAwLjAyZTAwY2VkLWVjYmYtNGQ2MC04YTZkLTIzOTE2MzAwNjQ0MXgxNzkzODIzMjM3NDUxNTEyMDAw parts=1015362026/11/04 20:13:59 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete15372026/11/04 20:13:59 INFO Completed upload id=1 objects=2 duration=24.292625ms15382026/11/04 20:13:59 INFO Received get closure request method=GET path=/api/closures/0000000000000000000000000000000015392026/11/04 20:13:59 INFO Received uploads request method=POST path=/api/pending_closures15402026/11/04 20:13:59 INFO Starting cleanup of old closures method=DELETE path=/api/closures15412026/11/04 20:13:59 INFO Aborted multipart uploads count=0 kept=015422026/11/04 20:13:59 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=015432026/11/04 20:13:59 INFO Vacuumed table table=pending_closures15442026/11/04 20:13:59 INFO Vacuumed table table=pending_objects15452026/11/04 20:13:59 INFO Received uploads request method=POST path=/api/pending_closures15462026/11/04 20:13:59 INFO Vacuumed table table=multipart_uploads15472026/11/04 20:13:59 INFO Vacuumed table table=closures15482026/11/04 20:13:59 INFO Vacuumed table table=objects15492026/11/04 20:13:59 INFO Received get closure request method=GET path=/api/closures/000000000000000000000000000000001550--- PASS: TestService_createPendingClosureHandler (7.48s)1551=== CONT TestServerTLSConfig1552=== RUN TestServerTLSConfig/no_client_CA1553=== PAUSE TestServerTLSConfig/no_client_CA1554=== RUN TestServerTLSConfig/missing_CA_file15552026/11/04 20:13:59 INFO Received uploads request method=POST path=/api/pending_closures1556=== PAUSE TestServerTLSConfig/missing_CA_file1557=== RUN TestServerTLSConfig/not_a_PEM_file1558=== PAUSE TestServerTLSConfig/not_a_PEM_file1559=== CONT TestReadProxyNarinfoAlreadyDecompressed15602026/11/04 20:13:59 INFO Received push request method=POST path=/api/pushes15612026/11/04 20:13:59 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign15622026/11/04 20:13:59 INFO Signed narinfos id=1 count=115632026/11/04 20:13:59 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign15642026/11/04 20:13:59 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign15652026/11/04 20:13:59 ERROR Failed to sign narinfos signer="index 1" error="signing key cannot be nil"15662026/11/04 20:13:59 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign15672026/11/04 20:13:59 ERROR Failed to sign narinfos signer=niks3-test-1 error="signer failed"15682026/11/04 20:13:59 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign15692026/11/04 20:13:59 ERROR Signer returned unexpected signature count signer=niks3-test-1 got=0 want=115702026/11/04 20:13:59 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign15712026/11/04 20:13:59 ERROR Signer returned unexpected object key signer=niks3-test-1 object_key=unexpected.narinfo1572--- PASS: TestPush_SignsNarinfosOfItsPendingObjects (6.51s)1573=== CONT TestPresentRefreshesOnlyStaleClosures15742026/11/04 20:14:00 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1575--- PASS: TestConnectWaitsForAPeerMigration (7.00s)1576=== CONT TestService_NativeMTLS15772026/11/04 20:14:00 INFO Completed multipart upload object_key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhh0100000000000000000000.nar.zst upload_id=MDQ1MzcwMjEtY2E0ZC00NTZkLTkzN2QtNjhlNmE4YmY4YTAwLmU0NTNmNTI1LWJkODMtNGM3My1iNDVmLTMwYzczMWY1NDU1MHgxNzkzODIzMjM4MTI1OTY1MDAw parts=1215782026/11/04 20:14:00 INFO Received uploads request method=POST path=/api/pending_closures1579--- PASS: TestCompletedNarNotReofferedAcrossClosures (7.93s)1580=== CONT TestReadProxyNarinfo15812026/11/04 20:14:00 INFO lead: released remote=192.0.2.1:123415822026/11/04 20:14:00 INFO lead: acquired remote=192.0.2.1:12341583=== RUN TestPush_RejectsBadRequests/root_not_in_objects1584=== PAUSE TestPush_RejectsBadRequests/root_not_in_objects1585=== RUN TestPush_RejectsBadRequests/no_roots1586=== PAUSE TestPush_RejectsBadRequests/no_roots1587=== RUN TestPush_RejectsBadRequests/no_objects1588=== PAUSE TestPush_RejectsBadRequests/no_objects1589=== RUN TestPush_RejectsBadRequests/bad_root1590=== PAUSE TestPush_RejectsBadRequests/bad_root1591=== CONT TestPresentReportsOnlyClosureRoots1592--- PASS: TestService_Rustfstest (6.17s)1593=== CONT TestMetricsCommit15942026/11/04 20:14:01 INFO Received push request method=POST path=/api/pushes15952026/11/04 20:14:01 INFO lead: released remote=192.0.2.1:12341596--- PASS: TestLeadElectsOneAndHandsOver (9.02s)1597=== CONT TestIsValidCachePath1598=== RUN TestIsValidCachePath/narinfo1599=== PAUSE TestIsValidCachePath/narinfo1600=== RUN TestIsValidCachePath/narinfo_all_nix_base32_chars1601=== PAUSE TestIsValidCachePath/narinfo_all_nix_base32_chars1602=== RUN TestIsValidCachePath/nar_zst1603=== PAUSE TestIsValidCachePath/nar_zst1604=== RUN TestIsValidCachePath/nar_xz1605=== PAUSE TestIsValidCachePath/nar_xz1606=== RUN TestIsValidCachePath/nar_bz21607=== PAUSE TestIsValidCachePath/nar_bz21608=== RUN TestIsValidCachePath/nar_uncompressed1609=== PAUSE TestIsValidCachePath/nar_uncompressed1610=== RUN TestIsValidCachePath/ls1611=== PAUSE TestIsValidCachePath/ls1612=== RUN TestIsValidCachePath/log1613=== PAUSE TestIsValidCachePath/log1614=== RUN TestIsValidCachePath/realisation1615=== PAUSE TestIsValidCachePath/realisation1616=== RUN TestIsValidCachePath/nix-cache-info1617=== PAUSE TestIsValidCachePath/nix-cache-info1618=== RUN TestIsValidCachePath/index.html1619=== PAUSE TestIsValidCachePath/index.html1620=== RUN TestIsValidCachePath/traversal_parent1621=== PAUSE TestIsValidCachePath/traversal_parent1622=== RUN TestIsValidCachePath/traversal_in_middle1623=== PAUSE TestIsValidCachePath/traversal_in_middle1624=== RUN TestIsValidCachePath/invalid_char_e1625=== PAUSE TestIsValidCachePath/invalid_char_e1626=== RUN TestIsValidCachePath/invalid_char_u1627=== PAUSE TestIsValidCachePath/invalid_char_u1628=== RUN TestIsValidCachePath/random_path1629=== PAUSE TestIsValidCachePath/random_path1630=== RUN TestIsValidCachePath/empty1631=== PAUSE TestIsValidCachePath/empty1632=== RUN TestIsValidCachePath/leading_slash1633=== PAUSE TestIsValidCachePath/leading_slash1634=== RUN TestIsValidCachePath/wrong_extension1635=== PAUSE TestIsValidCachePath/wrong_extension1636=== RUN TestIsValidCachePath/short_hash1637=== PAUSE TestIsValidCachePath/short_hash1638=== CONT TestCreatePin_ReservedPins16392026/11/04 20:14:01 INFO Received complete multipart upload request method=POST path=/api/multipart/complete16402026/11/04 20:14:01 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:49237/oidc16412026/11/04 20:14:01 INFO Received complete push request method=POST path=/api/pushes/1/complete16422026/11/04 20:14:01 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=MDQ1MzcwMjEtY2E0ZC00NTZkLTkzN2QtNjhlNmE4YmY4YTAwLmNhOWVjMGRkLTI2NmEtNDYxMC1iMTU0LTkwZTM1Mzc4MzU2OHgxNzkzODIzMjM5NDY3Njg4MDAw parts=1216432026/11/04 20:14:01 INFO Received uploads request method=POST path=/api/pending_closures16442026/11/04 20:14:01 INFO Completed push id=1 objects=4 duration=28.298ms16452026/11/04 20:14:01 INFO Received push request method=POST path=/api/pushes16462026/11/04 20:14:01 INFO Received uploads request method=POST path=/api/pending_closures1647--- PASS: TestConcurrentCommitsSharingObjectsDoNotDeadlock (8.13s)1648=== CONT TestParseSingleRange1649=== RUN TestParseSingleRange/none1650=== PAUSE TestParseSingleRange/none1651=== RUN TestParseSingleRange/unknown_unit1652=== PAUSE TestParseSingleRange/unknown_unit1653=== RUN TestParseSingleRange/multi-range_ignored1654=== PAUSE TestParseSingleRange/multi-range_ignored1655=== RUN TestParseSingleRange/malformed_no_dash1656=== PAUSE TestParseSingleRange/malformed_no_dash1657=== RUN TestParseSingleRange/malformed_both_empty1658=== PAUSE TestParseSingleRange/malformed_both_empty1659=== RUN TestParseSingleRange/malformed_end_before_start1660=== PAUSE TestParseSingleRange/malformed_end_before_start1661=== RUN TestParseSingleRange/closed1662=== PAUSE TestParseSingleRange/closed1663=== RUN TestParseSingleRange/open-ended1664=== PAUSE TestParseSingleRange/open-ended1665=== RUN TestParseSingleRange/end_clamped_to_size1666=== PAUSE TestParseSingleRange/end_clamped_to_size1667=== RUN TestParseSingleRange/suffix1668=== PAUSE TestParseSingleRange/suffix1669=== RUN TestParseSingleRange/suffix_exceeds_size1670=== PAUSE TestParseSingleRange/suffix_exceeds_size1671=== RUN TestParseSingleRange/single_byte1672=== PAUSE TestParseSingleRange/single_byte1673=== RUN TestParseSingleRange/start_past_EOF1674=== PAUSE TestParseSingleRange/start_past_EOF1675=== RUN TestParseSingleRange/start_far_past_EOF1676=== PAUSE TestParseSingleRange/start_far_past_EOF1677=== CONT TestOrphanedObjectsGCStressTest16782026/11/04 20:14:01 INFO Aborted multipart uploads count=0 kept=016792026/11/04 20:14:01 WARN Force mode enabled - objects will be deleted immediately without grace period16802026/11/04 20:14:01 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=016812026/11/04 20:14:01 INFO Vacuumed table table=pending_closures16822026/11/04 20:14:01 INFO Vacuumed table table=pending_objects16832026/11/04 20:14:01 INFO Vacuumed table table=multipart_uploads16842026/11/04 20:14:01 INFO Vacuumed table table=closures16852026/11/04 20:14:01 INFO Vacuumed table table=objects16862026/11/04 20:14:01 INFO Received complete push request method=POST path=/api/pushes/2/complete1687--- PASS: TestReadRedirectUsesPublicS3URL (6.53s)1688=== CONT TestReadRedirectKeepsNarinfoProxied16892026/11/04 20:14:01 INFO Completed push id=2 objects=4 duration=60.35525ms1690--- PASS: TestPush_SkippedKeySurvivesGCBeforeCommit (6.94s)1691=== CONT TestOrphanedObjectsGC16922026/11/04 20:14:02 INFO Received push request method=POST path=/api/pushes16932026/11/04 20:14:02 INFO Received complete push request method=POST path=/api/pushes/1/complete16942026/11/04 20:14:02 INFO Completed push id=1 objects=6 duration=47.219917ms1695--- PASS: TestPush_CompleteCommitsEveryRoot (6.69s)1696=== CONT TestReadProxyRangeRequest16972026/11/04 20:14:02 INFO Received push request method=POST path=/api/pushes16982026-11-04 20:14:02.729 UTC [55518] ERROR: could not obtain lock on row in relation "closures"16992026-11-04 20:14:02.729 UTC [55518] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT17002026-11-04 20:14:02.736 UTC [55518] ERROR: could not obtain lock on row in relation "closures"17012026-11-04 20:14:02.736 UTC [55518] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT17022026-11-04 20:14:02.740 UTC [55518] ERROR: could not obtain lock on row in relation "closures"17032026-11-04 20:14:02.740 UTC [55518] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT17042026-11-04 20:14:02.741 UTC [55518] ERROR: could not obtain lock on row in relation "closures"17052026-11-04 20:14:02.741 UTC [55518] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT17062026-11-04 20:14:02.748 UTC [55518] ERROR: could not obtain lock on row in relation "closures"17072026-11-04 20:14:02.748 UTC [55518] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT1708--- PASS: TestPush_RootsAreLockedInByteOrder (6.92s)1709=== CONT TestObjectStatsUpdatedOncePerCommit17102026/11/04 20:14:02 INFO Received push request method=POST path=/api/pushes1711--- PASS: TestPush_OverlappingRootsStoreOneRowPerKey (6.96s)1712=== CONT TestMetricsInventory17132026/11/04 20:14:03 INFO Received push request method=POST path=/api/pushes17142026/11/04 20:14:03 INFO Received complete push request method=POST path=/api/pushes/1/complete17152026/11/04 20:14:03 INFO Completed push id=1 objects=4 duration=35.787625ms17162026/11/04 20:14:03 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1717--- PASS: TestPush_RepeatedRootCommitsOnce (6.99s)1718=== CONT TestReadRedirectNar17192026/11/04 20:14:03 WARN Failed to abort redundant multipart upload, keeping its row object_key=nar/gggggggggggggggggggggggggggggg0200000000000000000000.nar.zst upload_id=MDQ1MzcwMjEtY2E0ZC00NTZkLTkzN2QtNjhlNmE4YmY4YTAwLjllZjFkYTZmLTRhNmQtNDUyNi1iMmJmLWM4ODU5MjI3NmRjYngxNzkzODIzMjQxNjkyOTMxMDAw error="Get \"http://127.0.0.1:1/bucket52/?location=\": dial tcp 127.0.0.1:1: connect: connection refused"17202026/11/04 20:14:03 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0200000000000000000000.nar.zst upload_id=MDQ1MzcwMjEtY2E0ZC00NTZkLTkzN2QtNjhlNmE4YmY4YTAwLjRkMDM2NDVjLWE4OGQtNDg4Ni04NWQ0LTg0YzE5MjhhNjkxMHgxNzkzODIzMjQxNjUxNTY1MDAw parts=1217212026/11/04 20:14:03 INFO Received cleanup request method=DELETE path=/api/pending_closures17222026/11/04 20:14:03 INFO Aborted multipart uploads count=1 kept=01723--- PASS: TestRedundantMultipartUpload (10.70s)1724=== CONT TestNARDeduplicationMetadataUploadBug1725--- PASS: TestReadProxyInvalidPath (6.87s)1726=== CONT TestObjectStatsTrigger17272026/11/04 20:14:03 WARN Rate limiter enabled after throttle name=s3-test rate=517282026/11/04 20:14:03 WARN S3 rate limit hit operation="complete multipart upload" error="Please reduce your request rate."1729=== NAME TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle1730 throttle_test.go:213: Proxy stats: total=13, throttled=10, completeMultipart=101731 throttle_test.go:215: Rate limiter: enabled=true, rate=5.001732--- PASS: TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle (11.08s)1733=== CONT TestCacheConfigHandlerMaxNarSize1734--- PASS: TestCacheConfigHandlerMaxNarSize (0.00s)1735=== CONT TestGenerateLandingPage1736--- PASS: TestGenerateLandingPage (0.00s)1737=== CONT TestPendingCleanupUsesOneCutoff1738--- PASS: TestReadProxyHead (7.18s)1739=== CONT TestCreatePendingClosureRejectsOversizedNAR17402026/11/04 20:14:03 INFO Received uploads request method=POST path=/api/pending_closures1741--- PASS: TestCreatePendingClosureRejectsOversizedNAR (0.00s)1742=== CONT TestService_readinessHandler17432026/11/04 20:14:03 INFO Received uploads request method=POST path=/api/pending_closures17442026/11/04 20:14:03 INFO Received cleanup request method=DELETE path=/api/pending_closures17452026/11/04 20:14:04 WARN Failed to abort upload, keeping its closure key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst error="Get \"http://127.0.0.1:1/bucket66/?location=\": dial tcp 127.0.0.1:1: connect: connection refused" code=""17462026/11/04 20:14:04 INFO Aborted multipart uploads count=0 kept=117472026/11/04 20:14:04 INFO Received cleanup request method=DELETE path=/api/pending_closures17482026/11/04 20:14:04 INFO Aborted multipart uploads count=1 kept=01749--- PASS: TestMultipartCleanup (6.92s)1750=== CONT TestMultipartUploadAbortedWhenCancelledBeforeRecorded1751--- PASS: TestDeleteClosuresRacingPins (10.24s)1752=== CONT TestGCTaskStore_GetReturnsLatest1753--- PASS: TestGCTaskStore_GetReturnsLatest (0.00s)1754=== CONT TestReadProxyDisabled1755--- PASS: TestReadProxyNarStreaming (6.44s)1756=== CONT TestGracefulShutdownDrainsInflight17572026/11/04 20:14:04 INFO Starting HTTP server address=127.0.0.1:4929717582026/11/04 20:14:04 INFO Shutdown signal received, draining in-flight requests timeout=10s1759--- PASS: TestGracefulShutdownDrainsInflight (0.07s)1760=== CONT TestGCTaskStore_DeduplicateSameParams1761--- PASS: TestGCTaskStore_DeduplicateSameParams (0.00s)1762=== CONT TestGCTaskStore_GetEmpty1763--- PASS: TestGCTaskStore_GetEmpty (0.00s)1764=== CONT TestGCTaskStore_ConflictDifferentParams1765--- PASS: TestGCTaskStore_ConflictDifferentParams (0.00s)1766=== CONT TestGCEndsOnShutdown1767=== RUN TestGCEndsOnShutdown/before_the_run1768=== PAUSE TestGCEndsOnShutdown/before_the_run1769=== RUN TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete1770=== PAUSE TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete1771=== RUN TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark1772=== PAUSE TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark1773=== CONT TestGCTaskStore_StartNew1774--- PASS: TestGCTaskStore_StartNew (0.00s)1775=== CONT TestGCTaskStore_Fail1776=== CONT TestGCTaskStore_PhaseUpdates1777=== CONT TestGCTaskStore_CompletedAllowsNewTask1778=== CONT TestForceGCDuringPushOffersSweptObject/before_pending_rows1779--- PASS: TestGCTaskStore_Fail (0.00s)1780--- PASS: TestGCTaskStore_PhaseUpdates (0.00s)1781--- PASS: TestGCTaskStore_CompletedAllowsNewTask (0.00s)1782--- PASS: TestReadProxy404 (6.66s)1783=== CONT TestForceGCDuringPushOffersSweptObject/after_presence_check1784--- PASS: TestService_healthCheckHandler (5.61s)1785=== CONT TestCacheConfigHandler/full_config,_no_issuer1786=== CONT TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1787=== CONT TestCacheConfigHandler/no_signing_keys1788=== CONT TestCacheConfigHandler/no_cache_url_configured1789--- PASS: TestCacheConfigHandler (0.00s)1790 --- PASS: TestCacheConfigHandler/full_config,_no_issuer (0.00s)1791 --- PASS: TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator (0.00s)1792 --- PASS: TestCacheConfigHandler/no_signing_keys (0.00s)1793 --- PASS: TestCacheConfigHandler/no_cache_url_configured (0.00s)1794=== CONT TestClientErrorHandling/InvalidStorePath1795--- PASS: TestReadProxyContentNegotiation (5.76s)1796=== CONT TestClientErrorHandling/ServerNotAvailable1797--- PASS: TestReadProxyNarinfoAlreadyDecompressed (5.58s)1798=== CONT TestClientErrorHandling/InvalidAuthToken17992026/11/04 20:14:05 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present1800--- PASS: TestPresentRefreshesOnlyStaleClosures (5.42s)1801=== CONT TestService_verifyS3ReuploadsStaleNarinfo/lost,_other_NAR_pushed18022026/11/04 20:14:05 WARN Request failed, retrying attempt=2 backoff=199.711534ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present18032026/11/04 20:14:05 WARN mTLS auth: subject not in bound subjects subject="CN=reader"18042026/11/04 20:14:05 WARN mTLS auth: subject not in bound subjects subject="CN=reader"1805--- PASS: TestService_NativeMTLS (5.34s)1806=== CONT TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost,_second_pushed18072026/11/04 20:14:05 WARN Request failed, retrying attempt=3 backoff=427.130161ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present18082026/11/04 20:14:05 ERROR Failed to decode narinfo key=3hcdxyjf9yiq7qf3i4548drb6sjmwa1v.narinfo limit=16777216 error=<nil>1809--- PASS: TestReadProxyNarinfo (5.54s)1810=== CONT TestService_verifyS3ReuploadsStaleNarinfo/lost,_same_NAR_pushed1811--- PASS: TestPresentReportsOnlyClosureRoots (5.08s)1812=== CONT TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost18132026/11/04 20:14:05 INFO Received push request method=POST path=/api/pushes18142026/11/04 20:14:05 WARN Request failed, retrying attempt=4 backoff=733.33142ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present18152026/11/04 20:14:06 INFO Received complete push request method=POST path=/api/pushes/1/complete18162026/11/04 20:14:06 INFO Completed push id=1 objects=4 duration=39.008292ms18172026/11/04 20:14:06 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete18182026/11/04 20:14:06 INFO Completed upload id=2 objects=2 duration=1.531291ms1819--- PASS: TestMetricsCommit (4.99s)1820=== CONT TestService_verifyS3ReuploadsStaleNarinfo/intact,_other_NAR_pushed18212026/11/04 20:14:06 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux18222026/11/04 20:14:06 WARN Refused reserved pin name=worker-x86_64-linux18232026/11/04 20:14:06 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux18242026/11/04 20:14:06 INFO Received create pin request method=POST path=/api/pins/my-app18252026/11/04 20:14:06 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux1826--- PASS: TestCreatePin_ReservedPins (4.68s)1827=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info18282026/11/04 20:14:06 INFO Received uploads request method=POST path=/1829=== CONT TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key18302026/11/04 20:14:06 INFO Received complete multipart upload request method=POST path=/1831=== CONT TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key18322026/11/04 20:14:06 INFO Received request for more parts method=POST path=/1833=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal18342026/11/04 20:14:06 INFO Received uploads request method=POST path=/1835--- PASS: TestUploadHandlersRejectInvalidKeys (0.08s)1836 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info (0.00s)1837 --- PASS: TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key (0.00s)1838 --- PASS: TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key (0.00s)1839 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal (0.00s)1840=== CONT TestIsValidUploadKey/narinfo1841=== CONT TestIsValidUploadKey/realisation_plus_in_output1842=== CONT TestIsValidUploadKey/unknown_type1843=== CONT TestIsValidUploadKey/empty_key1844=== CONT TestIsValidUploadKey/absolute1845=== CONT TestIsValidUploadKey/traversal_nar1846=== CONT TestIsValidUploadKey/traversal1847=== CONT TestIsValidUploadKey/listing_key,_narinfo_type1848=== CONT TestIsValidUploadKey/nar_key,_narinfo_type1849=== CONT TestIsValidUploadKey/narinfo_key,_nar_type1850=== CONT TestIsValidUploadKey/index.html1851=== CONT TestIsValidUploadKey/nix-cache-info1852=== CONT TestIsValidUploadKey/build_log_home-manager_file1853=== CONT TestIsValidUploadKey/realisation1854=== CONT TestIsValidUploadKey/build_log_equals1855=== CONT TestIsValidUploadKey/build_log_question_mark1856=== CONT TestIsValidUploadKey/build_log_plus_in_name1857=== CONT TestIsValidUploadKey/nar_plain1858=== CONT TestIsValidUploadKey/build_log1859=== CONT TestIsValidUploadKey/listing1860=== CONT TestIsValidUploadKey/nar_xz1861=== CONT TestIsValidUploadKey/nar_zst1862--- PASS: TestIsValidUploadKey (0.01s)1863 --- PASS: TestIsValidUploadKey/narinfo (0.00s)1864 --- PASS: TestIsValidUploadKey/realisation_plus_in_output (0.00s)1865 --- PASS: TestIsValidUploadKey/unknown_type (0.00s)1866 --- PASS: TestIsValidUploadKey/empty_key (0.00s)1867 --- PASS: TestIsValidUploadKey/absolute (0.00s)1868 --- PASS: TestIsValidUploadKey/traversal_nar (0.00s)1869 --- PASS: TestIsValidUploadKey/traversal (0.00s)1870 --- PASS: TestIsValidUploadKey/listing_key,_narinfo_type (0.00s)1871 --- PASS: TestIsValidUploadKey/nar_key,_narinfo_type (0.00s)1872 --- PASS: TestIsValidUploadKey/narinfo_key,_nar_type (0.00s)1873 --- PASS: TestIsValidUploadKey/index.html (0.00s)1874 --- PASS: TestIsValidUploadKey/nix-cache-info (0.00s)1875 --- PASS: TestIsValidUploadKey/build_log_home-manager_file (0.00s)1876 --- PASS: TestIsValidUploadKey/realisation (0.00s)1877 --- PASS: TestIsValidUploadKey/build_log_equals (0.00s)1878 --- PASS: TestIsValidUploadKey/build_log_question_mark (0.00s)1879 --- PASS: TestIsValidUploadKey/build_log_plus_in_name (0.00s)1880 --- PASS: TestIsValidUploadKey/nar_plain (0.00s)1881 --- PASS: TestIsValidUploadKey/build_log (0.00s)1882 --- PASS: TestIsValidUploadKey/listing (0.00s)1883 --- PASS: TestIsValidUploadKey/nar_xz (0.00s)1884 --- PASS: TestIsValidUploadKey/nar_zst (0.00s)1885=== CONT TestPendingClosureWriteTimeout/empty1886=== CONT TestProxyWriteTimeout/narinfo1887=== CONT TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline18882026/11/04 20:14:06 WARN Request failed, retrying attempt=5 backoff=1.468226467s error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present1889--- PASS: TestReadRedirectKeepsNarinfoProxied (4.83s)1890=== CONT TestPendingClosureWriteTimeout/670k_objects1891=== CONT TestPendingClosureWriteTimeout/400_objects1892=== CONT TestProxyWriteTimeout/10_GiB_nar1893=== CONT TestProxyWriteTimeout/unknown_size1894=== CONT TestProxyWriteTimeout/1_GiB_nar1895--- PASS: TestProxyWriteTimeout (0.00s)1896 --- PASS: TestProxyWriteTimeout/narinfo (0.00s)1897 --- PASS: TestProxyWriteTimeout/10_GiB_nar (0.00s)1898 --- PASS: TestProxyWriteTimeout/unknown_size (0.00s)1899 --- PASS: TestProxyWriteTimeout/1_GiB_nar (0.00s)1900=== CONT TestUploadHandlersRejectOversizedBody/create_pending_closure19012026/11/04 20:14:06 INFO Received uploads request method=POST path=/1902--- PASS: TestReadProxyRangeRequest (4.74s)1903=== CONT TestUploadHandlersRejectOversizedBody/request_more_parts19042026/11/04 20:14:07 INFO Received request for more parts method=POST path=/1905=== CONT TestUploadHandlersRejectOversizedBody/complete_multipart19062026/11/04 20:14:07 INFO Received complete multipart upload request method=POST path=/1907=== CONT TestService_RequireScope_OIDC/builder_may_write1908=== CONT TestService_RequireScope_OIDC/reader_may_read1909=== CONT TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1910=== CONT TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read19112026/11/04 20:14:07 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]1912=== CONT TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1913=== CONT TestService_RequireScope_OIDC/reader_may_read_with_netrc1914=== CONT TestService_RequireScope_OIDC/anonymous_may_not_read1915=== CONT TestService_RequireScope_OIDC/writer_implies_read1916=== CONT TestService_RequireScope_OIDC/reader_may_not_write1917=== CONT TestService_RequireScope_OIDC/static_token_may_write1918=== CONT TestService_RequireScope_OIDC/static_token_may_admin1919=== CONT TestService_RequireScope_OIDC/ops_may_admin1920=== CONT TestService_RequireScope_OIDC/ops_may_not_write1921=== CONT TestService_RequireScope_OIDC/builder_may_not_admin1922=== CONT TestService_AuthMiddleware_OIDC/valid_OIDC_token1923--- PASS: TestService_RequireScope_OIDC (5.19s)1924 --- PASS: TestService_RequireScope_OIDC/builder_may_write (0.00s)1925 --- PASS: TestService_RequireScope_OIDC/reader_may_read (0.00s)1926 --- PASS: TestService_RequireScope_OIDC/empty_netrc_password_may_not_read (0.00s)1927 --- PASS: TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read (0.00s)1928 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin_with_netrc (0.00s)1929 --- PASS: TestService_RequireScope_OIDC/reader_may_read_with_netrc (0.00s)1930 --- PASS: TestService_RequireScope_OIDC/anonymous_may_not_read (0.00s)1931 --- PASS: TestService_RequireScope_OIDC/writer_implies_read (0.00s)1932 --- PASS: TestService_RequireScope_OIDC/reader_may_not_write (0.00s)1933 --- PASS: TestService_RequireScope_OIDC/static_token_may_write (0.00s)1934 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin (0.00s)1935 --- PASS: TestService_RequireScope_OIDC/ops_may_admin (0.00s)1936 --- PASS: TestService_RequireScope_OIDC/ops_may_not_write (0.00s)1937 --- PASS: TestService_RequireScope_OIDC/builder_may_not_admin (0.00s)1938=== CONT TestService_AuthMiddleware_OIDC/malformed_token_rejected19392026/11/04 20:14:07 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]1940=== CONT TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1941=== CONT TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected19422026/11/04 20:14:07 WARN Authentication failed token_preview=eyJhbGciOi...PYRO7qJlgg token_length=701 oidc_error="no rule matched: claim \"repository_owner\" value [otherorg] not in allowed patterns [myorg]" oidc_provider=test tried_providers=[test]1943=== CONT TestResolveDBConnectionString/flag_wins1944=== CONT TestResolveDBConnectionString/PGHOST_allows_empty1945=== CONT TestResolveDBConnectionString/nothing_configured1946=== CONT TestResolveDBConnectionString/missing_file_is_an_error1947=== CONT TestResolveDBConnectionString/file_when_flag_empty1948=== CONT TestPresentNotReportedWhileGCDeletesClosure/stale1949--- PASS: TestService_AuthMiddleware_OIDC (4.84s)1950 --- PASS: TestService_AuthMiddleware_OIDC/valid_OIDC_token (0.00s)1951 --- PASS: TestService_AuthMiddleware_OIDC/malformed_token_rejected (0.00s)1952 --- PASS: TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured (0.00s)1953 --- PASS: TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected (0.01s)1954--- PASS: TestResolveDBConnectionString (0.05s)1955 --- PASS: TestResolveDBConnectionString/flag_wins (0.00s)1956 --- PASS: TestResolveDBConnectionString/PGHOST_allows_empty (0.00s)1957 --- PASS: TestResolveDBConnectionString/nothing_configured (0.00s)1958 --- PASS: TestResolveDBConnectionString/missing_file_is_an_error (0.00s)1959 --- PASS: TestResolveDBConnectionString/file_when_flag_empty (0.00s)1960=== CONT TestPresentNotReportedWhileGCDeletesClosure/fresh1961--- PASS: TestUploadHandlersRejectOversizedBody (0.24s)1962 --- PASS: TestUploadHandlersRejectOversizedBody/request_more_parts (0.02s)1963 --- PASS: TestUploadHandlersRejectOversizedBody/complete_multipart (0.02s)1964 --- PASS: TestUploadHandlersRejectOversizedBody/create_pending_closure (0.58s)1965--- PASS: TestObjectStatsUpdatedOncePerCommit (4.77s)1966=== CONT TestServerTLSConfig/no_client_CA1967=== CONT TestServerTLSConfig/not_a_PEM_file1968=== CONT TestServerTLSConfig/missing_CA_file1969--- PASS: TestServerTLSConfig (0.00s)1970 --- PASS: TestServerTLSConfig/no_client_CA (0.00s)1971 --- PASS: TestServerTLSConfig/not_a_PEM_file (0.02s)1972 --- PASS: TestServerTLSConfig/missing_CA_file (0.00s)1973=== CONT TestPush_RejectsBadRequests/root_not_in_objects19742026/11/04 20:14:07 INFO Received push request method=POST path=/api/pushes1975=== CONT TestPush_RejectsBadRequests/no_objects19762026/11/04 20:14:07 INFO Received push request method=POST path=/api/pushes1977=== CONT TestPush_RejectsBadRequests/bad_root19782026/11/04 20:14:07 INFO Received push request method=POST path=/api/pushes1979=== CONT TestPush_RejectsBadRequests/no_roots19802026/11/04 20:14:07 INFO Received push request method=POST path=/api/pushes1981=== CONT TestIsValidCachePath/narinfo1982=== CONT TestIsValidCachePath/index.html1983=== CONT TestIsValidCachePath/short_hash1984--- PASS: TestPush_RejectsBadRequests (5.88s)1985 --- PASS: TestPush_RejectsBadRequests/root_not_in_objects (0.00s)1986 --- PASS: TestPush_RejectsBadRequests/no_objects (0.00s)1987 --- PASS: TestPush_RejectsBadRequests/bad_root (0.01s)1988 --- PASS: TestPush_RejectsBadRequests/no_roots (0.00s)1989=== CONT TestIsValidCachePath/wrong_extension1990=== CONT TestIsValidCachePath/leading_slash1991=== CONT TestIsValidCachePath/empty1992=== CONT TestIsValidCachePath/random_path1993=== CONT TestIsValidCachePath/invalid_char_u1994=== CONT TestIsValidCachePath/invalid_char_e1995=== CONT TestIsValidCachePath/traversal_in_middle1996=== CONT TestIsValidCachePath/traversal_parent1997=== CONT TestIsValidCachePath/nar_uncompressed1998=== CONT TestIsValidCachePath/nix-cache-info1999=== CONT TestIsValidCachePath/realisation2000=== CONT TestIsValidCachePath/log2001=== CONT TestIsValidCachePath/ls2002=== CONT TestIsValidCachePath/nar_xz2003=== CONT TestIsValidCachePath/nar_bz22004=== CONT TestIsValidCachePath/nar_zst2005=== CONT TestIsValidCachePath/narinfo_all_nix_base32_chars2006--- PASS: TestIsValidCachePath (0.01s)2007 --- PASS: TestIsValidCachePath/narinfo (0.00s)2008 --- PASS: TestIsValidCachePath/index.html (0.00s)2009 --- PASS: TestIsValidCachePath/short_hash (0.00s)2010 --- PASS: TestIsValidCachePath/wrong_extension (0.00s)2011 --- PASS: TestIsValidCachePath/leading_slash (0.00s)2012 --- PASS: TestIsValidCachePath/empty (0.00s)2013 --- PASS: TestIsValidCachePath/random_path (0.00s)2014 --- PASS: TestIsValidCachePath/invalid_char_u (0.00s)2015 --- PASS: TestIsValidCachePath/invalid_char_e (0.00s)2016 --- PASS: TestIsValidCachePath/traversal_in_middle (0.00s)2017 --- PASS: TestIsValidCachePath/traversal_parent (0.00s)2018 --- PASS: TestIsValidCachePath/nar_uncompressed (0.00s)2019 --- PASS: TestIsValidCachePath/nix-cache-info (0.00s)2020 --- PASS: TestIsValidCachePath/realisation (0.00s)2021 --- PASS: TestIsValidCachePath/log (0.00s)2022 --- PASS: TestIsValidCachePath/ls (0.00s)2023 --- PASS: TestIsValidCachePath/nar_xz (0.00s)2024 --- PASS: TestIsValidCachePath/nar_bz2 (0.00s)2025 --- PASS: TestIsValidCachePath/nar_zst (0.00s)2026 --- PASS: TestIsValidCachePath/narinfo_all_nix_base32_chars (0.00s)2027=== CONT TestParseSingleRange/none2028=== CONT TestParseSingleRange/open-ended2029=== CONT TestParseSingleRange/start_far_past_EOF2030=== CONT TestParseSingleRange/start_past_EOF2031=== CONT TestParseSingleRange/single_byte2032=== CONT TestParseSingleRange/suffix_exceeds_size2033=== CONT TestParseSingleRange/suffix2034=== CONT TestParseSingleRange/end_clamped_to_size2035=== CONT TestParseSingleRange/malformed_both_empty2036=== CONT TestParseSingleRange/closed2037=== CONT TestParseSingleRange/malformed_end_before_start2038=== CONT TestParseSingleRange/multi-range_ignored2039=== CONT TestParseSingleRange/malformed_no_dash2040=== CONT TestParseSingleRange/unknown_unit2041--- PASS: TestParseSingleRange (0.01s)2042 --- PASS: TestParseSingleRange/none (0.00s)2043 --- PASS: TestParseSingleRange/open-ended (0.00s)2044 --- PASS: TestParseSingleRange/start_far_past_EOF (0.00s)2045 --- PASS: TestParseSingleRange/start_past_EOF (0.00s)2046 --- PASS: TestParseSingleRange/single_byte (0.00s)2047 --- PASS: TestParseSingleRange/suffix_exceeds_size (0.00s)2048 --- PASS: TestParseSingleRange/suffix (0.00s)2049 --- PASS: TestParseSingleRange/end_clamped_to_size (0.00s)2050 --- PASS: TestParseSingleRange/malformed_both_empty (0.00s)2051 --- PASS: TestParseSingleRange/closed (0.00s)2052 --- PASS: TestParseSingleRange/malformed_end_before_start (0.00s)2053 --- PASS: TestParseSingleRange/multi-range_ignored (0.00s)2054 --- PASS: TestParseSingleRange/malformed_no_dash (0.00s)2055 --- PASS: TestParseSingleRange/unknown_unit (0.00s)2056=== CONT TestGCEndsOnShutdown/before_the_run2057--- PASS: TestMetricsInventory (4.70s)2058=== CONT TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete2059=== NAME TestOrphanedObjectsGC2060 orphaned_objects_gc_test.go:287: GC Test Summary:2061 orphaned_objects_gc_test.go:288: - Kept: 2 objects from closure A2062 orphaned_objects_gc_test.go:289: - Deleted: 2 objects from closure B2063 orphaned_objects_gc_test.go:290: - Deleted: 6 orphaned chain objects (X1->X2->X3)2064 orphaned_objects_gc_test.go:291: - Deleted: 2 orphaned single objects (Y)2065 orphaned_objects_gc_test.go:292: - Total deleted: 10 objects2066--- PASS: TestOrphanedObjectsGC (6.05s)2067=== CONT TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark20682026/11/04 20:14:08 WARN Request failed, retrying attempt=1 backoff=100ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config20692026/11/04 20:14:08 WARN Request failed, retrying attempt=2 backoff=201.91251ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config2070--- PASS: TestReadRedirectNar (5.02s)2071=== NAME TestNARDeduplicationMetadataUploadBug2072 metadata_upload_test.go:48: First store path: /private/var/tb/7/scratch/63b205a296af2db3/build/TestNARDeduplicationMetadataUploadBug786620408/001/store/j46a2332q5912rvlvf044srfciihc1px-file1.txt20732026/11/04 20:14:08 INFO Received push request method=POST path=/api/pushes20742026/11/04 20:14:08 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)20752026/11/04 20:14:08 INFO Uploading j46a2332q5912rvlvf044srfciihc1px-file1.txt (160B)20762026/11/04 20:14:08 WARN Failed to register uploaded object key=j46a2332q5912rvlvf044srfciihc1px.ls error="server returned 404: 404 page not found\n"20772026/11/04 20:14:08 WARN Request failed, retrying attempt=3 backoff=369.886352ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config20782026/11/04 20:14:08 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign20792026/11/04 20:14:08 WARN Failed to register uploaded object key=nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst error="server returned 404: 404 page not found\n"20802026/11/04 20:14:08 INFO Signed narinfos id=1 count=120812026/11/04 20:14:08 INFO Uploading 1 narinfos2082--- PASS: TestObjectStatsTrigger (5.14s)20832026/11/04 20:14:08 INFO Received complete push request method=POST path=/api/pushes/1/complete20842026/11/04 20:14:08 WARN Failed to register uploaded object key=j46a2332q5912rvlvf044srfciihc1px.narinfo error="server returned 404: 404 page not found\n"20852026/11/04 20:14:08 INFO Completed push id=1 objects=3 duration=56.586666ms20862026/11/04 20:14:08 INFO Upload complete. (239ms)2087=== NAME TestNARDeduplicationMetadataUploadBug2088 metadata_upload_test.go:54: Retrieved narinfo from S3:2089 StorePath: /private/var/tb/7/scratch/63b205a296af2db3/build/TestNARDeduplicationMetadataUploadBug786620408/001/store/j46a2332q5912rvlvf044srfciihc1px-file1.txt2090 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst2091 Compression: zstd2092 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf2093 NarSize: 1602094 References: 2095 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf2096 metadata_upload_test.go:55: Retrieved .ls file from S3 (compressed size: 77 bytes)2097 metadata_upload_test.go:55: Decompressed .ls content (64 bytes):2098 {"version":1,"root":{"type":"regular","size":44,"narOffset":96}}20992026/11/04 20:14:08 INFO Received uploads request method=POST path=/api/pending_closures2100 metadata_upload_test.go:64: Second store path (same content): /private/var/tb/7/scratch/63b205a296af2db3/build/TestNARDeduplicationMetadataUploadBug786620408/001/store/s27fi7vi2qr49r9wa7m7vqdh6fz9lhk4-file2.txt21012026/11/04 20:14:08 INFO Received uploads request method=POST path=/api/pending_closures21022026/11/04 20:14:08 INFO Received push request method=POST path=/api/pushes21032026/11/04 20:14:08 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)21042026/11/04 20:14:08 INFO Received cleanup request method=DELETE path=/api/pending_closures21052026/11/04 20:14:08 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign21062026/11/04 20:14:08 WARN Failed to register uploaded object key=s27fi7vi2qr49r9wa7m7vqdh6fz9lhk4.ls error="server returned 404: 404 page not found\n"21072026/11/04 20:14:08 INFO Signed narinfos id=2 count=121082026/11/04 20:14:08 INFO Uploading 1 narinfos21092026/11/04 20:14:08 WARN Request failed, retrying attempt=4 backoff=720.921928ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21102026/11/04 20:14:08 INFO Received complete push request method=POST path=/api/pushes/2/complete21112026/11/04 20:14:08 WARN Failed to register uploaded object key=s27fi7vi2qr49r9wa7m7vqdh6fz9lhk4.narinfo error="server returned 404: 404 page not found\n"21122026/11/04 20:14:08 INFO Completed push id=2 objects=3 duration=1.071791ms21132026/11/04 20:14:08 INFO Upload complete. (169ms)2114 metadata_upload_test.go:76: Retrieved narinfo from S3:2115 StorePath: /private/var/tb/7/scratch/63b205a296af2db3/build/TestNARDeduplicationMetadataUploadBug786620408/001/store/s27fi7vi2qr49r9wa7m7vqdh6fz9lhk4-file2.txt2116 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst2117 Compression: zstd2118 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf2119 NarSize: 1602120 References: 2121 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf2122 metadata_upload_test.go:77: Retrieved .ls file from S3 (compressed size: 62 bytes)2123 metadata_upload_test.go:77: Decompressed .ls content (49 bytes):2124 {"version":1,"root":{"type":"regular","size":44}}21252026/11/04 20:14:08 WARN readiness check failed error="closed pool"2126--- PASS: TestService_readinessHandler (5.31s)2127--- PASS: TestNARDeduplicationMetadataUploadBug (5.61s)21282026/11/04 20:14:09 INFO Received uploads request method=POST path=/api/pending_closures2129--- PASS: TestMultipartUploadAbortedWhenCancelledBeforeRecorded (5.24s)2130--- PASS: TestReadProxyDisabled (5.33s)21312026/11/04 20:14:09 WARN Request failed, retrying attempt=5 backoff=1.584372452s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21322026/11/04 20:14:09 INFO Received uploads request method=POST path=/api/pending_closures21332026/11/04 20:14:09 INFO Aborted multipart uploads count=0 kept=021342026/11/04 20:14:09 WARN Force mode enabled - objects will be deleted immediately without grace period21352026/11/04 20:14:10 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=021362026/11/04 20:14:10 INFO Vacuumed table table=pending_closures21372026/11/04 20:14:10 INFO Vacuumed table table=pending_objects21382026/11/04 20:14:10 INFO Vacuumed table table=multipart_uploads21392026/11/04 20:14:10 INFO Vacuumed table table=closures21402026/11/04 20:14:10 INFO Vacuumed table table=objects21412026/11/04 20:14:10 INFO Received uploads request method=POST path=/api/pending_closures21422026/11/04 20:14:10 INFO Aborted multipart uploads count=0 kept=021432026/11/04 20:14:10 WARN Force mode enabled - objects will be deleted immediately without grace period21442026/11/04 20:14:10 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=021452026/11/04 20:14:10 INFO Vacuumed table table=pending_closures21462026/11/04 20:14:10 INFO Vacuumed table table=pending_objects21472026/11/04 20:14:10 INFO Vacuumed table table=multipart_uploads21482026/11/04 20:14:10 INFO Vacuumed table table=closures21492026/11/04 20:14:10 INFO Vacuumed table table=objects2150--- PASS: TestForceGCDuringPushOffersSweptObject (0.00s)2151 --- PASS: TestForceGCDuringPushOffersSweptObject/before_pending_rows (5.70s)2152 --- PASS: TestForceGCDuringPushOffersSweptObject/after_presence_check (5.65s)21532026/11/04 20:14:10 INFO Received uploads request method=POST path=/api/pending_closures21542026/11/04 20:14:10 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"21552026/11/04 20:14:10 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"21562026/11/04 20:14:10 INFO Received uploads request method=POST path=/api/pending_closures21572026/11/04 20:14:11 INFO Received uploads request method=POST path=/api/pending_closures21582026/11/04 20:14:11 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: sending request: request failed after retries: Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused"21592026/11/04 20:14:11 WARN Request failed, retrying attempt=1 backoff=100ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21602026/11/04 20:14:11 WARN Request failed, retrying attempt=2 backoff=181.63897ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21612026/11/04 20:14:11 INFO Received uploads request method=POST path=/api/pending_closures21622026/11/04 20:14:11 WARN Request failed, retrying attempt=3 backoff=431.616402ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21632026/11/04 20:14:11 INFO Received uploads request method=POST path=/api/pending_closures21642026/11/04 20:14:11 WARN Request failed, retrying attempt=4 backoff=757.798427ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21652026/11/04 20:14:12 INFO Received complete multipart upload request method=POST path=/api/multipart/complete21662026/11/04 20:14:12 INFO Received uploads request method=POST path=/api/pending_closures21672026/11/04 20:14:12 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000100000000000000000000.nar.zst upload_id=MDQ1MzcwMjEtY2E0ZC00NTZkLTkzN2QtNjhlNmE4YmY4YTAwLjNkNDU2N2Q1LTdkNTAtNDc1OC05NDI0LWY1YzczNzM3MjMwMngxNzkzODIzMjUwNjI1MzY1MDAw parts=1021682026/11/04 20:14:12 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete21692026/11/04 20:14:12 INFO Completed upload id=1 objects=3 duration=16.842333ms21702026/11/04 20:14:12 INFO Received complete multipart upload request method=POST path=/api/multipart/complete21712026/11/04 20:14:12 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000400000000000000000000.nar.zst upload_id=MDQ1MzcwMjEtY2E0ZC00NTZkLTkzN2QtNjhlNmE4YmY4YTAwLjg5OWMxODNlLWE5NGQtNGYzZi05OTYyLTg1NTE0MmQ1MTBlOXgxNzkzODIzMjUwODY5NzI5MDAw parts=1021722026/11/04 20:14:12 WARN Request failed, retrying attempt=5 backoff=1.660236203s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21732026/11/04 20:14:12 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete21742026/11/04 20:14:12 INFO Completed upload id=1 objects=3 duration=22.737833ms21752026/11/04 20:14:12 INFO Received uploads request method=POST path=/api/pending_closures21762026/11/04 20:14:12 INFO Received uploads request method=POST path=/api/pending_closures21772026/11/04 20:14:12 INFO Object in database but missing from S3 key=nar/dadb44fdadb44fdadb44fdadb44f000100000000000000000000.nar.zst21782026/11/04 20:14:12 WARN Narinfo references a NAR missing from S3, will re-upload narinfo=dadb44fdadb44fdadb44fdadb44f0001.narinfo21792026/11/04 20:14:13 INFO Received complete multipart upload request method=POST path=/api/multipart/complete2180--- PASS: TestPendingClosureWriteTimeout (0.00s)2181 --- PASS: TestPendingClosureWriteTimeout/empty (0.00s)2182 --- PASS: TestPendingClosureWriteTimeout/670k_objects (0.00s)2183 --- PASS: TestPendingClosureWriteTimeout/400_objects (0.00s)2184 --- PASS: TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline (6.92s)21852026/11/04 20:14:13 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000500000000000000000000.nar.zst upload_id=MDQ1MzcwMjEtY2E0ZC00NTZkLTkzN2QtNjhlNmE4YmY4YTAwLjJkOGUyZjc5LTVhYWEtNDNkNC1hMzA4LWZhODQ4YWY2N2Y2NHgxNzkzODIzMjUxMTM4NzYxMDAw parts=1021862026/11/04 20:14:13 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete21872026/11/04 20:14:13 INFO Completed upload id=1 objects=3 duration=10.0945ms21882026/11/04 20:14:13 INFO Received complete multipart upload request method=POST path=/api/multipart/complete21892026/11/04 20:14:13 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000300000000000000000000.nar.zst upload_id=MDQ1MzcwMjEtY2E0ZC00NTZkLTkzN2QtNjhlNmE4YmY4YTAwLjBmYTJhMDE1LTMxNjItNDU5YS1iZjg2LTI0YWZmMjhmMTk5ZHgxNzkzODIzMjUxNDcyMjcwMDAw parts=102190--- PASS: TestPresentNotReportedWhileGCDeletesClosure (0.00s)2191 --- PASS: TestPresentNotReportedWhileGCDeletesClosure/stale (5.95s)2192 --- PASS: TestPresentNotReportedWhileGCDeletesClosure/fresh (6.25s)21932026/11/04 20:14:13 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete21942026/11/04 20:14:13 INFO Completed upload id=1 objects=3 duration=15.070708ms21952026/11/04 20:14:13 INFO Received uploads request method=POST path=/api/pending_closures21962026/11/04 20:14:13 INFO Received uploads request method=POST path=/api/pending_closures21972026/11/04 20:14:13 INFO Object in database but missing from S3 key=nar/dadb44fdadb44fdadb44fdadb44f000500000000000000000000.nar.zst21982026/11/04 20:14:13 WARN Found objects in DB but missing from S3, will re-upload count=121992026/11/04 20:14:13 INFO Received complete multipart upload request method=POST path=/api/multipart/complete22002026/11/04 20:14:13 INFO Aborted multipart uploads count=0 kept=022012026/11/04 20:14:13 WARN Force mode enabled - objects will be deleted immediately without grace period22022026/11/04 20:14:13 ERROR failed to remove object object=nar/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa.nar.zst error="Post \"http://localhost:65225/bucket104/?delete=\": context canceled"22032026/11/04 20:14:13 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000200000000000000000000.nar.zst upload_id=MDQ1MzcwMjEtY2E0ZC00NTZkLTkzN2QtNjhlNmE4YmY4YTAwLmY2OTYyMmFhLWQyN2UtNDFjOS05YjE2LWRkYWEwNmNjYzIzZngxNzkzODIzMjUxODcyNTczMDAw parts=1022042026/11/04 20:14:14 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete22052026/11/04 20:14:14 INFO Completed upload id=1 objects=3 duration=13.442708ms22062026/11/04 20:14:14 INFO Received uploads request method=POST path=/api/pending_closures22072026/11/04 20:14:14 INFO Aborted multipart uploads count=0 kept=022082026/11/04 20:14:14 WARN Force mode enabled - objects will be deleted immediately without grace period22092026-11-04 20:14:14.321 UTC [55631] ERROR: canceling statement due to user request22102026-11-04 20:14:14.321 UTC [55631] STATEMENT: -- name: MarkStaleObjects :execrows2211 WITH RECURSIVE ct AS (2212 SELECT timezone('UTC', now()) AS now2213 ),2214 closure_reach AS (2215 -- Start with all closure keys2216 SELECT o.key, o.refs2217 FROM objects o2218 INNER JOIN closures c ON o.key = c.key2219 UNION2220 -- Recursively add all referenced objects2221 SELECT o.key, o.refs2222 FROM objects o2223 INNER JOIN closure_reach cr ON o.key = ANY(cr.refs)2224 ),2225 reachable_objects AS (2226 SELECT DISTINCT key FROM closure_reach2227 ),2228 stale_objects AS (2229 SELECT o.key2230 FROM objects AS o, ct2231 WHERE2232 NOT EXISTS (2233 SELECT 12234 FROM reachable_objects ro2235 WHERE ro.key = o.key2236 )2237 AND NOT EXISTS (2238 SELECT 12239 FROM pending_objects AS po2240 WHERE po.key = o.key2241 )2242 AND o.deleted_at IS NULL -- Only mark fresh objects2243 ORDER BY o.key COLLATE "C" -- lock in key order, like commit_pending_closure2244 FOR UPDATE2245 )2246 UPDATE objects2247 SET2248 deleted_at = ct.now,2249 first_deleted_at = COALESCE(first_deleted_at, ct.now)2250 FROM stale_objects, ct2251 WHERE objects.key = stale_objects.key2252 2253--- PASS: TestGCEndsOnShutdown (0.00s)2254 --- PASS: TestGCEndsOnShutdown/before_the_run (5.98s)2255 --- PASS: TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete (6.29s)2256 --- PASS: TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark (6.28s)22572026/11/04 20:14:14 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_closures22582026/11/04 20:14:14 INFO Received complete multipart upload request method=POST path=/api/multipart/complete22592026/11/04 20:14:14 WARN Request failed, retrying attempt=2 backoff=210.853998ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures22602026/11/04 20:14:14 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f100400000000000000000000.nar.zst upload_id=MDQ1MzcwMjEtY2E0ZC00NTZkLTkzN2QtNjhlNmE4YmY4YTAwLjUyYjNmMDQ4LWIxNjQtNDM5NC1hNjQ1LTkwYzRhYTQ3YzQxMHgxNzkzODIzMjUyODMyNjQyMDAw parts=1022612026/11/04 20:14:14 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete22622026/11/04 20:14:14 INFO Completed upload id=2 objects=3 duration=1.117792ms22632026/11/04 20:14:14 WARN Request failed, retrying attempt=3 backoff=401.58157ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures22642026/11/04 20:14:14 INFO Received uploads request method=POST path=/api/pending_closures22652026/11/04 20:14:14 INFO Object in database but missing from S3 key=nar/dadb44fdadb44fdadb44fdadb44f000400000000000000000000.nar.zst22662026/11/04 20:14:14 WARN Narinfo references a NAR missing from S3, will re-upload narinfo=dadb44fdadb44fdadb44fdadb44f0004.narinfo22672026/11/04 20:14:14 INFO Aborted multipart uploads count=1 kept=022682026/11/04 20:14:14 INFO Received cleanup request method=DELETE path=/api/pending_closures22692026/11/04 20:14:14 INFO Aborted multipart uploads count=1 kept=02270--- PASS: TestPendingCleanupUsesOneCutoff (11.42s)22712026/11/04 20:14:14 INFO Received complete multipart upload request method=POST path=/api/multipart/complete22722026/11/04 20:14:15 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f100300000000000000000000.nar.zst upload_id=MDQ1MzcwMjEtY2E0ZC00NTZkLTkzN2QtNjhlNmE4YmY4YTAwLjNkOTFjNzJkLTc3NjAtNDBlMS04MDg4LTkwNDE5N2ZiMDc5MngxNzkzODIzMjUzNjgwMTk3MDAw parts=1022732026/11/04 20:14:15 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete22742026/11/04 20:14:15 INFO Completed upload id=2 objects=3 duration=824.209µs22752026/11/04 20:14:15 WARN Request failed, retrying attempt=4 backoff=795.476669ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures22762026/11/04 20:14:15 INFO Received uploads request method=POST path=/api/pending_closures22772026/11/04 20:14:15 INFO Object in database but missing from S3 key=nar/dadb44fdadb44fdadb44fdadb44f000300000000000000000000.nar.zst22782026/11/04 20:14:15 WARN Narinfo references a NAR missing from S3, will re-upload narinfo=dadb44fdadb44fdadb44fdadb44f0003.narinfo2279--- PASS: TestService_verifyS3ReuploadsStaleNarinfo (0.00s)2280 --- PASS: TestService_verifyS3ReuploadsStaleNarinfo/lost,_other_NAR_pushed (7.69s)2281 --- PASS: TestService_verifyS3ReuploadsStaleNarinfo/lost,_same_NAR_pushed (8.03s)2282 --- PASS: TestService_verifyS3ReuploadsStaleNarinfo/intact,_other_NAR_pushed (8.04s)2283 --- PASS: TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost,_second_pushed (9.40s)2284 --- PASS: TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost (9.48s)22852026/11/04 20:14:15 WARN Request failed, retrying attempt=5 backoff=1.449793989s error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures2286=== NAME TestOrphanedObjectsGCStressTest2287 orphaned_objects_gc_test.go:422: Created 10 active closures, 5 to-delete closures, 20 orphaned chains2288 orphaned_objects_gc_test.go:440: Marked 210 objects for deletion2289--- PASS: TestClientErrorHandling (0.00s)2290 --- PASS: TestClientErrorHandling/InvalidStorePath (5.73s)2291 --- PASS: TestClientErrorHandling/InvalidAuthToken (5.69s)2292 --- PASS: TestClientErrorHandling/ServerNotAvailable (12.42s)2293=== NAME TestOrphanedObjectsGCStressTest2294 orphaned_objects_gc_test.go:503: Stress test completed successfully:2295 orphaned_objects_gc_test.go:504: - Active objects preserved: 202296 orphaned_objects_gc_test.go:505: - Objects deleted: 2102297 orphaned_objects_gc_test.go:506: - Total GC'd: 2102298--- PASS: TestOrphanedObjectsGCStressTest (22.66s)2299PASS2300{"timestamp":"2026-11-04T20:14:24.409634Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:49162","error_kind":"io_error","error":"Cancelled","result":"transport_error","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":2561,"threadName":"rustfs-worker","threadId":"ThreadId(10)"}2301{"timestamp":"2026-11-04T20:14:24.413404Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:49220","error_kind":"io_error","error":"Cancelled","result":"transport_error","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":2561,"threadName":"rustfs-worker","threadId":"ThreadId(3)"}23022026-11-04 20:14:24.517 UTC [55136] LOG: received smart shutdown request23032026-11-04 20:14:24.519 UTC [55136] LOG: background worker "logical replication launcher" (PID 55146) exited with exit code 123042026-11-04 20:14:24.535 UTC [55141] LOG: shutting down23052026-11-04 20:14:24.535 UTC [55141] LOG: checkpoint starting: shutdown immediate23062026-11-04 20:14:26.219 UTC [55141] LOG: checkpoint complete: wrote 11978 buffers (73.1%), wrote 5 SLRU buffers; 0 WAL file(s) added, 0 removed, 32 recycled; write=0.942 s, sync=0.709 s, total=1.685 s; sync files=35725, longest=0.001 s, average=0.001 s; distance=525269 kB, estimate=525269 kB; lsn=0/218824C8, redo lsn=0/218824C823072026-11-04 20:14:26.229 UTC [55136] LOG: database system is shut down2308Running OIDC tests...2309=== RUN TestAudienceForIssuer2310=== PAUSE TestAudienceForIssuer2311=== RUN TestGlobMatch2312=== PAUSE TestGlobMatch2313=== RUN TestValidateToken_ValidToken2314=== PAUSE TestValidateToken_ValidToken2315=== RUN TestValidateToken_WrongAudience2316=== PAUSE TestValidateToken_WrongAudience2317=== RUN TestValidateToken_Expired2318=== PAUSE TestValidateToken_Expired2319=== RUN TestValidateToken_BoundClaimsMismatch2320=== PAUSE TestValidateToken_BoundClaimsMismatch2321=== RUN TestValidateToken_BoundSubjectMismatch2322=== PAUSE TestValidateToken_BoundSubjectMismatch2323=== RUN TestValidateToken_MultipleProviders2324=== PAUSE TestValidateToken_MultipleProviders2325=== RUN TestValidateToken_NoMatchingProvider2326=== PAUSE TestValidateToken_NoMatchingProvider2327=== RUN TestValidateToken_KubernetesServiceAccount2328=== PAUSE TestValidateToken_KubernetesServiceAccount2329=== RUN TestNewValidator_KubernetesRequiresCA2330=== PAUSE TestNewValidator_KubernetesRequiresCA2331=== RUN TestValidateToken_KubernetesIssuerFromOwnToken2332=== PAUSE TestValidateToken_KubernetesIssuerFromOwnToken2333=== RUN TestPins_ReservedForMatchingRule2334=== PAUSE TestPins_ReservedForMatchingRule2335=== RUN TestPins_TopLevelShorthand2336=== PAUSE TestPins_TopLevelShorthand2337=== RUN TestPins_ConfigValidation2338=== PAUSE TestPins_ConfigValidation2339=== RUN TestScopes_LegacyProviderDefaultsToWrite2340=== PAUSE TestScopes_LegacyProviderDefaultsToWrite2341=== RUN TestScopes_Rules2342=== PAUSE TestScopes_Rules2343=== RUN TestScopes_ConfigValidation2344=== PAUSE TestScopes_ConfigValidation2345=== CONT TestAudienceForIssuer2346--- PASS: TestAudienceForIssuer (0.00s)2347=== CONT TestValidateToken_NoMatchingProvider2348=== CONT TestScopes_LegacyProviderDefaultsToWrite2349=== CONT TestPins_ConfigValidation2350=== CONT TestPins_ReservedForMatchingRule2351=== CONT TestScopes_ConfigValidation2352=== CONT TestValidateToken_KubernetesServiceAccount2353=== CONT TestScopes_Rules2354--- PASS: TestPins_ConfigValidation (0.00s)2355--- PASS: TestScopes_ConfigValidation (0.00s)2356=== CONT TestValidateToken_KubernetesIssuerFromOwnToken2357=== CONT TestNewValidator_KubernetesRequiresCA2358=== CONT TestValidateToken_Expired2359=== CONT TestValidateToken_MultipleProviders2360=== CONT TestValidateToken_BoundClaimsMismatch2361=== CONT TestValidateToken_BoundSubjectMismatch2362=== CONT TestValidateToken_ValidToken2363=== CONT TestValidateToken_WrongAudience2364=== CONT TestGlobMatch2365=== RUN TestGlobMatch/foo_foo2366=== PAUSE TestGlobMatch/foo_foo2367=== RUN TestGlobMatch/foo_bar2368=== PAUSE TestGlobMatch/foo_bar2369=== RUN TestGlobMatch/*_2370=== PAUSE TestGlobMatch/*_2371=== RUN TestGlobMatch/*_anything2372=== PAUSE TestGlobMatch/*_anything2373=== RUN TestGlobMatch/foo*_foo2374=== PAUSE TestGlobMatch/foo*_foo2375=== RUN TestGlobMatch/foo*_foobar2376=== PAUSE TestGlobMatch/foo*_foobar2377=== RUN TestGlobMatch/foo*_bar2378=== PAUSE TestGlobMatch/foo*_bar2379=== RUN TestGlobMatch/*bar_bar2380=== PAUSE TestGlobMatch/*bar_bar2381=== RUN TestGlobMatch/*bar_foobar2382=== CONT TestPins_TopLevelShorthand2383=== PAUSE TestGlobMatch/*bar_foobar2384=== RUN TestGlobMatch/*bar_foo2385=== PAUSE TestGlobMatch/*bar_foo2386=== RUN TestGlobMatch/foo*bar_foobar2387=== PAUSE TestGlobMatch/foo*bar_foobar2388=== RUN TestGlobMatch/foo*bar_foo123bar2389=== PAUSE TestGlobMatch/foo*bar_foo123bar2390=== RUN TestGlobMatch/foo*bar_foobarbaz2391=== PAUSE TestGlobMatch/foo*bar_foobarbaz2392=== RUN TestGlobMatch/*/*_foo/bar2393=== PAUSE TestGlobMatch/*/*_foo/bar2394=== RUN TestGlobMatch/*/*_foo2395=== PAUSE TestGlobMatch/*/*_foo2396=== RUN TestGlobMatch/refs/heads/*_refs/heads/main2397=== PAUSE TestGlobMatch/refs/heads/*_refs/heads/main2398=== RUN TestGlobMatch/refs/heads/*_refs/tags/v1.02399=== PAUSE TestGlobMatch/refs/heads/*_refs/tags/v1.02400=== RUN TestGlobMatch/refs/*/main_refs/heads/main2401=== PAUSE TestGlobMatch/refs/*/main_refs/heads/main2402=== RUN TestGlobMatch/fo?_foo2403=== PAUSE TestGlobMatch/fo?_foo2404=== RUN TestGlobMatch/fo?_fo2405=== PAUSE TestGlobMatch/fo?_fo2406=== RUN TestGlobMatch/fo?_fooo2407=== PAUSE TestGlobMatch/fo?_fooo2408=== RUN TestGlobMatch/?oo_foo2409=== PAUSE TestGlobMatch/?oo_foo2410=== RUN TestGlobMatch/?oo_boo2411=== PAUSE TestGlobMatch/?oo_boo2412=== RUN TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2413=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2414=== RUN TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2415=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2416=== CONT TestGlobMatch/foo_foo2417=== CONT TestGlobMatch/*/*_foo/bar2418=== CONT TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2419=== CONT TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2420=== CONT TestGlobMatch/*bar_bar2421=== CONT TestGlobMatch/foo*bar_foobarbaz2422=== CONT TestGlobMatch/foo*bar_foo123bar2423=== CONT TestGlobMatch/foo*bar_foobar2424=== CONT TestGlobMatch/*bar_foo2425=== CONT TestGlobMatch/fo?_foo2426=== CONT TestGlobMatch/?oo_boo2427=== CONT TestGlobMatch/?oo_foo2428=== CONT TestGlobMatch/fo?_fooo2429=== CONT TestGlobMatch/fo?_fo2430=== CONT TestGlobMatch/refs/heads/*_refs/tags/v1.02431=== CONT TestGlobMatch/refs/*/main_refs/heads/main2432=== CONT TestGlobMatch/refs/heads/*_refs/heads/main2433=== CONT TestGlobMatch/*/*_foo2434=== CONT TestGlobMatch/*bar_foobar2435=== CONT TestGlobMatch/foo*_foo2436=== CONT TestGlobMatch/foo*_bar2437=== CONT TestGlobMatch/foo*_foobar2438=== CONT TestGlobMatch/*_2439=== CONT TestGlobMatch/*_anything2440=== CONT TestGlobMatch/foo_bar2441--- PASS: TestGlobMatch (0.02s)2442 --- PASS: TestGlobMatch/foo_foo (0.00s)2443 --- PASS: TestGlobMatch/*/*_foo/bar (0.00s)2444 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main (0.00s)2445 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main (0.00s)2446 --- PASS: TestGlobMatch/*bar_bar (0.00s)2447 --- PASS: TestGlobMatch/foo*bar_foobarbaz (0.00s)2448 --- PASS: TestGlobMatch/foo*bar_foo123bar (0.00s)2449 --- PASS: TestGlobMatch/foo*bar_foobar (0.00s)2450 --- PASS: TestGlobMatch/*/*_foo (0.00s)2451 --- PASS: TestGlobMatch/*bar_foobar (0.00s)2452 --- PASS: TestGlobMatch/foo*_foo (0.00s)2453 --- PASS: TestGlobMatch/foo*_bar (0.00s)2454 --- PASS: TestGlobMatch/foo*_foobar (0.00s)2455 --- PASS: TestGlobMatch/*_ (0.00s)2456 --- PASS: TestGlobMatch/*_anything (0.00s)2457 --- PASS: TestGlobMatch/foo_bar (0.00s)2458 --- PASS: TestGlobMatch/*bar_foo (0.00s)2459 --- PASS: TestGlobMatch/fo?_foo (0.00s)2460 --- PASS: TestGlobMatch/?oo_boo (0.00s)2461 --- PASS: TestGlobMatch/?oo_foo (0.00s)2462 --- PASS: TestGlobMatch/fo?_fooo (0.00s)2463 --- PASS: TestGlobMatch/fo?_fo (0.00s)2464 --- PASS: TestGlobMatch/refs/heads/*_refs/tags/v1.0 (0.00s)2465 --- PASS: TestGlobMatch/refs/*/main_refs/heads/main (0.00s)2466 --- PASS: TestGlobMatch/refs/heads/*_refs/heads/main (0.00s)24672026/11/04 20:14:27 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:49495/oidc24682026/11/04 20:14:27 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:49499/oidc24692026/11/04 20:14:27 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:49498/oidc2470--- PASS: TestValidateToken_BoundSubjectMismatch (0.07s)2471--- PASS: TestValidateToken_Expired (0.08s)2472--- PASS: TestPins_ReservedForMatchingRule (0.09s)24732026/11/04 20:14:27 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:49504/oidc24742026/11/04 20:14:27 INFO OIDC provider initialized name=kubernetes issuer=https://127.0.0.1:495012475--- PASS: TestScopes_Rules (0.10s)2476--- PASS: TestValidateToken_KubernetesServiceAccount (0.10s)24772026/11/04 20:14:27 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:49506/oidc2478--- PASS: TestValidateToken_BoundClaimsMismatch (0.09s)24792026/11/04 20:14:27 INFO OIDC provider initialized name=kubernetes issuer=https://oidc.eks.invalid/id/ABC1232480--- PASS: TestValidateToken_KubernetesIssuerFromOwnToken (0.13s)24812026/11/04 20:14:28 http: TLS handshake error from 127.0.0.1:49513: read tcp 127.0.0.1:49512->127.0.0.1:49513: use of closed network connection2482--- PASS: TestNewValidator_KubernetesRequiresCA (0.15s)24832026/11/04 20:14:28 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:49497/oidc24842026/11/04 20:14:28 INFO OIDC provider initialized name=provider2 issuer=http://127.0.0.1:49514/oidc24852026/11/04 20:14:28 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:49517/oidc2486--- PASS: TestValidateToken_MultipleProviders (0.14s)2487--- PASS: TestPins_TopLevelShorthand (0.12s)24882026/11/04 20:14:28 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:49509/oidc2489--- PASS: TestValidateToken_NoMatchingProvider (0.17s)24902026/11/04 20:14:28 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:49521/oidc2491--- PASS: TestValidateToken_WrongAudience (0.16s)24922026/11/04 20:14:28 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:49523/oidc2493--- PASS: TestScopes_LegacyProviderDefaultsToWrite (0.20s)24942026/11/04 20:14:28 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:49525/oidc2495--- PASS: TestValidateToken_ValidToken (0.18s)2496PASS2497Running hook tests...2498=== RUN TestSendPathsEmpty2499=== PAUSE TestSendPathsEmpty2500=== RUN TestQueueEnqueueAndFetch2501=== PAUSE TestQueueEnqueueAndFetch2502=== RUN TestQueueDeduplication2503=== PAUSE TestQueueDeduplication2504=== RUN TestQueueRemove2505=== PAUSE TestQueueRemove2506=== RUN TestQueueFetchBatchLimit2507=== PAUSE TestQueueFetchBatchLimit2508=== RUN TestQueueRetryMovesToBack2509=== PAUSE TestQueueRetryMovesToBack2510=== RUN TestQueueFetchRemoveLifecycle2511=== PAUSE TestQueueFetchRemoveLifecycle2512=== RUN TestQueueConcurrentWriters2513=== PAUSE TestQueueConcurrentWriters2514=== RUN TestQueueRemoveLargeClosure2515=== PAUSE TestQueueRemoveLargeClosure2516=== RUN TestServerClientIntegration2517--- PASS: TestServerClientIntegration (0.00s)2518=== RUN TestServerQueueError25192026/11/04 20:14:28 ERROR Failed to queue paths error="permission denied" count=12520--- PASS: TestServerQueueError (0.00s)2521=== RUN TestGetListenerSocketActivation2522 server_test.go:145: systemd socket activation does not exist on darwin2523--- SKIP: TestGetListenerSocketActivation (0.00s)2524=== RUN TestServerStalledClientDoesNotBlockShutdown2525=== PAUSE TestServerStalledClientDoesNotBlockShutdown2526=== RUN TestServerBacksOffOnAcceptErrors2527=== PAUSE TestServerBacksOffOnAcceptErrors2528=== RUN TestDrainIsolatesPoisonPath2529=== PAUSE TestDrainIsolatesPoisonPath2530=== RUN TestRunNotBlockedByPoisonHead2531=== PAUSE TestRunNotBlockedByPoisonHead2532=== RUN TestDrainGivesUpWhenServerDown2533=== PAUSE TestDrainGivesUpWhenServerDown2534=== RUN TestFailedPathPrunedByLaterClosure2535=== PAUSE TestFailedPathPrunedByLaterClosure2536=== RUN TestWorkerUploadsAndRemoves2537=== PAUSE TestWorkerUploadsAndRemoves2538=== RUN TestWorkerSkipsGCdPaths2539=== PAUSE TestWorkerSkipsGCdPaths2540=== RUN TestWorkerPrunesClosureDeps2541=== PAUSE TestWorkerPrunesClosureDeps2542=== RUN TestDrainTimeout2543=== PAUSE TestDrainTimeout2544=== RUN TestWorkerRemoveFailureIsNotProgress2545=== PAUSE TestWorkerRemoveFailureIsNotProgress2546=== RUN TestWorkerKeepsPathItCannotStat2547=== PAUSE TestWorkerKeepsPathItCannotStat2548=== CONT TestSendPathsEmpty2549=== CONT TestDrainIsolatesPoisonPath2550--- PASS: TestSendPathsEmpty (0.00s)2551=== CONT TestQueueRetryMovesToBack2552=== CONT TestWorkerKeepsPathItCannotStat2553=== CONT TestWorkerRemoveFailureIsNotProgress2554=== CONT TestDrainTimeout2555=== CONT TestServerStalledClientDoesNotBlockShutdown2556=== CONT TestWorkerSkipsGCdPaths2557=== CONT TestWorkerUploadsAndRemoves2558=== CONT TestFailedPathPrunedByLaterClosure2559=== CONT TestDrainGivesUpWhenServerDown2560=== CONT TestRunNotBlockedByPoisonHead2561=== CONT TestQueueRemoveLargeClosure2562=== CONT TestQueueConcurrentWriters2563=== CONT TestQueueFetchRemoveLifecycle2564=== CONT TestServerBacksOffOnAcceptErrors25652026/11/04 20:14:28 ERROR Accept failed error="too many open files"2566=== CONT TestQueueDeduplication2567=== CONT TestQueueRemove2568=== CONT TestQueueEnqueueAndFetch2569=== CONT TestQueueFetchBatchLimit2570=== CONT TestWorkerPrunesClosureDeps25712026/11/04 20:14:28 ERROR Accept failed error="too many open files"25722026/11/04 20:14:28 INFO Uploading batch count=225732026/11/04 20:14:28 ERROR Upload failed error="upload failed" count=225742026/11/04 20:14:28 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/7/scratch/63b205a296af2db3/build/TestDrainGivesUpWhenServerDown3656630314/002/a25752026/11/04 20:14:28 INFO Uploading batch count=125762026/11/04 20:14:28 ERROR Upload failed error="upload failed" count=125772026/11/04 20:14:28 INFO Uploading batch count=125782026/11/04 20:14:28 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/7/scratch/63b205a296af2db3/build/TestDrainGivesUpWhenServerDown3656630314/002/b2579--- PASS: TestQueueDeduplication (0.01s)2580--- PASS: TestQueueRetryMovesToBack (0.01s)25812026/11/04 20:14:28 INFO Uploading batch count=22582--- PASS: TestQueueFetchRemoveLifecycle (0.01s)25832026/11/04 20:14:28 WARN Cannot stat store path, will retry later path=/private/var/tb/7/scratch/63b205a296af2db3/build/TestWorkerKeepsPathItCannotStat1883985731/002/locked/aaa error="stat /private/var/tb/7/scratch/63b205a296af2db3/build/TestWorkerKeepsPathItCannotStat1883985731/002/locked/aaa: permission denied"2584--- PASS: TestQueueFetchBatchLimit (0.01s)25852026/11/04 20:14:28 INFO Upload queue status pending=225862026/11/04 20:14:28 WARN Cannot stat store path, will retry later path=/private/var/tb/7/scratch/63b205a296af2db3/build/TestWorkerKeepsPathItCannotStat1883985731/002/locked/aaa error="stat /private/var/tb/7/scratch/63b205a296af2db3/build/TestWorkerKeepsPathItCannotStat1883985731/002/locked/aaa: permission denied"25872026/11/04 20:14:28 WARN Cannot stat store path, will retry later path=/private/var/tb/7/scratch/63b205a296af2db3/build/TestWorkerKeepsPathItCannotStat1883985731/002/locked/aaa error="stat /private/var/tb/7/scratch/63b205a296af2db3/build/TestWorkerKeepsPathItCannotStat1883985731/002/locked/aaa: permission denied"25882026/11/04 20:14:28 INFO Uploading batch count=225892026/11/04 20:14:28 ERROR Upload failed error="upload failed" count=225902026/11/04 20:14:28 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/7/scratch/63b205a296af2db3/build/TestDrainGivesUpWhenServerDown3656630314/002/c25912026/11/04 20:14:28 INFO Upload queue status pending=225922026/11/04 20:14:28 INFO Uploading batch count=125932026/11/04 20:14:28 INFO Uploading batch count=225942026/11/04 20:14:28 ERROR Drain finished with paths left in queue remaining=125952026/11/04 20:14:28 INFO Uploading batch count=12596--- PASS: TestQueueRemove (0.01s)25972026/11/04 20:14:28 INFO Upload queue status pending=225982026/11/04 20:14:28 INFO Uploading batch count=425992026/11/04 20:14:28 ERROR Upload failed error="upload failed" count=426002026/11/04 20:14:28 WARN Store path no longer exists (garbage collected?), removing from queue path=/private/var/tb/7/scratch/63b205a296af2db3/build/TestWorkerSkipsGCdPaths3439916232/002/nonexistent26012026/11/04 20:14:28 INFO Uploading batch count=126022026/11/04 20:14:28 INFO Upload queue status pending=326032026/11/04 20:14:28 INFO Uploading batch count=126042026/11/04 20:14:28 ERROR Upload failed error="upload failed" count=126052026/11/04 20:14:28 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/7/scratch/63b205a296af2db3/build/TestDrainIsolatesPoisonPath4011664204/002/bbb26062026/11/04 20:14:28 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/7/scratch/63b205a296af2db3/build/TestDrainGivesUpWhenServerDown3656630314/002/d26072026/11/04 20:14:28 WARN Store path no longer exists (garbage collected?), removing from queue path=/private/var/tb/7/scratch/63b205a296af2db3/build/TestWorkerRemoveFailureIsNotProgress1341188134/002/nonexistent26082026/11/04 20:14:28 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=126092026/11/04 20:14:28 WARN Store path no longer exists (garbage collected?), removing from queue path=/private/var/tb/7/scratch/63b205a296af2db3/build/TestWorkerRemoveFailureIsNotProgress1341188134/002/nonexistent26102026/11/04 20:14:28 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=126112026/11/04 20:14:28 INFO Uploading batch count=126122026/11/04 20:14:28 INFO Uploading batch count=226132026/11/04 20:14:28 ERROR Upload failed error="upload failed" count=226142026/11/04 20:14:28 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/7/scratch/63b205a296af2db3/build/TestDrainGivesUpWhenServerDown3656630314/002/e26152026/11/04 20:14:28 WARN Store path no longer exists (garbage collected?), removing from queue path=/private/var/tb/7/scratch/63b205a296af2db3/build/TestWorkerRemoveFailureIsNotProgress1341188134/002/nonexistent26162026/11/04 20:14:28 ERROR Upload failed error="upload failed" count=126172026/11/04 20:14:28 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=126182026/11/04 20:14:28 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/7/scratch/63b205a296af2db3/build/TestDrainGivesUpWhenServerDown3656630314/002/f26192026/11/04 20:14:28 ERROR Drain finished with paths left in queue remaining=1026202026/11/04 20:14:28 ERROR Drain finished with paths left in queue remaining=12621--- PASS: TestFailedPathPrunedByLaterClosure (0.02s)2622--- PASS: TestWorkerKeepsPathItCannotStat (0.02s)26232026/11/04 20:14:28 INFO Uploading batch count=126242026/11/04 20:14:28 ERROR Upload failed error="upload failed" count=12625--- PASS: TestQueueEnqueueAndFetch (0.01s)26262026/11/04 20:14:28 INFO Uploading batch count=12627--- PASS: TestWorkerRemoveFailureIsNotProgress (0.02s)26282026/11/04 20:14:28 ERROR Accept failed error="too many open files"26292026/11/04 20:14:28 ERROR Upload failed error="upload failed" count=126302026/11/04 20:14:28 ERROR Drain finished with paths left in queue remaining=12631--- PASS: TestDrainGivesUpWhenServerDown (0.02s)2632--- PASS: TestDrainIsolatesPoisonPath (0.02s)2633--- PASS: TestWorkerUploadsAndRemoves (0.03s)2634--- PASS: TestWorkerSkipsGCdPaths (0.04s)2635--- PASS: TestWorkerPrunesClosureDeps (0.03s)26362026/11/04 20:14:28 ERROR Accept failed error="too many open files"2637--- PASS: TestQueueRemoveLargeClosure (0.04s)2638--- PASS: TestQueueConcurrentWriters (0.04s)26392026/11/04 20:14:28 ERROR Accept failed error="too many open files"26402026/11/04 20:14:28 ERROR Accept failed error="too many open files"26412026/11/04 20:14:28 ERROR Failed to decode request error="read unix /private/var/tb/7/scratch/63b205a296af2db3/build/hook3761280501/test.sock->: i/o timeout"26422026/11/04 20:14:28 ERROR Failed to write response error="write unix /private/var/tb/7/scratch/63b205a296af2db3/build/hook3761280501/test.sock->: i/o timeout"2643--- PASS: TestServerStalledClientDoesNotBlockShutdown (0.20s)26442026/11/04 20:14:28 ERROR Upload failed error="context deadline exceeded" count=226452026/11/04 20:14:28 ERROR Drain finished with paths left in queue remaining=42646--- PASS: TestDrainTimeout (0.21s)26472026/11/04 20:14:28 ERROR Accept failed error="too many open files"26482026/11/04 20:14:29 ERROR Accept failed error="too many open files"2649--- PASS: TestServerBacksOffOnAcceptErrors (0.64s)26502026/11/04 20:14:29 INFO Uploading batch count=126512026/11/04 20:14:29 INFO Uploading batch count=126522026/11/04 20:14:29 INFO Uploading batch count=126532026/11/04 20:14:29 ERROR Upload failed error="upload failed" count=126542026/11/04 20:14:29 INFO Uploading batch count=126552026/11/04 20:14:29 ERROR Upload failed error="upload failed" count=126562026/11/04 20:14:29 INFO Uploading batch count=126572026/11/04 20:14:29 ERROR Upload failed error="upload failed" count=126582026/11/04 20:14:29 INFO Uploading batch count=126592026/11/04 20:14:29 ERROR Upload failed error="upload failed" count=126602026/11/04 20:14:29 ERROR Drain finished with paths left in queue remaining=12661--- PASS: TestRunNotBlockedByPoisonHead (1.04s)2662PASS2663Running signing tests...2664=== RUN TestExternalSigner2665=== PAUSE TestExternalSigner2666=== RUN TestExternalSignerWrongPublicKey2667=== PAUSE TestExternalSignerWrongPublicKey2668=== RUN TestExternalSignerErrors2669=== PAUSE TestExternalSignerErrors2670=== RUN TestExternalSignerRestartsAfterCrash2671=== PAUSE TestExternalSignerRestartsAfterCrash2672=== RUN TestExternalSignerProgramErrorKeepsProcess2673=== PAUSE TestExternalSignerProgramErrorKeepsProcess2674=== RUN TestExternalSignerClose2675=== PAUSE TestExternalSignerClose2676=== RUN TestExternalSignerRejectsInvalidPublicKey2677=== PAUSE TestExternalSignerRejectsInvalidPublicKey2678=== RUN TestExternalSignerCancellation2679=== PAUSE TestExternalSignerCancellation2680=== RUN TestGenerateFingerprint2681=== PAUSE TestGenerateFingerprint2682=== RUN TestParseSigningKey2683=== PAUSE TestParseSigningKey2684=== RUN TestSign2685=== PAUSE TestSign2686=== RUN TestSignBatch2687=== PAUSE TestSignBatch2688=== RUN TestNilKeyPublicKey2689=== PAUSE TestNilKeyPublicKey2690=== RUN TestSignErrors2691=== PAUSE TestSignErrors2692=== CONT TestExternalSigner2693=== CONT TestExternalSignerCancellation2694=== CONT TestExternalSignerProgramErrorKeepsProcess2695=== CONT TestSignBatch2696=== CONT TestExternalSignerRejectsInvalidPublicKey2697=== RUN TestExternalSignerRejectsInvalidPublicKey/#002698=== PAUSE TestExternalSignerRejectsInvalidPublicKey/#002699=== RUN TestExternalSignerRejectsInvalidPublicKey/no-colon2700=== PAUSE TestExternalSignerRejectsInvalidPublicKey/no-colon2701=== RUN TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2702=== PAUSE TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2703=== RUN TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2704=== PAUSE TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2705=== RUN TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2706=== PAUSE TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2707=== CONT TestExternalSignerRejectsInvalidPublicKey/#002708=== CONT TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2709=== CONT TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2710=== CONT TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2711=== CONT TestExternalSignerRejectsInvalidPublicKey/no-colon2712=== CONT TestExternalSignerClose2713=== CONT TestSign2714=== CONT TestExternalSignerErrors2715=== RUN TestExternalSignerErrors/wrong_shape2716=== CONT TestGenerateFingerprint2717=== RUN TestGenerateFingerprint/basic_with_references2718=== PAUSE TestGenerateFingerprint/basic_with_references2719=== CONT TestSignErrors2720=== CONT TestExternalSignerRestartsAfterCrash2721--- PASS: TestExternalSignerRejectsInvalidPublicKey (0.00s)2722 --- PASS: TestExternalSignerRejectsInvalidPublicKey/#00 (0.00s)2723 --- PASS: TestExternalSignerRejectsInvalidPublicKey/test-key:YQ== (0.00s)2724 --- PASS: TestExternalSignerRejectsInvalidPublicKey/test-key:invalid! (0.00s)2725 --- PASS: TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA= (0.00s)2726 --- PASS: TestExternalSignerRejectsInvalidPublicKey/no-colon (0.00s)2727=== CONT TestExternalSignerWrongPublicKey2728=== CONT TestNilKeyPublicKey2729--- PASS: TestNilKeyPublicKey (0.00s)2730=== PAUSE TestExternalSignerErrors/wrong_shape2731=== RUN TestExternalSignerErrors/null2732=== RUN TestGenerateFingerprint/no_references2733=== PAUSE TestExternalSignerErrors/null2734=== PAUSE TestGenerateFingerprint/no_references2735=== RUN TestExternalSignerErrors/missing_signatures2736=== CONT TestParseSigningKey2737=== RUN TestGenerateFingerprint/unsorted_references_get_sorted2738=== PAUSE TestExternalSignerErrors/missing_signatures2739=== RUN TestParseSigningKey/valid_32-byte_key2740=== RUN TestExternalSignerErrors/missing_signature_name2741=== PAUSE TestExternalSignerErrors/missing_signature_name2742=== RUN TestExternalSignerErrors/wrong_signature_length2743=== PAUSE TestExternalSignerErrors/wrong_signature_length2744=== RUN TestExternalSignerErrors/program_error2745=== PAUSE TestExternalSignerErrors/program_error2746=== RUN TestExternalSignerErrors/exit_at_startup2747=== PAUSE TestParseSigningKey/valid_32-byte_key2748=== PAUSE TestGenerateFingerprint/unsorted_references_get_sorted2749=== PAUSE TestExternalSignerErrors/exit_at_startup2750=== RUN TestParseSigningKey/valid_32-byte_key_with_different_name2751=== PAUSE TestParseSigningKey/valid_32-byte_key_with_different_name2752=== RUN TestExternalSignerErrors/invalid_JSON2753=== PAUSE TestExternalSignerErrors/invalid_JSON2754=== RUN TestExternalSignerErrors/too_few_signatures2755=== RUN TestGenerateFingerprint/invalid_nar_hash_prefix2756=== PAUSE TestGenerateFingerprint/invalid_nar_hash_prefix2757=== RUN TestGenerateFingerprint/invalid_nar_hash_length2758=== PAUSE TestGenerateFingerprint/invalid_nar_hash_length2759=== RUN TestGenerateFingerprint/invalid_store_path_prefix2760=== PAUSE TestGenerateFingerprint/invalid_store_path_prefix2761=== RUN TestGenerateFingerprint/invalid_reference_prefix2762=== PAUSE TestGenerateFingerprint/invalid_reference_prefix2763=== CONT TestGenerateFingerprint/basic_with_references2764=== RUN TestParseSigningKey/no_colon2765=== PAUSE TestParseSigningKey/no_colon2766=== RUN TestParseSigningKey/empty_name2767=== PAUSE TestParseSigningKey/empty_name2768=== RUN TestParseSigningKey/invalid_base642769=== PAUSE TestParseSigningKey/invalid_base642770=== RUN TestParseSigningKey/wrong_length2771=== PAUSE TestParseSigningKey/wrong_length2772=== CONT TestParseSigningKey/valid_32-byte_key2773=== CONT TestGenerateFingerprint/invalid_reference_prefix2774=== CONT TestGenerateFingerprint/invalid_store_path_prefix2775=== CONT TestGenerateFingerprint/invalid_nar_hash_length2776--- PASS: TestSign (0.00s)2777=== RUN TestSignErrors/nil_key2778=== PAUSE TestSignErrors/nil_key2779=== RUN TestSignErrors/nil_narinfo2780=== PAUSE TestSignErrors/nil_narinfo2781=== RUN TestSignErrors/invalid_narinfo2782=== PAUSE TestSignErrors/invalid_narinfo2783=== RUN TestSignErrors/canceled2784=== PAUSE TestSignErrors/canceled2785=== CONT TestSignErrors/nil_key2786=== CONT TestGenerateFingerprint/invalid_nar_hash_prefix2787=== CONT TestGenerateFingerprint/unsorted_references_get_sorted2788=== CONT TestGenerateFingerprint/no_references2789--- PASS: TestGenerateFingerprint (0.00s)2790 --- PASS: TestGenerateFingerprint/basic_with_references (0.00s)2791 --- PASS: TestGenerateFingerprint/invalid_reference_prefix (0.00s)2792 --- PASS: TestGenerateFingerprint/invalid_store_path_prefix (0.00s)2793 --- PASS: TestGenerateFingerprint/invalid_nar_hash_length (0.00s)2794 --- PASS: TestGenerateFingerprint/invalid_nar_hash_prefix (0.00s)2795 --- PASS: TestGenerateFingerprint/unsorted_references_get_sorted (0.00s)2796 --- PASS: TestGenerateFingerprint/no_references (0.00s)2797=== PAUSE TestExternalSignerErrors/too_few_signatures2798=== RUN TestExternalSignerErrors/wrong_signature_name2799=== PAUSE TestExternalSignerErrors/wrong_signature_name2800=== RUN TestExternalSignerErrors/exit_on_request2801=== PAUSE TestExternalSignerErrors/exit_on_request2802=== CONT TestParseSigningKey/wrong_length2803=== CONT TestParseSigningKey/invalid_base642804=== CONT TestParseSigningKey/empty_name2805=== CONT TestParseSigningKey/no_colon2806=== CONT TestParseSigningKey/valid_32-byte_key_with_different_name2807--- PASS: TestParseSigningKey (0.00s)2808 --- PASS: TestParseSigningKey/valid_32-byte_key (0.00s)2809 --- PASS: TestParseSigningKey/wrong_length (0.00s)2810 --- PASS: TestParseSigningKey/invalid_base64 (0.00s)2811 --- PASS: TestParseSigningKey/empty_name (0.00s)2812 --- PASS: TestParseSigningKey/no_colon (0.00s)2813 --- PASS: TestParseSigningKey/valid_32-byte_key_with_different_name (0.00s)2814=== CONT TestSignErrors/invalid_narinfo2815=== CONT TestSignErrors/canceled2816--- PASS: TestSignBatch (0.00s)2817=== CONT TestSignErrors/nil_narinfo2818=== RUN TestExternalSignerErrors/wrong_id2819=== PAUSE TestExternalSignerErrors/wrong_id2820=== RUN TestExternalSignerErrors/null_signatures2821--- PASS: TestSignErrors (0.00s)2822 --- PASS: TestSignErrors/nil_key (0.00s)2823 --- PASS: TestSignErrors/invalid_narinfo (0.00s)2824 --- PASS: TestSignErrors/canceled (0.00s)2825 --- PASS: TestSignErrors/nil_narinfo (0.00s)2826=== PAUSE TestExternalSignerErrors/null_signatures2827=== RUN TestExternalSignerErrors/wrong_signatures_shape2828=== PAUSE TestExternalSignerErrors/wrong_signatures_shape2829=== RUN TestExternalSignerErrors/invalid_signature_base642830=== PAUSE TestExternalSignerErrors/invalid_signature_base642831=== RUN TestExternalSignerErrors/unrequested_key2832=== PAUSE TestExternalSignerErrors/unrequested_key2833=== CONT TestExternalSignerErrors/wrong_shape2834=== CONT TestExternalSignerErrors/invalid_signature_base642835=== CONT TestExternalSignerErrors/wrong_signature_name2836=== CONT TestExternalSignerErrors/too_few_signatures2837=== CONT TestExternalSignerErrors/null_signatures2838=== CONT TestExternalSignerErrors/wrong_id2839=== CONT TestExternalSignerErrors/exit_on_request2840=== CONT TestExternalSignerErrors/program_error2841=== CONT TestExternalSignerErrors/unrequested_key2842=== CONT TestExternalSignerErrors/invalid_JSON2843=== CONT TestExternalSignerErrors/exit_at_startup2844=== CONT TestExternalSignerErrors/missing_signature_name2845=== CONT TestExternalSignerErrors/wrong_signature_length2846=== CONT TestExternalSignerErrors/missing_signatures2847=== CONT TestExternalSignerErrors/null2848=== CONT TestExternalSignerErrors/wrong_signatures_shape2849--- PASS: TestExternalSigner (0.23s)2850--- PASS: TestExternalSignerCancellation (0.43s)2851--- PASS: TestExternalSignerClose (1.22s)2852--- PASS: TestExternalSignerWrongPublicKey (2.56s)2853--- PASS: TestExternalSignerProgramErrorKeepsProcess (2.95s)2854--- PASS: TestExternalSignerRestartsAfterCrash (3.35s)2855/private/var/tb/7/scratch/63b205a296af2db3/build/TestExternalSignerRestartsAfterCrash2247496514/001/sign program: line 7: /private/var/tb/7/scratch/63b205a296af2db3/build/TestExternalSignerRestartsAfterCrash2247496514/001/sign program.starts: No such file or directory2856--- PASS: TestExternalSignerErrors (0.00s)2857 --- PASS: TestExternalSignerErrors/wrong_signature_name (0.60s)2858 --- PASS: TestExternalSignerErrors/program_error (0.79s)2859 --- PASS: TestExternalSignerErrors/exit_on_request (1.41s)2860 --- PASS: TestExternalSignerErrors/missing_signature_name (1.59s)2861 --- PASS: TestExternalSignerErrors/invalid_signature_base64 (1.79s)2862 --- PASS: TestExternalSignerErrors/invalid_JSON (1.97s)2863 --- PASS: TestExternalSignerErrors/exit_at_startup (2.17s)2864 --- PASS: TestExternalSignerErrors/too_few_signatures (2.36s)2865 --- PASS: TestExternalSignerErrors/wrong_shape (2.75s)2866 --- PASS: TestExternalSignerErrors/unrequested_key (3.14s)2867 --- PASS: TestExternalSignerErrors/wrong_signatures_shape (3.52s)2868 --- PASS: TestExternalSignerErrors/null_signatures (3.71s)2869 --- PASS: TestExternalSignerErrors/wrong_id (3.90s)2870 --- PASS: TestExternalSignerErrors/wrong_signature_length (4.09s)2871 --- PASS: TestExternalSignerErrors/missing_signatures (4.28s)2872 --- PASS: TestExternalSignerErrors/null (4.47s)2873PASS2874Running OpenBao signer tests...2875=== RUN TestSign2876=== PAUSE TestSign2877=== RUN TestSignErrors2878=== PAUSE TestSignErrors2879=== RUN TestServe2880=== PAUSE TestServe2881=== RUN TestServeRejectsGarbage2882=== PAUSE TestServeRejectsGarbage2883=== CONT TestSign2884=== CONT TestServeRejectsGarbage2885=== CONT TestSignErrors2886=== RUN TestSignErrors/http_error2887=== PAUSE TestSignErrors/http_error2888=== RUN TestSignErrors/invalid_json2889=== PAUSE TestSignErrors/invalid_json2890=== RUN TestSignErrors/no_prefix2891=== PAUSE TestSignErrors/no_prefix2892--- PASS: TestServeRejectsGarbage (0.00s)2893=== CONT TestServe2894=== RUN TestSignErrors/invalid_base642895=== PAUSE TestSignErrors/invalid_base642896=== CONT TestSignErrors/http_error2897--- PASS: TestServe (0.00s)2898=== CONT TestSignErrors/invalid_json2899=== CONT TestSignErrors/invalid_base642900=== CONT TestSignErrors/no_prefix2901--- PASS: TestSign (0.01s)2902--- PASS: TestSignErrors (0.00s)2903 --- PASS: TestSignErrors/invalid_json (0.00s)2904 --- PASS: TestSignErrors/http_error (0.00s)2905 --- PASS: TestSignErrors/invalid_base64 (0.00s)2906 --- PASS: TestSignErrors/no_prefix (0.00s)2907PASS