niks3-go-unit-tests
checks.aarch64-darwin.go-unit-tests
· build #467
· raw
1tribuchet: building on mac022Running client tests...3=== RUN TestDoServerRequestAttachesToken4=== PAUSE TestDoServerRequestAttachesToken5=== RUN TestUploadBuildLog_FileBodyReplayedOnRetry6=== PAUSE TestUploadBuildLog_FileBodyReplayedOnRetry7=== RUN TestRegisterUploadedObjectReusesConnections8=== PAUSE TestRegisterUploadedObjectReusesConnections9=== RUN TestRunGarbageCollection_FinishedOnAnotherReplica10=== PAUSE TestRunGarbageCollection_FinishedOnAnotherReplica11=== RUN TestRunGarbageCollection_NotFoundAfterLocalRun12=== PAUSE TestRunGarbageCollection_NotFoundAfterLocalRun13=== RUN TestCaseHackSuffix14=== PAUSE TestCaseHackSuffix15=== RUN TestFilterOversizedClosures16=== PAUSE TestFilterOversizedClosures17=== RUN TestUploadMultipart_PartsInParallel18=== PAUSE TestUploadMultipart_PartsInParallel19=== RUN TestUploadMultipart_ReturnsAfterDroppedBody20=== PAUSE TestUploadMultipart_ReturnsAfterDroppedBody21=== RUN TestPartSizeForNAR22=== PAUSE TestPartSizeForNAR23=== RUN TestUploadMultipart_SupersededByPeer24=== PAUSE TestUploadMultipart_SupersededByPeer25=== RUN TestDumpPathCaseHackMatchesNix26--- PASS: TestDumpPathCaseHackMatchesNix (0.07s)27=== RUN TestDumpPathCaseHackCollision28--- PASS: TestDumpPathCaseHackCollision (0.00s)29=== RUN TestSupersededNARStillUploadsListing30=== PAUSE TestSupersededNARStillUploadsListing31=== RUN TestDumpPathMatchesNix32=== PAUSE TestDumpPathMatchesNix33=== RUN TestDumpPathSingleFile34=== PAUSE TestDumpPathSingleFile35=== RUN TestDumpPathWriterError36=== PAUSE TestDumpPathWriterError37=== RUN TestEncodeNixBase3238=== PAUSE TestEncodeNixBase3239=== RUN TestEncodeNixBase32WithRealHash40=== PAUSE TestEncodeNixBase32WithRealHash41=== RUN TestConvertHashToNix3242=== PAUSE TestConvertHashToNix3243=== RUN TestGetStorePathHash44=== PAUSE TestGetStorePathHash45=== RUN TestPathInfoHashCompatibility46=== PAUSE TestPathInfoHashCompatibility47=== RUN TestParsePathInfoJSON48=== PAUSE TestParsePathInfoJSON49=== RUN TestParsePathInfoJSONMultiplePaths50=== PAUSE TestParsePathInfoJSONMultiplePaths51=== RUN TestPathInfoCACompatibility52=== PAUSE TestPathInfoCACompatibility53=== RUN TestRateLimiterFeedback54=== PAUSE TestRateLimiterFeedback55=== RUN TestRateLimiterFeedback_400DoesNotCountAsSuccess56=== PAUSE TestRateLimiterFeedback_400DoesNotCountAsSuccess57=== RUN TestRegisterUploadedObject_BoundedAgainstSilentServer58=== PAUSE TestRegisterUploadedObject_BoundedAgainstSilentServer59=== RUN TestRegisterUploadedObject_OutlivesPush60=== PAUSE TestRegisterUploadedObject_OutlivesPush61=== 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 TestStaticToken119=== CONT TestStreamPushReportsSignatures120--- PASS: TestStaticToken (0.00s)121=== CONT TestScriptTokenEmptyCommand122=== CONT TestScriptTokenScriptFails123=== CONT TestScriptTokenBadJSON124=== CONT TestScriptTokenEmptyToken125=== CONT TestFileTokenEmpty126=== CONT TestScriptTokenNoExpiryRerunsEveryCall127=== CONT TestRateLimiterFeedback128=== RUN TestRateLimiterFeedback/429_enables_limiter129=== PAUSE TestRateLimiterFeedback/429_enables_limiter130=== RUN TestRateLimiterFeedback/503_enables_limiter131=== PAUSE TestRateLimiterFeedback/503_enables_limiter132=== RUN TestRateLimiterFeedback/200_does_not_enable_limiter1332026/11/06 08:13:33 ERROR Upload failed error=boom count=1134=== CONT TestSetClientTLSErrors135=== CONT TestPathInfoHashCompatibility136=== RUN TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)137=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)138=== RUN TestPathInfoHashCompatibility/old_string_format_with_colon139=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_colon140=== RUN TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI141=== PAUSE TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI142=== CONT TestSetClientTLSDoesNotMutateDefaultTransport143=== CONT TestSetClientTLS144=== CONT TestStreamPushStopsWhenCanceled145=== CONT TestClientSignaturesByStorePath146=== CONT TestStreamPushReportsSkippedPaths147=== CONT TestScriptTokenCachesUntilRefresh148=== CONT TestFileTokenReadsAndCaches149=== CONT TestStreamPushIsolatesFailures150=== CONT TestStreamPushRequestLine151=== CONT TestStreamPushGivesUpOnDeadServer152=== CONT TestDumpPathMatchesNix153=== CONT TestPathInfoCACompatibility154=== CONT TestParsePathInfoJSONMultiplePaths155=== CONT TestFileTokenMissing156--- PASS: TestScriptTokenEmptyCommand (0.00s)157=== CONT TestParsePathInfoJSON158=== PAUSE TestRateLimiterFeedback/200_does_not_enable_limiter159--- PASS: TestStreamPushReportsSignatures (0.00s)160--- PASS: TestClientSignaturesByStorePath (0.00s)161=== CONT TestGetStorePathHash1622026/11/06 08:13:33 ERROR Upload failed error="bad path" count=3163=== RUN TestPathInfoHashCompatibility/new_structured_format_with_sha512164=== RUN TestRateLimiterFeedback/400_does_not_enable_limiter1652026/11/06 08:13:33 ERROR Upload failed error="connection refused" count=201662026/11/06 08:13:33 ERROR Server seems unavailable, giving up on batch untried=17167--- PASS: TestStreamPushIsolatesFailures (0.00s)168=== CONT TestConvertHashToNix32169=== RUN TestPathInfoCACompatibility/null_ca_field170=== RUN TestConvertHashToNix32/SRI_format_to_Nix32171=== PAUSE TestPathInfoCACompatibility/null_ca_field172=== RUN TestPathInfoCACompatibility/old_string_format_-_text173=== PAUSE TestPathInfoCACompatibility/old_string_format_-_text174=== RUN TestPathInfoCACompatibility/old_string_format_-_fixed_recursive175=== PAUSE TestPathInfoCACompatibility/old_string_format_-_fixed_recursive176=== RUN TestPathInfoCACompatibility/new_structured_format_-_text177=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_text178=== PAUSE TestConvertHashToNix32/SRI_format_to_Nix32179=== CONT TestEncodeNixBase32WithRealHash180=== CONT TestEncodeNixBase32181=== RUN TestPathInfoCACompatibility/new_structured_format_-_nar_method182=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_nar_method183=== CONT TestDumpPathWriterError184=== RUN TestConvertHashToNix32/already_Nix32_format185=== CONT TestShellSplit186=== CONT TestStreamPushBatchesUnderLoad187=== RUN TestStreamPushBatchesUnderLoad/oneAtATime=false188=== PAUSE TestConvertHashToNix32/already_Nix32_format189=== RUN TestConvertHashToNix32/invalid_format190=== PAUSE TestConvertHashToNix32/invalid_format191=== PAUSE TestStreamPushBatchesUnderLoad/oneAtATime=false192=== RUN TestStreamPushBatchesUnderLoad/oneAtATime=true193=== RUN TestEncodeNixBase32/test_string_hash194=== PAUSE TestEncodeNixBase32/test_string_hash195=== RUN TestEncodeNixBase32/empty_input196=== PAUSE TestEncodeNixBase32/empty_input197=== PAUSE TestStreamPushBatchesUnderLoad/oneAtATime=true198=== CONT TestShellSplitErrors199=== CONT TestPartSizeForNAR200=== RUN TestPartSizeForNAR/zero_stays_at_minimum201=== PAUSE TestPartSizeForNAR/zero_stays_at_minimum202=== RUN TestPartSizeForNAR/small_stays_at_minimum203=== PAUSE TestPartSizeForNAR/small_stays_at_minimum204=== RUN TestPartSizeForNAR/80_GiB_fits_at_minimum205=== PAUSE TestPartSizeForNAR/80_GiB_fits_at_minimum206=== RUN TestPartSizeForNAR/115_GiB_needs_larger_parts207=== PAUSE TestPartSizeForNAR/115_GiB_needs_larger_parts208=== RUN TestPartSizeForNAR/1_TiB209=== PAUSE TestPartSizeForNAR/1_TiB210=== RUN TestPartSizeForNAR/5_TiB_S3_max_object211=== PAUSE TestPartSizeForNAR/5_TiB_S3_max_object212=== RUN TestPartSizeForNAR/capped_at_5_GiB213=== PAUSE TestPartSizeForNAR/capped_at_5_GiB214=== CONT TestStreamPushReportsEveryPath215=== CONT TestFilterOversizedClosures216=== RUN TestFilterOversizedClosures/no_limit_keeps_everything217=== PAUSE TestFilterOversizedClosures/no_limit_keeps_everything218=== RUN TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped219=== PAUSE TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped220=== RUN TestFilterOversizedClosures/all_closures_skipped221=== PAUSE TestFilterOversizedClosures/all_closures_skipped222=== CONT TestSupersededNARStillUploadsListing223=== RUN TestSupersededNARStillUploadsListing/small_NAR224=== PAUSE TestSupersededNARStillUploadsListing/small_NAR225=== RUN TestSupersededNARStillUploadsListing/dump_cut_short226=== PAUSE TestSupersededNARStillUploadsListing/dump_cut_short227=== RUN TestSupersededNARStillUploadsListing/listing_upload_fails228=== PAUSE TestSupersededNARStillUploadsListing/listing_upload_fails229=== CONT TestDumpPathSingleFile230=== CONT TestCaseHackSuffix231=== CONT TestUploadMultipart_ReturnsAfterDroppedBody232=== CONT TestRegisterUploadedObjectReusesConnections233=== RUN TestParsePathInfoJSON/Nix_format234=== CONT TestUploadMultipart_PartsInParallel235--- PASS: TestStreamPushGivesUpOnDeadServer (0.00s)236=== CONT TestUploadMultipart_SupersededByPeer2372026/11/06 08:13:33 ERROR Upload failed error=boom count=1238=== RUN TestUploadMultipart_SupersededByPeer/exists239=== PAUSE TestUploadMultipart_SupersededByPeer/exists240=== RUN TestUploadMultipart_SupersededByPeer/missing241=== PAUSE TestUploadMultipart_SupersededByPeer/missing242=== PAUSE TestPathInfoHashCompatibility/new_structured_format_with_sha512243=== CONT TestRetryTimeoutOutlastsMaxRetries244=== CONT TestDoWithRetry_FinalResponseBodyReadable245=== CONT TestResolveStorePath246--- PASS: TestStreamPushReportsSkippedPaths (0.00s)247--- PASS: TestEncodeNixBase32WithRealHash (0.00s)248--- PASS: TestStreamPushStopsWhenCanceled (0.00s)249=== RUN TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths250--- PASS: TestShellSplit (0.00s)251=== CONT TestDoWithRetry_BodyReplayedViaGetBody252--- PASS: TestShellSplitErrors (0.00s)253--- PASS: TestFileTokenReadsAndCaches (0.00s)254--- PASS: TestStreamPushReportsEveryPath (0.00s)255--- PASS: TestFileTokenMissing (0.00s)256=== PAUSE TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths257=== RUN TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths258--- PASS: TestScriptTokenScriptFails (0.01s)259--- PASS: TestUploadMultipart_ReturnsAfterDroppedBody (0.00s)260=== PAUSE TestRateLimiterFeedback/400_does_not_enable_limiter261=== PAUSE TestParsePathInfoJSON/Nix_format262=== RUN TestParsePathInfoJSON/Lix_format2632026/11/06 08:13:33 WARN Request returned retryable status, retrying attempt=1 backoff=1ms status=502 url=http://127.0.0.1:56575264=== RUN TestGetStorePathHash/valid_store_path265=== PAUSE TestGetStorePathHash/valid_store_path266=== CONT TestRegisterUploadedObject_BoundedAgainstSilentServer267--- PASS: TestResolveStorePath (0.00s)268=== CONT TestUploadBuildLog_FileBodyReplayedOnRetry269=== CONT TestRegisterUploadedObject_OutlivesPush270=== PAUSE TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths271=== PAUSE TestParsePathInfoJSON/Lix_format272=== RUN TestParsePathInfoJSON/empty_input273--- PASS: TestFileTokenEmpty (0.01s)274=== PAUSE TestParsePathInfoJSON/empty_input275=== RUN TestParsePathInfoJSON/whitespace_only276=== RUN TestGetStorePathHash/basename_without_hyphen_should_error277=== PAUSE TestParsePathInfoJSON/whitespace_only278=== RUN TestParsePathInfoJSON/invalid_JSON279=== PAUSE TestParsePathInfoJSON/invalid_JSON280=== CONT TestRateLimiterFeedback_400DoesNotCountAsSuccess281=== PAUSE TestGetStorePathHash/basename_without_hyphen_should_error282=== RUN TestGetStorePathHash/hash_with_invalid_characters_should_error283=== PAUSE TestGetStorePathHash/hash_with_invalid_characters_should_error284=== RUN TestGetStorePathHash/hash_with_wrong_length_should_error285=== PAUSE TestGetStorePathHash/hash_with_wrong_length_should_error286=== CONT TestRunGarbageCollection_NotFoundAfterLocalRun287=== CONT TestRunGarbageCollection_FinishedOnAnotherReplica2882026/11/06 08:13:33 WARN Rate limiter enabled after throttle name=server-test rate=5289--- PASS: TestDoServerRequestAttachesToken (0.02s)290=== CONT TestPathInfoCACompatibility/null_ca_field291=== CONT TestPathInfoCACompatibility/new_structured_format_-_nar_method292=== CONT TestPathInfoCACompatibility/new_structured_format_-_text293=== CONT TestPathInfoCACompatibility/old_string_format_-_fixed_recursive294=== CONT TestPathInfoCACompatibility/old_string_format_-_text295--- PASS: TestPathInfoCACompatibility (0.00s)296 --- PASS: TestPathInfoCACompatibility/null_ca_field (0.00s)297 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_nar_method (0.00s)298 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_text (0.00s)299 --- PASS: TestPathInfoCACompatibility/old_string_format_-_fixed_recursive (0.00s)300 --- PASS: TestPathInfoCACompatibility/old_string_format_-_text (0.00s)301=== CONT TestConvertHashToNix32/SRI_format_to_Nix32302=== CONT TestConvertHashToNix32/invalid_format303=== CONT TestConvertHashToNix32/already_Nix32_format304--- PASS: TestConvertHashToNix32 (0.00s)305 --- PASS: TestConvertHashToNix32/SRI_format_to_Nix32 (0.00s)306 --- PASS: TestConvertHashToNix32/invalid_format (0.00s)307 --- PASS: TestConvertHashToNix32/already_Nix32_format (0.00s)308=== CONT TestEncodeNixBase32/test_string_hash309=== CONT TestStreamPushBatchesUnderLoad/oneAtATime=false310=== CONT TestPartSizeForNAR/zero_stays_at_minimum311=== CONT TestEncodeNixBase32/empty_input312--- PASS: TestEncodeNixBase32 (0.00s)313 --- PASS: TestEncodeNixBase32/test_string_hash (0.00s)314 --- PASS: TestEncodeNixBase32/empty_input (0.00s)315=== CONT TestFilterOversizedClosures/no_limit_keeps_everything316=== CONT TestStreamPushBatchesUnderLoad/oneAtATime=true3172026/11/06 08:13:33 WARN Request returned retryable status, retrying attempt=2 backoff=1ms status=502 url=http://127.0.0.1:56575318--- PASS: TestStreamPushBatchesUnderLoad (0.00s)319 --- PASS: TestStreamPushBatchesUnderLoad/oneAtATime=false (0.00s)320 --- PASS: TestStreamPushBatchesUnderLoad/oneAtATime=true (0.00s)321=== CONT TestSupersededNARStillUploadsListing/small_NAR322--- PASS: TestRegisterUploadedObject_OutlivesPush (0.00s)323=== CONT TestPartSizeForNAR/capped_at_5_GiB324=== CONT TestPartSizeForNAR/5_TiB_S3_max_object325=== CONT TestPartSizeForNAR/1_TiB326--- PASS: TestSetClientTLSDoesNotMutateDefaultTransport (0.02s)327=== CONT TestPartSizeForNAR/80_GiB_fits_at_minimum328=== CONT TestPartSizeForNAR/small_stays_at_minimum329=== CONT TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped3302026/11/06 08:13:33 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=2000331=== RUN TestSetClientTLS/rejects_connection_without_client_cert332=== PAUSE TestSetClientTLS/rejects_connection_without_client_cert333=== RUN TestSetClientTLS/succeeds_with_client_cert_and_CA334=== PAUSE TestSetClientTLS/succeeds_with_client_cert_and_CA335=== RUN TestSetClientTLS/preserves_debug_logging_transport336=== PAUSE TestSetClientTLS/preserves_debug_logging_transport337=== CONT TestFilterOversizedClosures/all_closures_skipped3382026/11/06 08:13:33 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=50339--- PASS: TestFilterOversizedClosures (0.00s)340 --- PASS: TestFilterOversizedClosures/no_limit_keeps_everything (0.00s)341 --- PASS: TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped (0.00s)342 --- PASS: TestFilterOversizedClosures/all_closures_skipped (0.00s)343=== CONT TestSupersededNARStillUploadsListing/listing_upload_fails3442026/11/06 08:13:33 WARN Rate limiter enabled after throttle name=s3-test rate=53452026/11/06 08:13:33 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:56597346--- PASS: TestScriptTokenBadJSON (0.03s)347=== CONT TestUploadMultipart_SupersededByPeer/exists3482026/11/06 08:13:33 WARN Rate limiter enabled after throttle name=server-test rate=53492026/11/06 08:13:33 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:565363502026/11/06 08:13:33 INFO Uploading abc-hello (1.0GB)351=== CONT TestSupersededNARStillUploadsListing/dump_cut_short3522026/11/06 08:13:33 WARN Rate limiter backed off name=server-test rate=53532026/11/06 08:13:33 WARN Request returned retryable status, retrying attempt=2 backoff=0s status=503 url=http://127.0.0.1:56536354--- PASS: TestDoWithRetry_BodyReplayedViaGetBody (0.02s)355=== CONT TestUploadMultipart_SupersededByPeer/missing356--- PASS: TestUploadBuildLog_FileBodyReplayedOnRetry (0.01s)3572026/11/06 08:13:33 INFO Garbage collection started3582026/11/06 08:13:33 INFO Garbage collection started3592026/11/06 08:13:33 WARN Request returned retryable status, retrying attempt=1 backoff=1ms status=502 url=http://127.0.0.1:565753602026/11/06 08:13:33 WARN Rate limiter enabled after throttle name=server-test rate=53612026/11/06 08:13:33 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:565813622026/11/06 08:13:33 WARN Rate limiter backed off name=server-test rate=53632026/11/06 08:13:33 INFO Uploading abc-hello (1.0GB)364=== CONT TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)365=== CONT TestRateLimiterFeedback/200_does_not_enable_limiter366--- PASS: TestScriptTokenEmptyToken (0.03s)367--- PASS: TestDoWithRetry_FinalResponseBodyReadable (0.02s)368=== CONT TestRateLimiterFeedback/429_enables_limiter369=== CONT TestPartSizeForNAR/115_GiB_needs_larger_parts370--- PASS: TestPartSizeForNAR (0.00s)371 --- PASS: TestPartSizeForNAR/zero_stays_at_minimum (0.00s)372 --- PASS: TestPartSizeForNAR/capped_at_5_GiB (0.00s)373 --- PASS: TestPartSizeForNAR/5_TiB_S3_max_object (0.00s)374 --- PASS: TestPartSizeForNAR/80_GiB_fits_at_minimum (0.00s)375 --- PASS: TestPartSizeForNAR/small_stays_at_minimum (0.00s)376 --- PASS: TestPartSizeForNAR/1_TiB (0.00s)377 --- PASS: TestPartSizeForNAR/115_GiB_needs_larger_parts (0.00s)378=== CONT TestRateLimiterFeedback/400_does_not_enable_limiter379=== CONT TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI380=== CONT TestPathInfoHashCompatibility/old_string_format_with_colon381=== CONT TestRateLimiterFeedback/503_enables_limiter382--- PASS: TestRunGarbageCollection_NotFoundAfterLocalRun (0.01s)383=== CONT TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths3842026/11/06 08:13:33 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=03852026/11/06 08:13:33 WARN Rate limiter enabled after throttle name=server-test rate=53862026/11/06 08:13:33 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=429 url=http://127.0.0.1:56616387=== CONT TestPathInfoHashCompatibility/new_structured_format_with_sha512388--- PASS: TestPathInfoHashCompatibility (0.01s)389 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) (0.00s)390 --- PASS: TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI (0.00s)391 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_colon (0.00s)392 --- PASS: TestPathInfoHashCompatibility/new_structured_format_with_sha512 (0.00s)393=== CONT TestParsePathInfoJSON/invalid_JSON3942026/11/06 08:13:33 WARN Rate limiter backed off name=server-test rate=5395=== CONT TestParsePathInfoJSON/whitespace_only396=== CONT TestParsePathInfoJSON/Lix_format397=== CONT TestParsePathInfoJSON/Nix_format398=== CONT TestGetStorePathHash/valid_store_path399=== CONT TestParsePathInfoJSON/empty_input400=== CONT TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths401=== CONT TestGetStorePathHash/hash_with_invalid_characters_should_error402=== CONT TestGetStorePathHash/basename_without_hyphen_should_error4032026/11/06 08:13:33 WARN Request returned retryable status, retrying attempt=2 backoff=1ms status=502 url=http://127.0.0.1:565754042026/11/06 08:13:33 WARN Rate limiter enabled after throttle name=server-test rate=54052026/11/06 08:13:33 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:56621406=== CONT TestSetClientTLS/succeeds_with_client_cert_and_CA407=== RUN TestSetClientTLSErrors/missing_cert_file408=== PAUSE TestSetClientTLSErrors/missing_cert_file409=== RUN TestSetClientTLSErrors/missing_key_file410=== PAUSE TestSetClientTLSErrors/missing_key_file411=== RUN TestSetClientTLSErrors/missing_ca_file412=== PAUSE TestSetClientTLSErrors/missing_ca_file413=== RUN TestSetClientTLSErrors/invalid_ca_file414=== PAUSE TestSetClientTLSErrors/invalid_ca_file415=== CONT TestSetClientTLS/preserves_debug_logging_transport416--- PASS: TestParsePathInfoJSONMultiplePaths (0.02s)417 --- PASS: TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths (0.00s)418 --- PASS: TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths (0.00s)419=== CONT TestSetClientTLSErrors/missing_cert_file420=== CONT TestSetClientTLSErrors/invalid_ca_file421=== CONT TestSetClientTLSErrors/missing_ca_file422=== CONT TestSetClientTLSErrors/missing_key_file423--- PASS: TestParsePathInfoJSON (0.02s)424 --- PASS: TestParsePathInfoJSON/invalid_JSON (0.00s)425 --- PASS: TestParsePathInfoJSON/whitespace_only (0.00s)426 --- PASS: TestParsePathInfoJSON/empty_input (0.00s)427 --- PASS: TestParsePathInfoJSON/Lix_format (0.00s)428 --- PASS: TestParsePathInfoJSON/Nix_format (0.00s)429--- PASS: TestSetClientTLSErrors (0.04s)430 --- PASS: TestSetClientTLSErrors/missing_cert_file (0.00s)431 --- PASS: TestSetClientTLSErrors/invalid_ca_file (0.00s)432 --- PASS: TestSetClientTLSErrors/missing_ca_file (0.00s)433 --- PASS: TestSetClientTLSErrors/missing_key_file (0.00s)4342026/11/06 08:13:33 WARN Rate limiter backed off name=server-test rate=54352026/11/06 08:13:33 WARN Request returned retryable status, retrying attempt=3 backoff=1ms status=502 url=http://127.0.0.1:565754362026/11/06 08:13:33 WARN Garbage collection finished on another replica. Its statistics are not available here437--- PASS: TestUploadMultipart_SupersededByPeer (0.00s)438 --- PASS: TestUploadMultipart_SupersededByPeer/exists (0.00s)439 --- PASS: TestUploadMultipart_SupersededByPeer/missing (0.01s)440--- PASS: TestRateLimiterFeedback (0.01s)441 --- PASS: TestRateLimiterFeedback/200_does_not_enable_limiter (0.00s)442 --- PASS: TestRateLimiterFeedback/400_does_not_enable_limiter (0.00s)443 --- PASS: TestRateLimiterFeedback/429_enables_limiter (0.00s)444 --- PASS: TestRateLimiterFeedback/503_enables_limiter (0.01s)445=== CONT TestGetStorePathHash/hash_with_wrong_length_should_error446=== CONT TestSetClientTLS/rejects_connection_without_client_cert447--- PASS: TestGetStorePathHash (0.02s)448 --- PASS: TestGetStorePathHash/valid_store_path (0.00s)449 --- PASS: TestGetStorePathHash/hash_with_invalid_characters_should_error (0.00s)450 --- PASS: TestGetStorePathHash/basename_without_hyphen_should_error (0.00s)451 --- PASS: TestGetStorePathHash/hash_with_wrong_length_should_error (0.00s)452--- PASS: TestRunGarbageCollection_FinishedOnAnotherReplica (0.02s)453--- PASS: TestStreamPushRequestLine (0.04s)4542026/11/06 08:13:33 WARN Request returned retryable status, retrying attempt=4 backoff=1ms status=502 url=http://127.0.0.1:565754552026/11/06 08:13:33 WARN Request returned retryable status, retrying attempt=5 backoff=1ms status=502 url=http://127.0.0.1:565754562026/11/06 08:13:33 WARN Request returned retryable status, retrying attempt=6 backoff=1ms status=502 url=http://127.0.0.1:565754572026/11/06 08:13:33 WARN Request returned retryable status, retrying attempt=7 backoff=1ms status=502 url=http://127.0.0.1:565754582026/11/06 08:13:33 WARN Request returned retryable status, retrying attempt=8 backoff=1ms status=502 url=http://127.0.0.1:565754592026/11/06 08:13:33 WARN Request returned retryable status, retrying attempt=9 backoff=1ms status=502 url=http://127.0.0.1:56575460--- PASS: TestScriptTokenNoExpiryRerunsEveryCall (0.05s)4612026/11/06 08:13:33 WARN Request returned retryable status, retrying attempt=10 backoff=1ms status=502 url=http://127.0.0.1:565754622026/11/06 08:13:33 WARN Request returned retryable status, retrying attempt=11 backoff=1ms status=502 url=http://127.0.0.1:565754632026/11/06 08:13:33 WARN Request returned retryable status, retrying attempt=12 backoff=1ms status=502 url=http://127.0.0.1:565754642026/11/06 08:13:33 WARN Request returned retryable status, retrying attempt=13 backoff=1ms status=502 url=http://127.0.0.1:565754652026/11/06 08:13:33 WARN Request returned retryable status, retrying attempt=14 backoff=1ms status=502 url=http://127.0.0.1:56575466--- PASS: TestRegisterUploadedObjectReusesConnections (0.06s)4672026/11/06 08:13:33 WARN Request returned retryable status, retrying attempt=15 backoff=1ms status=502 url=http://127.0.0.1:565754682026/11/06 08:13:33 WARN Request returned retryable status, retrying attempt=16 backoff=1ms status=502 url=http://127.0.0.1:565754692026/11/06 08:13:33 http: TLS handshake error from 127.0.0.1:56633: remote error: tls: bad certificate4702026/11/06 08:13:33 WARN Request returned retryable status, retrying attempt=17 backoff=1ms status=502 url=http://127.0.0.1:56575471--- PASS: TestSetClientTLS (0.03s)472 --- PASS: TestSetClientTLS/succeeds_with_client_cert_and_CA (0.01s)473 --- PASS: TestSetClientTLS/preserves_debug_logging_transport (0.01s)474 --- PASS: TestSetClientTLS/rejects_connection_without_client_cert (0.02s)475--- PASS: TestRetryTimeoutOutlastsMaxRetries (0.06s)476--- PASS: TestScriptTokenCachesUntilRefresh (0.07s)477--- PASS: TestDumpPathSingleFile (0.07s)478--- PASS: TestCaseHackSuffix (0.09s)479--- PASS: TestDumpPathWriterError (0.09s)4802026/11/06 08:13:33 INFO Uploading abc-hello (1.0GB)4812026/11/06 08:13:33 WARN Request failed, retrying attempt=1 backoff=100ms error="Put \"http://127.0.0.1:56610/part/2\": uploading part 1: server returned 404: no such upload\n" url=http://127.0.0.1:56610/part/24822026/11/06 08:13:33 WARN Request failed, retrying attempt=1 backoff=100ms error="Put \"http://127.0.0.1:56610/part/3\": uploading part 1: server returned 404: no such upload\n" url=http://127.0.0.1:56610/part/34832026/11/06 08:13:33 ERROR Failed to close zstd encoder error="io: read/write on closed pipe"4842026/11/06 08:13:33 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:56594/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:56594/api/uploads/complete4852026/11/06 08:13:33 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"4862026/11/06 08:13:33 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:56594/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:56594/api/uploads/complete4872026/11/06 08:13:33 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"4882026/11/06 08:13:33 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:56594/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:56594/api/uploads/complete4892026/11/06 08:13:33 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"490--- PASS: TestRegisterUploadedObject_BoundedAgainstSilentServer (0.10s)491--- PASS: TestDumpPathMatchesNix (0.15s)492--- PASS: TestSupersededNARStillUploadsListing (0.00s)493 --- PASS: TestSupersededNARStillUploadsListing/listing_upload_fails (0.01s)494 --- PASS: TestSupersededNARStillUploadsListing/small_NAR (0.02s)495 --- PASS: TestSupersededNARStillUploadsListing/dump_cut_short (0.59s)496--- PASS: TestUploadMultipart_PartsInParallel (0.64s)497--- PASS: TestRateLimiterFeedback_400DoesNotCountAsSuccess (1.00s)498PASS499Running server tests...500The files belonging to this database system will be owned by user "_tribuchetbld1".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/1/scratch/8499ef2246bbc144/build/postgres3295967028/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/1/scratch/8499ef2246bbc144/build/postgres3295967028/data -l logfile start526527/private/var/tb/1/scratch/8499ef2246bbc144/build/postgres3295967028:5432 - no response5282026-11-06 08:13:35.456 UTC [97956] LOG: starting PostgreSQL 18.6 on aarch64-apple-darwin25.6.0, compiled by clang version 21.1.8, 64-bit5292026-11-06 08:13:35.456 UTC [97956] LOG: listening on Unix socket "/private/var/tb/1/scratch/8499ef2246bbc144/build/postgres3295967028/.s.PGSQL.5432"5302026-11-06 08:13:35.459 UTC [97963] LOG: database system was shut down at 2026-11-06 08:13:35 UTC5312026-11-06 08:13:35.460 UTC [97956] LOG: database system is ready to accept connections532/private/var/tb/1/scratch/8499ef2246bbc144/build/postgres3295967028:5432 - accepting connections533{"timestamp":"2026-11-06T08:13:35.808165Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"68260e87-988e-41a5-86bf-ff0f6ecaca43","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":14,"result":"server_error","target":"rustfs::server::http","filename":"rustfs/src/server/layer.rs","line_number":502,"threadName":"rustfs-worker","threadId":"ThreadId(4)"}534{"timestamp":"2026-11-06T08:13:35.926288Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"abbaf7e0-a4b7-4670-9d23-660a0a33c61d","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(7)"}535{"timestamp":"2026-11-06T08:13:36.029501Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"78f2591d-c1f2-43f6-9e4d-de75c19c725e","trace_id":"unknown","span_id":"unknown","peer_addr":"127.0.0.1","method":"GET","uri":"/health/ready","status_code":503,"suppressed_errors":0,"duration_ms":0,"result":"server_error","target":"rustfs::server::http","filename":"rustfs/src/server/layer.rs","line_number":502,"threadName":"rustfs-worker","threadId":"ThreadId(2)"}536=== RUN TestService_AuthMiddleware537=== PAUSE TestService_AuthMiddleware538=== RUN TestService_AuthMiddleware_MTLSProxyHeader539=== PAUSE TestService_AuthMiddleware_MTLSProxyHeader540=== RUN TestService_AuthMiddleware_MTLSBoundSubjects541=== PAUSE TestService_AuthMiddleware_MTLSBoundSubjects542=== RUN TestService_ReadAuthMiddleware543=== PAUSE TestService_ReadAuthMiddleware544=== RUN TestService_AuthMiddleware_OIDC545=== PAUSE TestService_AuthMiddleware_OIDC546=== RUN TestService_RequireScope_OIDC547=== PAUSE TestService_RequireScope_OIDC548=== RUN TestService_ReadScope_PublicByDefault549=== PAUSE TestService_ReadScope_PublicByDefault550=== RUN TestCacheConfigHandler551=== PAUSE TestCacheConfigHandler552=== RUN TestCacheStatsHandler553=== PAUSE TestCacheStatsHandler554=== RUN TestClientCADerivations555=== PAUSE TestClientCADerivations556=== RUN TestClientErrorHandling557=== PAUSE TestClientErrorHandling558=== RUN TestClientIntegration559=== PAUSE TestClientIntegration560=== RUN TestClientMultipleUploads561=== PAUSE TestClientMultipleUploads562=== RUN TestClientWithDependencies563=== PAUSE TestClientWithDependencies564=== RUN TestClientSharedPathCommittedMidPush565=== PAUSE TestClientSharedPathCommittedMidPush566=== RUN TestPinProtectsFromGC567=== PAUSE TestPinProtectsFromGC568=== RUN TestClientPushesUseOnePush569=== PAUSE TestClientPushesUseOnePush570=== RUN TestClientFallsBackToClosures571=== PAUSE TestClientFallsBackToClosures572=== RUN TestDeleteClosuresRacingPins573=== PAUSE TestDeleteClosuresRacingPins574=== RUN TestConcurrentCommitsSharingObjectsDoNotDeadlock575=== PAUSE TestConcurrentCommitsSharingObjectsDoNotDeadlock576=== RUN TestResolveDBConnectionString577=== PAUSE TestResolveDBConnectionString578=== RUN TestConnectWaitsForAPeerMigration579=== PAUSE TestConnectWaitsForAPeerMigration580=== RUN TestLeadElectsOneAndHandsOver581=== PAUSE TestLeadElectsOneAndHandsOver582=== RUN TestLeadIncumbentWinsAfterRestart5832026/11/06 08:13:36 INFO lead: acquired remote=192.0.2.1:12345842026/11/06 08:13:37 INFO lead: released remote=192.0.2.1:12345852026/11/06 08:13:37 INFO lead: acquired remote=192.0.2.1:12345862026/11/06 08:13:38 INFO lead: released remote=192.0.2.1:1234587--- PASS: TestLeadIncumbentWinsAfterRestart (2.09s)588=== RUN TestLeadIncumbentAnnouncesAtOnce589=== PAUSE TestLeadIncumbentAnnouncesAtOnce590=== RUN TestLeadEndsOnShutdown591=== PAUSE TestLeadEndsOnShutdown592=== RUN TestLeadEndsWhenItsConnectionHangs5932026/11/06 08:13:38 INFO lead: acquired remote=192.0.2.1:12345942026-11-06 08:13:39.782 UTC [97998] FATAL: terminating connection due to administrator command5952026/11/06 08:13:39 INFO lead: acquired remote=192.0.2.1:12345962026/11/06 08:13:40 WARN lead: lock connection lost error="timeout: context deadline exceeded"5972026/11/06 08:13:40 INFO lead: released remote=192.0.2.1:12345982026/11/06 08:13:41 INFO lead: released remote=192.0.2.1:1234599--- PASS: TestLeadEndsWhenItsConnectionHangs (2.95s)600=== RUN TestGCAdvisoryLockBlocksConcurrentRun601=== PAUSE TestGCAdvisoryLockBlocksConcurrentRun602=== RUN TestGCBugBareHashReferences603=== PAUSE TestGCBugBareHashReferences604=== RUN TestGCMetrics605=== PAUSE TestGCMetrics606=== RUN TestPushDedupSurvivesConcurrentGC607=== PAUSE TestPushDedupSurvivesConcurrentGC608=== RUN TestDeduplicatedObjectsRecordedAsPending609=== PAUSE TestDeduplicatedObjectsRecordedAsPending610=== RUN TestGCSweepSkipsPendingObjects611=== PAUSE TestGCSweepSkipsPendingObjects612=== RUN TestTombstonedObjectOfferedWithoutWaiting613=== PAUSE TestTombstonedObjectOfferedWithoutWaiting614=== RUN TestGCSweepDeliversEachKeyOnce615=== PAUSE TestGCSweepDeliversEachKeyOnce616=== RUN TestCreatePendingClosureVerifyS3FailureReleasesConnection617=== PAUSE TestCreatePendingClosureVerifyS3FailureReleasesConnection618=== RUN TestForceGCDuringPushOffersSweptObject619=== PAUSE TestForceGCDuringPushOffersSweptObject620=== RUN TestFailedS3DeleteKeepsTombstone621=== PAUSE TestFailedS3DeleteKeepsTombstone622=== RUN TestSweepSkipsRowsLockedByPush623=== PAUSE TestSweepSkipsRowsLockedByPush624=== RUN TestRegisterCompletedObjectNeedsPendingRow625=== PAUSE TestRegisterCompletedObjectNeedsPendingRow626=== RUN TestGetExistingObjectsLocksRows627=== PAUSE TestGetExistingObjectsLocksRows628=== RUN TestSweepRechecksPendingAfterLocking629=== PAUSE TestSweepRechecksPendingAfterLocking630=== RUN TestPushWaitsForSweepHoldingRow631=== PAUSE TestPushWaitsForSweepHoldingRow632=== RUN TestCommitRacingPendingCleanupKeepsObjects633=== PAUSE TestCommitRacingPendingCleanupKeepsObjects634=== RUN TestGCEndsOnShutdown635=== PAUSE TestGCEndsOnShutdown636=== RUN TestGCTaskStore_StartNew637=== PAUSE TestGCTaskStore_StartNew638=== RUN TestGCTaskStore_DeduplicateSameParams639=== PAUSE TestGCTaskStore_DeduplicateSameParams640=== RUN TestGCTaskStore_ConflictDifferentParams641=== PAUSE TestGCTaskStore_ConflictDifferentParams642=== RUN TestGCTaskStore_GetEmpty643=== PAUSE TestGCTaskStore_GetEmpty644=== RUN TestGCTaskStore_GetReturnsLatest645=== PAUSE TestGCTaskStore_GetReturnsLatest646=== RUN TestGCTaskStore_CompletedAllowsNewTask647=== PAUSE TestGCTaskStore_CompletedAllowsNewTask648=== RUN TestGCTaskStore_PhaseUpdates649=== PAUSE TestGCTaskStore_PhaseUpdates650=== RUN TestGCTaskStore_Fail651=== PAUSE TestGCTaskStore_Fail652=== RUN TestGracefulShutdownDrainsInflight653=== PAUSE TestGracefulShutdownDrainsInflight654=== RUN TestService_healthCheckHandler655=== PAUSE TestService_healthCheckHandler656=== RUN TestService_readinessHandler657=== PAUSE TestService_readinessHandler658=== RUN TestGenerateLandingPage659=== PAUSE TestGenerateLandingPage660=== RUN TestCacheConfigHandlerMaxNarSize661=== PAUSE TestCacheConfigHandlerMaxNarSize662=== RUN TestCreatePendingClosureRejectsOversizedNAR663=== PAUSE TestCreatePendingClosureRejectsOversizedNAR664=== RUN TestNARDeduplicationMetadataUploadBug665=== PAUSE TestNARDeduplicationMetadataUploadBug666=== RUN TestMetricsInventory667=== PAUSE TestMetricsInventory668=== RUN TestMetricsCommit669=== PAUSE TestMetricsCommit670=== RUN TestService_NativeMTLS671=== PAUSE TestService_NativeMTLS672=== RUN TestServerTLSConfig673=== PAUSE TestServerTLSConfig674=== RUN TestMultipartCleanup675=== PAUSE TestMultipartCleanup676=== RUN TestMultipartUploadAbortedWhenCancelledBeforeRecorded677=== PAUSE TestMultipartUploadAbortedWhenCancelledBeforeRecorded678=== RUN TestPendingCleanupUsesOneCutoff679=== PAUSE TestPendingCleanupUsesOneCutoff680=== RUN TestObjectStatsTrigger681=== PAUSE TestObjectStatsTrigger682=== RUN TestObjectStatsUpdatedOncePerCommit683=== PAUSE TestObjectStatsUpdatedOncePerCommit684=== RUN TestOrphanedObjectsGC685=== PAUSE TestOrphanedObjectsGC686=== RUN TestOrphanedObjectsGCStressTest687=== PAUSE TestOrphanedObjectsGCStressTest688=== RUN TestCreatePin_ReservedPins689=== PAUSE TestCreatePin_ReservedPins690=== RUN TestPresentReportsOnlyClosureRoots691=== PAUSE TestPresentReportsOnlyClosureRoots692=== RUN TestPresentRefreshesOnlyStaleClosures693=== PAUSE TestPresentRefreshesOnlyStaleClosures694=== RUN TestPresentNotReportedWhileGCDeletesClosure695=== PAUSE TestPresentNotReportedWhileGCDeletesClosure696=== RUN TestParseSingleRange697=== PAUSE TestParseSingleRange698=== RUN TestProxyHeadersOnlyTrustedOnSocket6992026/11/06 08:13:41 INFO Starting HTTP server address=127.0.0.1:566657002026/11/06 08:13:41 INFO Starting HTTP server address=proxy.sock7012026/11/06 08:13:41 WARN mTLS auth: subject not in bound subjects subject="CN=someone"7022026/11/06 08:13:41 INFO Shutdown signal received, draining in-flight requests timeout=10s703--- PASS: TestProxyHeadersOnlyTrustedOnSocket (0.16s)704=== RUN TestIsValidCachePath705=== PAUSE TestIsValidCachePath706=== RUN TestReadProxyNarinfo707=== PAUSE TestReadProxyNarinfo708=== RUN TestReadProxyNarinfoAlreadyDecompressed709=== PAUSE TestReadProxyNarinfoAlreadyDecompressed710=== RUN TestReadProxyContentNegotiation711=== PAUSE TestReadProxyContentNegotiation712=== RUN TestReadProxyNarStreaming713=== PAUSE TestReadProxyNarStreaming714=== RUN TestReadProxy404715=== PAUSE TestReadProxy404716=== RUN TestReadProxyInvalidPath717=== PAUSE TestReadProxyInvalidPath718=== RUN TestReadProxyHead719=== PAUSE TestReadProxyHead720=== RUN TestReadProxyOutlastsServerWriteTimeout721=== PAUSE TestReadProxyOutlastsServerWriteTimeout722=== RUN TestReadProxyConditionalGet723=== PAUSE TestReadProxyConditionalGet724=== RUN TestReadProxyRootRedirectsToIndexHTML725=== PAUSE TestReadProxyRootRedirectsToIndexHTML726=== RUN TestReadProxyDisabled727=== PAUSE TestReadProxyDisabled728=== RUN TestReadRedirectNar729=== PAUSE TestReadRedirectNar730=== RUN TestReadRedirectKeepsNarinfoProxied731=== PAUSE TestReadRedirectKeepsNarinfoProxied732=== RUN TestReadProxyRangeRequest733=== PAUSE TestReadProxyRangeRequest734=== RUN TestReadRedirectUsesPublicS3URL735=== PAUSE TestReadRedirectUsesPublicS3URL736=== RUN TestPush_OverlappingRootsStoreOneRowPerKey737=== PAUSE TestPush_OverlappingRootsStoreOneRowPerKey738=== RUN TestPush_CompleteCommitsEveryRoot739=== PAUSE TestPush_CompleteCommitsEveryRoot740=== RUN TestPush_RepeatedRootCommitsOnce741=== PAUSE TestPush_RepeatedRootCommitsOnce742=== RUN TestPush_CompleteWaitsForCleanupOfThePush743=== PAUSE TestPush_CompleteWaitsForCleanupOfThePush744=== RUN TestPush_RootsAreLockedInByteOrder745=== PAUSE TestPush_RootsAreLockedInByteOrder746=== RUN TestPush_SkippedKeySurvivesGCBeforeCommit747=== PAUSE TestPush_SkippedKeySurvivesGCBeforeCommit748=== RUN TestPush_RejectsBadRequests749=== PAUSE TestPush_RejectsBadRequests750=== RUN TestPush_SignsNarinfosOfItsPendingObjects751=== PAUSE TestPush_SignsNarinfosOfItsPendingObjects752=== RUN TestRedundantMultipartUpload753=== PAUSE TestRedundantMultipartUpload754=== RUN TestCompleteMultipartUpload_ErrorButObjectExists755=== PAUSE TestCompleteMultipartUpload_ErrorButObjectExists756=== RUN TestCompletedNarNotReofferedAcrossClosures757=== PAUSE TestCompletedNarNotReofferedAcrossClosures758=== RUN TestPresignedUploadRegisteredBeforeCommit759=== PAUSE TestPresignedUploadRegisteredBeforeCommit760=== RUN TestService_Rustfstest761=== PAUSE TestService_Rustfstest762=== RUN TestParseSize763=== PAUSE TestParseSize764=== RUN TestSkippedUploadsHandler765=== PAUSE TestSkippedUploadsHandler766=== RUN TestSystemdListenerNotActivated767--- PASS: TestSystemdListenerNotActivated (0.00s)768=== RUN TestWatchdogBeatsWhenHealthy769--- PASS: TestWatchdogBeatsWhenHealthy (0.03s)770=== RUN TestWatchdogSkipsWhenUnhealthy7712026/11/06 08:13:41 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7722026/11/06 08:13:41 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7732026/11/06 08:13:41 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7742026/11/06 08:13:41 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7752026/11/06 08:13:41 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7762026/11/06 08:13:41 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7772026/11/06 08:13:41 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7782026/11/06 08:13:41 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7792026/11/06 08:13:41 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7802026/11/06 08:13:41 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"781--- PASS: TestWatchdogSkipsWhenUnhealthy (0.21s)782=== RUN TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle783=== PAUSE TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle784=== RUN TestProxyWriteTimeout785=== PAUSE TestProxyWriteTimeout786=== RUN TestPendingClosureWriteTimeout787=== PAUSE TestPendingClosureWriteTimeout788=== RUN TestIsValidUploadKey789=== PAUSE TestIsValidUploadKey790=== RUN TestUploadHandlersRejectInvalidKeys791=== PAUSE TestUploadHandlersRejectInvalidKeys792=== RUN TestUploadHandlersRejectOversizedBody793=== PAUSE TestUploadHandlersRejectOversizedBody794=== RUN TestService_cleanupPendingClosuresHandler795=== PAUSE TestService_cleanupPendingClosuresHandler796=== RUN TestService_createPendingClosureHandler797=== PAUSE TestService_createPendingClosureHandler798=== RUN TestService_verifyS3Integrity799=== PAUSE TestService_verifyS3Integrity800=== RUN TestService_verifyS3ReuploadsStaleNarinfo801=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo802=== RUN TestCompleteMultipartUnregistered803=== PAUSE TestCompleteMultipartUnregistered804=== RUN TestCreatePendingClosure_SmallNARUsesSimplePUT805=== PAUSE TestCreatePendingClosure_SmallNARUsesSimplePUT806=== CONT TestRedundantMultipartUpload807=== CONT TestCompleteMultipartUnregistered808=== CONT TestPushWaitsForSweepHoldingRow809=== CONT TestCommitRacingPendingCleanupKeepsObjects810=== CONT TestReadRedirectUsesPublicS3URL811=== CONT TestMultipartCleanup812=== CONT TestPush_RejectsBadRequests813=== CONT TestPush_SkippedKeySurvivesGCBeforeCommit814=== CONT TestPush_RootsAreLockedInByteOrder815=== CONT TestPush_CompleteWaitsForCleanupOfThePush816=== CONT TestPush_RepeatedRootCommitsOnce817=== CONT TestPush_CompleteCommitsEveryRoot818=== CONT TestIsValidUploadKey819=== RUN TestIsValidUploadKey/narinfo820=== CONT TestCreatePendingClosure_SmallNARUsesSimplePUT821=== CONT TestPush_OverlappingRootsStoreOneRowPerKey822=== CONT TestReadProxyRangeRequest823=== CONT TestReadRedirectKeepsNarinfoProxied824=== CONT TestReadRedirectNar825=== CONT TestReadProxyDisabled826=== CONT TestReadProxyRootRedirectsToIndexHTML827=== CONT TestReadProxyConditionalGet828=== CONT TestReadProxyOutlastsServerWriteTimeout829=== CONT TestPush_SignsNarinfosOfItsPendingObjects830=== CONT TestService_AuthMiddleware831=== PAUSE TestIsValidUploadKey/narinfo832=== RUN TestIsValidUploadKey/nar_zst833=== PAUSE TestIsValidUploadKey/nar_zst834=== RUN TestIsValidUploadKey/nar_xz835=== PAUSE TestIsValidUploadKey/nar_xz836=== RUN TestIsValidUploadKey/nar_plain837=== PAUSE TestIsValidUploadKey/nar_plain838=== RUN TestIsValidUploadKey/listing839=== PAUSE TestIsValidUploadKey/listing840=== RUN TestIsValidUploadKey/build_log841=== PAUSE TestIsValidUploadKey/build_log842=== RUN TestIsValidUploadKey/build_log_home-manager_file843=== PAUSE TestIsValidUploadKey/build_log_home-manager_file844=== RUN TestIsValidUploadKey/build_log_plus_in_name845=== PAUSE TestIsValidUploadKey/build_log_plus_in_name846=== RUN TestIsValidUploadKey/build_log_question_mark847=== PAUSE TestIsValidUploadKey/build_log_question_mark848=== RUN TestIsValidUploadKey/build_log_equals849=== PAUSE TestIsValidUploadKey/build_log_equals850=== RUN TestIsValidUploadKey/realisation851=== PAUSE TestIsValidUploadKey/realisation852=== RUN TestIsValidUploadKey/realisation_plus_in_output853=== PAUSE TestIsValidUploadKey/realisation_plus_in_output854=== RUN TestIsValidUploadKey/nix-cache-info855=== PAUSE TestIsValidUploadKey/nix-cache-info856=== RUN TestIsValidUploadKey/index.html857=== PAUSE TestIsValidUploadKey/index.html858=== RUN TestIsValidUploadKey/narinfo_key,_nar_type859=== PAUSE TestIsValidUploadKey/narinfo_key,_nar_type860=== RUN TestIsValidUploadKey/nar_key,_narinfo_type861=== PAUSE TestIsValidUploadKey/nar_key,_narinfo_type862=== RUN TestIsValidUploadKey/listing_key,_narinfo_type863=== PAUSE TestIsValidUploadKey/listing_key,_narinfo_type864=== RUN TestIsValidUploadKey/traversal865=== PAUSE TestIsValidUploadKey/traversal866=== RUN TestIsValidUploadKey/traversal_nar867=== PAUSE TestIsValidUploadKey/traversal_nar868=== RUN TestIsValidUploadKey/absolute869=== PAUSE TestIsValidUploadKey/absolute870=== RUN TestIsValidUploadKey/empty_key871=== PAUSE TestIsValidUploadKey/empty_key872=== RUN TestIsValidUploadKey/unknown_type873=== PAUSE TestIsValidUploadKey/unknown_type874=== CONT TestReadProxyHead8752026/11/06 08:13:42 INFO Received uploads request method=POST path=/api/pending_closures876--- PASS: TestPushWaitsForSweepHoldingRow (1.33s)877=== CONT TestReadProxyInvalidPath8782026/11/06 08:13:43 INFO Received complete multipart upload request method=POST path=/api/multipart/complete8792026/11/06 08:13:43 ERROR Failed to get multipart upload error="no rows in result set" upload_id=does-not-exist object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst880--- PASS: TestCompleteMultipartUnregistered (1.70s)881=== CONT TestReadProxy404882--- PASS: TestReadProxyRangeRequest (2.03s)883=== CONT TestReadProxyNarStreaming8842026/11/06 08:13:43 INFO Received uploads request method=POST path=/api/pending_closures8852026/11/06 08:13:43 INFO Received uploads request method=POST path=/api/pending_closures8862026/11/06 08:13:43 INFO Aborted multipart uploads count=0 kept=08872026/11/06 08:13:44 WARN Force mode enabled - objects will be deleted immediately without grace period8882026/11/06 08:13:44 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=08892026/11/06 08:13:44 INFO Vacuumed table table=pending_closures8902026/11/06 08:13:44 INFO Vacuumed table table=pending_objects8912026/11/06 08:13:44 INFO Vacuumed table table=multipart_uploads8922026/11/06 08:13:44 INFO Vacuumed table table=closures8932026/11/06 08:13:44 INFO Vacuumed table table=objects894--- PASS: TestCommitRacingPendingCleanupKeepsObjects (2.48s)895=== CONT TestReadProxyContentNegotiation8962026/11/06 08:13:44 INFO Received uploads request method=POST path=/api/pending_closures8972026/11/06 08:13:44 INFO Received cleanup request method=DELETE path=/api/pending_closures8982026/11/06 08:13:44 WARN Failed to abort upload, keeping its closure key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst error="Get \"http://127.0.0.1:1/bucket9/?location=\": dial tcp 127.0.0.1:1: connect: connection refused" code=""8992026/11/06 08:13:44 INFO Aborted multipart uploads count=0 kept=19002026/11/06 08:13:44 INFO Received cleanup request method=DELETE path=/api/pending_closures9012026/11/06 08:13:44 INFO Aborted multipart uploads count=1 kept=0902--- PASS: TestMultipartCleanup (2.70s)903=== CONT TestReadProxyNarinfoAlreadyDecompressed904--- PASS: TestReadRedirectUsesPublicS3URL (2.77s)905=== CONT TestReadProxyNarinfo9062026/11/06 08:13:44 INFO Received uploads request method=POST path=/api/pending_closures907--- PASS: TestCreatePendingClosure_SmallNARUsesSimplePUT (3.02s)908=== CONT TestIsValidCachePath909=== RUN TestIsValidCachePath/narinfo910=== PAUSE TestIsValidCachePath/narinfo911=== RUN TestIsValidCachePath/narinfo_all_nix_base32_chars912=== PAUSE TestIsValidCachePath/narinfo_all_nix_base32_chars913=== RUN TestIsValidCachePath/nar_zst914=== PAUSE TestIsValidCachePath/nar_zst915=== RUN TestIsValidCachePath/nar_xz916=== PAUSE TestIsValidCachePath/nar_xz917=== RUN TestIsValidCachePath/nar_bz2918=== PAUSE TestIsValidCachePath/nar_bz2919=== RUN TestIsValidCachePath/nar_uncompressed920=== PAUSE TestIsValidCachePath/nar_uncompressed921=== RUN TestIsValidCachePath/ls922=== PAUSE TestIsValidCachePath/ls923=== RUN TestIsValidCachePath/log924=== PAUSE TestIsValidCachePath/log925=== RUN TestIsValidCachePath/realisation926=== PAUSE TestIsValidCachePath/realisation927=== RUN TestIsValidCachePath/nix-cache-info928=== PAUSE TestIsValidCachePath/nix-cache-info929=== RUN TestIsValidCachePath/index.html930=== PAUSE TestIsValidCachePath/index.html931=== RUN TestIsValidCachePath/traversal_parent932=== PAUSE TestIsValidCachePath/traversal_parent933=== RUN TestIsValidCachePath/traversal_in_middle934=== PAUSE TestIsValidCachePath/traversal_in_middle935=== RUN TestIsValidCachePath/invalid_char_e936=== PAUSE TestIsValidCachePath/invalid_char_e937=== RUN TestIsValidCachePath/invalid_char_u938=== PAUSE TestIsValidCachePath/invalid_char_u939=== RUN TestIsValidCachePath/random_path940=== PAUSE TestIsValidCachePath/random_path941=== RUN TestIsValidCachePath/empty942=== PAUSE TestIsValidCachePath/empty943=== RUN TestIsValidCachePath/leading_slash944=== PAUSE TestIsValidCachePath/leading_slash945=== RUN TestIsValidCachePath/wrong_extension946=== PAUSE TestIsValidCachePath/wrong_extension947=== RUN TestIsValidCachePath/short_hash948=== PAUSE TestIsValidCachePath/short_hash949=== CONT TestParseSingleRange950=== RUN TestParseSingleRange/none951=== PAUSE TestParseSingleRange/none952=== RUN TestParseSingleRange/unknown_unit953=== PAUSE TestParseSingleRange/unknown_unit954=== RUN TestParseSingleRange/multi-range_ignored955=== PAUSE TestParseSingleRange/multi-range_ignored956=== RUN TestParseSingleRange/malformed_no_dash957=== PAUSE TestParseSingleRange/malformed_no_dash958=== RUN TestParseSingleRange/malformed_both_empty959=== PAUSE TestParseSingleRange/malformed_both_empty960=== RUN TestParseSingleRange/malformed_end_before_start961=== PAUSE TestParseSingleRange/malformed_end_before_start962=== RUN TestParseSingleRange/closed963=== PAUSE TestParseSingleRange/closed964=== RUN TestParseSingleRange/open-ended965=== PAUSE TestParseSingleRange/open-ended966=== RUN TestParseSingleRange/end_clamped_to_size967=== PAUSE TestParseSingleRange/end_clamped_to_size968=== RUN TestParseSingleRange/suffix969=== PAUSE TestParseSingleRange/suffix970=== RUN TestParseSingleRange/suffix_exceeds_size971=== PAUSE TestParseSingleRange/suffix_exceeds_size972=== RUN TestParseSingleRange/single_byte973=== PAUSE TestParseSingleRange/single_byte974=== RUN TestParseSingleRange/start_past_EOF975=== PAUSE TestParseSingleRange/start_past_EOF976=== RUN TestParseSingleRange/start_far_past_EOF977=== PAUSE TestParseSingleRange/start_far_past_EOF978=== CONT TestPresentNotReportedWhileGCDeletesClosure979=== RUN TestPresentNotReportedWhileGCDeletesClosure/stale980=== PAUSE TestPresentNotReportedWhileGCDeletesClosure/stale981=== RUN TestPresentNotReportedWhileGCDeletesClosure/fresh982=== PAUSE TestPresentNotReportedWhileGCDeletesClosure/fresh983=== CONT TestPresentRefreshesOnlyStaleClosures9842026/11/06 08:13:44 INFO Received push request method=POST path=/api/pushes9852026/11/06 08:13:44 INFO Received push request method=POST path=/api/pushes9862026/11/06 08:13:45 INFO Received complete push request method=POST path=/api/pushes/1/complete9872026/11/06 08:13:45 INFO Completed push id=1 objects=6 duration=27.314ms988--- PASS: TestPush_CompleteCommitsEveryRoot (3.51s)989=== CONT TestPresentReportsOnlyClosureRoots9902026-11-06 08:13:45.139 UTC [98098] ERROR: Push does not exist: id=19912026-11-06 08:13:45.139 UTC [98098] CONTEXT: PL/pgSQL function commit_push(bigint) line 11 at RAISE9922026-11-06 08:13:45.139 UTC [98098] STATEMENT: SELECT commit_push($1)993--- PASS: TestPush_CompleteWaitsForCleanupOfThePush (3.55s)994=== CONT TestCreatePin_ReservedPins9952026/11/06 08:13:45 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9962026/11/06 08:13:45 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:56702/oidc9972026/11/06 08:13:45 INFO Received push request method=POST path=/api/pushes9982026/11/06 08:13:45 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=NDY2MGFiYzYtMjNiZC00YTcwLTkxZWMtYTE5MDZmMGY4MmUzLmQ0YmYzNWVkLTUwNGUtNDUyMi1iNzhhLWQ4OThiYjZkNzdmOXgxNzkzOTUyODIzNzE2ODA5MDAw parts=129992026/11/06 08:13:45 INFO Received uploads request method=POST path=/api/pending_closures10002026/11/06 08:13:45 INFO Received uploads request method=POST path=/api/pending_closures1001--- PASS: TestPush_OverlappingRootsStoreOneRowPerKey (3.71s)1002=== CONT TestOrphanedObjectsGCStressTest1003--- PASS: TestReadProxyDisabled (3.88s)1004=== CONT TestOrphanedObjectsGC10052026/11/06 08:13:45 INFO Received push request method=POST path=/api/pushes10062026/11/06 08:13:45 INFO Received complete push request method=POST path=/api/pushes/1/complete10072026/11/06 08:13:45 INFO Completed push id=1 objects=4 duration=22.120875ms10082026/11/06 08:13:45 INFO Received push request method=POST path=/api/pushes10092026/11/06 08:13:45 INFO Aborted multipart uploads count=0 kept=010102026/11/06 08:13:45 WARN Force mode enabled - objects will be deleted immediately without grace period10112026/11/06 08:13:45 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=1 objects-marked-for-deletion=2 objects-deleted-after-grace-period=2 objects-failed-to-delete=010122026/11/06 08:13:45 INFO Vacuumed table table=pending_closures10132026/11/06 08:13:45 INFO Vacuumed table table=pending_objects10142026/11/06 08:13:46 INFO Vacuumed table table=multipart_uploads10152026/11/06 08:13:46 INFO Vacuumed table table=closures1016--- PASS: TestReadProxyHead (4.45s)1017=== CONT TestObjectStatsUpdatedOncePerCommit10182026/11/06 08:13:46 INFO Vacuumed table table=objects10192026/11/06 08:13:46 INFO Received complete push request method=POST path=/api/pushes/2/complete10202026/11/06 08:13:46 INFO Completed push id=2 objects=4 duration=9.071875ms1021--- PASS: TestPush_SkippedKeySurvivesGCBeforeCommit (4.49s)1022=== CONT TestObjectStatsTrigger10232026/11/06 08:13:46 WARN Authentication failed token_preview=wrongtoken token_length=10 reason="static API token mismatch"1024--- PASS: TestService_AuthMiddleware (4.66s)1025=== CONT TestPendingCleanupUsesOneCutoff1026=== RUN TestPush_RejectsBadRequests/root_not_in_objects1027=== PAUSE TestPush_RejectsBadRequests/root_not_in_objects1028=== RUN TestPush_RejectsBadRequests/no_roots1029=== PAUSE TestPush_RejectsBadRequests/no_roots1030=== RUN TestPush_RejectsBadRequests/no_objects1031=== PAUSE TestPush_RejectsBadRequests/no_objects1032=== RUN TestPush_RejectsBadRequests/bad_root1033=== PAUSE TestPush_RejectsBadRequests/bad_root1034=== CONT TestMultipartUploadAbortedWhenCancelledBeforeRecorded10352026/11/06 08:13:46 INFO Received complete multipart upload request method=POST path=/api/multipart/complete10362026/11/06 08:13:46 INFO Received push request method=POST path=/api/pushes10372026/11/06 08:13:46 WARN Failed to abort redundant multipart upload, keeping its row object_key=nar/gggggggggggggggggggggggggggggg0200000000000000000000.nar.zst upload_id=NDY2MGFiYzYtMjNiZC00YTcwLTkxZWMtYTE5MDZmMGY4MmUzLmVkNjc3OTg2LTgxOWYtNDk3Ny1hZDMzLTZiNTQ5ZGJmODM5YXgxNzkzOTUyODI1Mjg2OTgyMDAw error="Get \"http://127.0.0.1:1/bucket7/?location=\": dial tcp 127.0.0.1:1: connect: connection refused"10382026/11/06 08:13:46 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0200000000000000000000.nar.zst upload_id=NDY2MGFiYzYtMjNiZC00YTcwLTkxZWMtYTE5MDZmMGY4MmUzLjY1MTM4NDgwLTg5NTQtNGFmZS05NjY5LTg5NDZkMzIyMjk2OXgxNzkzOTUyODI1MjQzMjMxMDAw parts=1210392026/11/06 08:13:46 INFO Received cleanup request method=DELETE path=/api/pending_closures10402026/11/06 08:13:46 INFO Aborted multipart uploads count=1 kept=01041--- PASS: TestRedundantMultipartUpload (5.30s)1042=== CONT TestParseSize1043--- PASS: TestParseSize (0.00s)1044=== CONT TestPendingClosureWriteTimeout1045=== RUN TestPendingClosureWriteTimeout/empty1046=== PAUSE TestPendingClosureWriteTimeout/empty1047=== RUN TestPendingClosureWriteTimeout/400_objects1048=== PAUSE TestPendingClosureWriteTimeout/400_objects1049=== RUN TestPendingClosureWriteTimeout/670k_objects1050=== PAUSE TestPendingClosureWriteTimeout/670k_objects1051=== RUN TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline1052=== PAUSE TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline1053=== CONT TestProxyWriteTimeout1054=== RUN TestProxyWriteTimeout/narinfo1055=== PAUSE TestProxyWriteTimeout/narinfo1056=== RUN TestProxyWriteTimeout/1_GiB_nar1057=== PAUSE TestProxyWriteTimeout/1_GiB_nar1058=== RUN TestProxyWriteTimeout/10_GiB_nar1059=== PAUSE TestProxyWriteTimeout/10_GiB_nar1060=== RUN TestProxyWriteTimeout/unknown_size1061=== PAUSE TestProxyWriteTimeout/unknown_size1062=== CONT TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle10632026-11-06 08:13:47.025 UTC [98129] ERROR: could not obtain lock on row in relation "closures"10642026-11-06 08:13:47.025 UTC [98129] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT10652026-11-06 08:13:47.028 UTC [98129] ERROR: could not obtain lock on row in relation "closures"10662026-11-06 08:13:47.028 UTC [98129] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT10672026-11-06 08:13:47.028 UTC [98129] ERROR: could not obtain lock on row in relation "closures"10682026-11-06 08:13:47.028 UTC [98129] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT10692026-11-06 08:13:47.028 UTC [98129] ERROR: could not obtain lock on row in relation "closures"10702026-11-06 08:13:47.028 UTC [98129] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT10712026-11-06 08:13:47.029 UTC [98129] ERROR: could not obtain lock on row in relation "closures"10722026-11-06 08:13:47.029 UTC [98129] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT1073--- PASS: TestPush_RootsAreLockedInByteOrder (5.46s)1074=== CONT TestSkippedUploadsHandler10752026/11/06 08:13:47 INFO Client skipped oversized paths paths=3 nar_bytes=50000000001076--- PASS: TestSkippedUploadsHandler (0.01s)1077=== CONT TestPresignedUploadRegisteredBeforeCommit10782026/11/06 08:13:47 INFO Received push request method=POST path=/api/pushes10792026/11/06 08:13:47 INFO Received complete push request method=POST path=/api/pushes/1/complete10802026/11/06 08:13:47 INFO Completed push id=1 objects=4 duration=22.141334ms1081--- PASS: TestPush_RepeatedRootCommitsOnce (5.61s)1082=== CONT TestService_Rustfstest1083--- PASS: TestReadRedirectNar (5.75s)1084=== CONT TestCompletedNarNotReofferedAcrossClosures1085--- PASS: TestReadProxyConditionalGet (5.92s)1086=== CONT TestCompleteMultipartUpload_ErrorButObjectExists10872026/11/06 08:13:47 INFO Received push request method=POST path=/api/pushes10882026/11/06 08:13:47 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign10892026/11/06 08:13:47 INFO Signed narinfos id=1 count=110902026/11/06 08:13:47 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign10912026/11/06 08:13:47 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign10922026/11/06 08:13:47 ERROR Failed to sign narinfos signer="index 1" error="signing key cannot be nil"10932026/11/06 08:13:47 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign10942026/11/06 08:13:47 ERROR Failed to sign narinfos signer=niks3-test-1 error="signer failed"10952026/11/06 08:13:47 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign10962026/11/06 08:13:47 ERROR Signer returned unexpected signature count signer=niks3-test-1 got=0 want=110972026/11/06 08:13:47 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign10982026/11/06 08:13:47 ERROR Signer returned unexpected object key signer=niks3-test-1 object_key=unexpected.narinfo1099--- PASS: TestPush_SignsNarinfosOfItsPendingObjects (6.41s)1100=== CONT TestResolveDBConnectionString1101=== RUN TestResolveDBConnectionString/flag_wins1102=== PAUSE TestResolveDBConnectionString/flag_wins1103=== RUN TestResolveDBConnectionString/file_when_flag_empty1104=== PAUSE TestResolveDBConnectionString/file_when_flag_empty1105=== RUN TestResolveDBConnectionString/missing_file_is_an_error1106=== PAUSE TestResolveDBConnectionString/missing_file_is_an_error1107=== RUN TestResolveDBConnectionString/PGHOST_allows_empty1108=== PAUSE TestResolveDBConnectionString/PGHOST_allows_empty1109=== RUN TestResolveDBConnectionString/nothing_configured1110=== PAUSE TestResolveDBConnectionString/nothing_configured1111=== CONT TestSweepRechecksPendingAfterLocking1112--- PASS: TestReadProxyRootRedirectsToIndexHTML (6.58s)1113=== CONT TestGetExistingObjectsLocksRows1114--- PASS: TestReadRedirectKeepsNarinfoProxied (6.82s)1115=== CONT TestRegisterCompletedObjectNeedsPendingRow1116--- PASS: TestReadProxyInvalidPath (5.66s)1117=== CONT TestSweepSkipsRowsLockedByPush1118--- PASS: TestReadProxyNarStreaming (5.42s)1119=== CONT TestFailedS3DeleteKeepsTombstone1120--- PASS: TestReadProxy404 (5.97s)1121=== CONT TestForceGCDuringPushOffersSweptObject1122=== RUN TestForceGCDuringPushOffersSweptObject/before_pending_rows1123=== PAUSE TestForceGCDuringPushOffersSweptObject/before_pending_rows1124=== RUN TestForceGCDuringPushOffersSweptObject/after_presence_check1125=== PAUSE TestForceGCDuringPushOffersSweptObject/after_presence_check1126=== CONT TestCreatePendingClosureVerifyS3FailureReleasesConnection1127--- PASS: TestReadProxyContentNegotiation (5.36s)1128=== CONT TestGCSweepDeliversEachKeyOnce1129--- PASS: TestReadProxyNarinfoAlreadyDecompressed (5.27s)1130=== CONT TestTombstonedObjectOfferedWithoutWaiting11312026/11/06 08:13:49 ERROR Failed to decode narinfo key=3hcdxyjf9yiq7qf3i4548drb6sjmwa1v.narinfo limit=16777216 error=<nil>1132--- PASS: TestReadProxyNarinfo (5.56s)1133=== CONT TestGCSweepSkipsPendingObjects1134--- PASS: TestPresentRefreshesOnlyStaleClosures (5.55s)1135=== CONT TestDeduplicatedObjectsRecordedAsPending1136--- PASS: TestPresentReportsOnlyClosureRoots (5.29s)1137=== CONT TestPushDedupSurvivesConcurrentGC11382026/11/06 08:13:51 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux11392026/11/06 08:13:51 WARN Refused reserved pin name=worker-x86_64-linux11402026/11/06 08:13:51 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux11412026/11/06 08:13:51 INFO Received create pin request method=POST path=/api/pins/my-app11422026/11/06 08:13:51 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux1143--- PASS: TestCreatePin_ReservedPins (5.90s)1144=== CONT TestGCMetrics1145--- PASS: TestObjectStatsTrigger (5.74s)1146=== CONT TestGCBugBareHashReferences1147--- PASS: TestReadProxyOutlastsServerWriteTimeout (10.37s)1148=== CONT TestGCAdvisoryLockBlocksConcurrentRun1149--- PASS: TestObjectStatsUpdatedOncePerCommit (6.50s)1150=== CONT TestLeadEndsOnShutdown11512026/11/06 08:13:52 INFO Received uploads request method=POST path=/api/pending_closures11522026/11/06 08:13:52 INFO Received uploads request method=POST path=/api/pending_closures11532026/11/06 08:13:52 INFO Received cleanup request method=DELETE path=/api/pending_closures11542026/11/06 08:13:53 INFO Received uploads request method=POST path=/api/pending_closures1155--- PASS: TestMultipartUploadAbortedWhenCancelledBeforeRecorded (6.67s)1156=== CONT TestLeadIncumbentAnnouncesAtOnce11572026/11/06 08:13:53 INFO Received uploads request method=POST path=/api/pending_closures1158=== NAME TestOrphanedObjectsGC1159 orphaned_objects_gc_test.go:287: GC Test Summary:1160 orphaned_objects_gc_test.go:288: - Kept: 2 objects from closure A1161 orphaned_objects_gc_test.go:289: - Deleted: 2 objects from closure B1162 orphaned_objects_gc_test.go:290: - Deleted: 6 orphaned chain objects (X1->X2->X3)1163 orphaned_objects_gc_test.go:291: - Deleted: 2 orphaned single objects (Y)1164 orphaned_objects_gc_test.go:292: - Total deleted: 10 objects1165--- PASS: TestOrphanedObjectsGC (8.49s)1166=== CONT TestLeadElectsOneAndHandsOver11672026/11/06 08:13:54 INFO Received uploads request method=POST path=/api/pending_closures11682026/11/06 08:13:54 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11692026/11/06 08:13:54 INFO Registered completed upload object_key=nar/jjjjjjjjjjjjjjjjjjjjjjjjjjjjjj0100000000000000000000.nar.zst11702026/11/06 08:13:54 INFO Received uploads request method=POST path=/api/pending_closures1171--- PASS: TestPresignedUploadRegisteredBeforeCommit (7.19s)1172=== CONT TestConnectWaitsForAPeerMigration1173--- PASS: TestService_Rustfstest (7.17s)1174=== CONT TestService_createPendingClosureHandler11752026/11/06 08:13:54 INFO Received uploads request method=POST path=/api/pending_closures11762026/11/06 08:13:55 INFO Received uploads request method=POST path=/api/pending_closures11772026/11/06 08:13:55 INFO Aborted multipart uploads count=0 kept=011782026/11/06 08:13:55 WARN Force mode enabled - objects will be deleted immediately without grace period11792026/11/06 08:13:55 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=011802026/11/06 08:13:55 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11812026/11/06 08:13:55 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified key does not exist." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=NDY2MGFiYzYtMjNiZC00YTcwLTkxZWMtYTE5MDZmMGY4MmUzLjEzYmFkZjJiLThlZjYtNDI5MC04N2FhLTRhMGUxZWQ1YWY2ZHgxNzkzOTUyODM1MDc4NDQ3MDAw11822026/11/06 08:13:55 INFO Vacuumed table table=pending_closures11832026/11/06 08:13:55 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=NDY2MGFiYzYtMjNiZC00YTcwLTkxZWMtYTE5MDZmMGY4MmUzLjEzYmFkZjJiLThlZjYtNDI5MC04N2FhLTRhMGUxZWQ1YWY2ZHgxNzkzOTUyODM1MDc4NDQ3MDAw parts=11184--- PASS: TestCompleteMultipartUpload_ErrorButObjectExists (8.18s)1185=== CONT TestService_verifyS3ReuploadsStaleNarinfo1186=== RUN TestService_verifyS3ReuploadsStaleNarinfo/lost,_other_NAR_pushed1187=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo/lost,_other_NAR_pushed1188=== RUN TestService_verifyS3ReuploadsStaleNarinfo/intact,_other_NAR_pushed1189=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo/intact,_other_NAR_pushed1190=== RUN TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost1191=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost1192=== RUN TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost,_second_pushed1193=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost,_second_pushed1194=== RUN TestService_verifyS3ReuploadsStaleNarinfo/lost,_same_NAR_pushed1195=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo/lost,_same_NAR_pushed1196=== CONT TestService_verifyS3Integrity11972026/11/06 08:13:55 INFO Vacuumed table table=pending_objects11982026/11/06 08:13:55 INFO Vacuumed table table=multipart_uploads11992026/11/06 08:13:55 INFO Vacuumed table table=closures12002026/11/06 08:13:55 INFO Vacuumed table table=objects1201--- PASS: TestSweepRechecksPendingAfterLocking (7.83s)1202=== CONT TestClientErrorHandling1203=== RUN TestClientErrorHandling/InvalidStorePath1204=== PAUSE TestClientErrorHandling/InvalidStorePath1205=== RUN TestClientErrorHandling/InvalidAuthToken1206=== PAUSE TestClientErrorHandling/InvalidAuthToken1207=== RUN TestClientErrorHandling/ServerNotAvailable1208=== PAUSE TestClientErrorHandling/ServerNotAvailable1209=== CONT TestConcurrentCommitsSharingObjectsDoNotDeadlock1210--- PASS: TestGetExistingObjectsLocksRows (7.69s)1211=== CONT TestDeleteClosuresRacingPins1212--- PASS: TestRegisterCompletedObjectNeedsPendingRow (7.70s)1213=== CONT TestClientFallsBackToClosures12142026/11/06 08:13:56 INFO Aborted multipart uploads count=0 kept=012152026/11/06 08:13:56 WARN Force mode enabled - objects will be deleted immediately without grace period12162026/11/06 08:13:56 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=012172026/11/06 08:13:56 INFO Vacuumed table table=pending_closures12182026/11/06 08:13:56 INFO Vacuumed table table=pending_objects12192026/11/06 08:13:56 INFO Vacuumed table table=multipart_uploads12202026/11/06 08:13:56 INFO Vacuumed table table=closures12212026/11/06 08:13:56 INFO Vacuumed table table=objects12222026/11/06 08:13:56 INFO Aborted multipart uploads count=0 kept=012232026/11/06 08:13:56 WARN Force mode enabled - objects will be deleted immediately without grace period12242026/11/06 08:13:56 INFO Received uploads request method=POST path=/api/pending_closures12252026/11/06 08:13:56 INFO Received complete multipart upload request method=POST path=/api/multipart/complete12262026/11/06 08:13:57 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=012272026/11/06 08:13:57 INFO Vacuumed table table=pending_closures12282026/11/06 08:13:57 INFO Vacuumed table table=pending_objects12292026/11/06 08:13:57 INFO Vacuumed table table=multipart_uploads12302026/11/06 08:13:57 INFO Vacuumed table table=closures12312026/11/06 08:13:57 INFO Completed multipart upload object_key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhh0100000000000000000000.nar.zst upload_id=NDY2MGFiYzYtMjNiZC00YTcwLTkxZWMtYTE5MDZmMGY4MmUzLmUwY2I5NTk2LWRmODMtNGJjOC04MTI5LWVmY2E0MDUxMWVmZngxNzkzOTUyODM0NzcxMDI5MDAw parts=1212322026/11/06 08:13:57 INFO Vacuumed table table=objects12332026/11/06 08:13:57 INFO Received uploads request method=POST path=/api/pending_closures1234--- PASS: TestSweepSkipsRowsLockedByPush (8.46s)1235--- PASS: TestCompletedNarNotReofferedAcrossClosures (9.71s)1236=== CONT TestClientPushesUseOnePush1237=== CONT TestPinProtectsFromGC12382026/11/06 08:13:57 INFO Received uploads request method=POST path=/api/pending_closures12392026/11/06 08:13:57 INFO Aborted multipart uploads count=0 kept=012402026/11/06 08:13:57 WARN Force mode enabled - objects will be deleted immediately without grace period12412026/11/06 08:13:57 ERROR failed to remove object object=nar/dddddddddddddddddddddddddddddddddddddddddddddddddddd.nar.zst error="Access Denied."12422026/11/06 08:13:57 ERROR failed to remove object object=dddddddddddddddddddddddddddddddd.narinfo error="Access Denied."1243--- PASS: TestFailedS3DeleteKeepsTombstone (8.27s)1244=== CONT TestClientSharedPathCommittedMidPush1245--- PASS: TestCreatePendingClosureVerifyS3FailureReleasesConnection (8.24s)1246=== CONT TestClientWithDependencies12472026/11/06 08:13:57 INFO Aborted multipart uploads count=0 kept=012482026/11/06 08:13:57 WARN Force mode enabled - objects will be deleted immediately without grace period12492026/11/06 08:13:57 INFO Received uploads request method=POST path=/api/pending_closures1250--- PASS: TestTombstonedObjectOfferedWithoutWaiting (8.30s)1251=== CONT TestClientMultipleUploads12522026/11/06 08:13:58 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=012532026/11/06 08:13:58 INFO Vacuumed table table=pending_closures12542026/11/06 08:13:58 INFO Received uploads request method=POST path=/api/pending_closures12552026/11/06 08:13:58 INFO Vacuumed table table=pending_objects12562026/11/06 08:13:58 INFO Vacuumed table table=multipart_uploads12572026/11/06 08:13:58 INFO Vacuumed table table=closures12582026/11/06 08:13:58 INFO Vacuumed table table=objects1259--- PASS: TestGCSweepDeliversEachKeyOnce (8.93s)1260=== CONT TestClientIntegration12612026/11/06 08:13:58 INFO Aborted multipart uploads count=0 kept=012622026/11/06 08:13:58 WARN Force mode enabled - objects will be deleted immediately without grace period12632026/11/06 08:13:58 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=012642026/11/06 08:13:58 INFO Vacuumed table table=pending_closures12652026/11/06 08:13:58 INFO Vacuumed table table=pending_objects12662026/11/06 08:13:58 INFO Vacuumed table table=multipart_uploads12672026/11/06 08:13:58 INFO Vacuumed table table=closures12682026/11/06 08:13:58 INFO Vacuumed table table=objects12692026/11/06 08:13:58 INFO Received uploads request method=POST path=/api/pending_closures1270--- PASS: TestGCSweepSkipsPendingObjects (8.75s)1271=== CONT TestService_RequireScope_OIDC1272--- PASS: TestDeduplicatedObjectsRecordedAsPending (8.54s)1273=== CONT TestClientCADerivations12742026/11/06 08:13:58 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:56862/oidc12752026/11/06 08:13:58 WARN Rate limiter enabled after throttle name=s3-test rate=512762026/11/06 08:13:58 WARN S3 rate limit hit operation="complete multipart upload" error="Please reduce your request rate."1277=== NAME TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle1278 throttle_test.go:213: Proxy stats: total=13, throttled=10, completeMultipart=101279 throttle_test.go:215: Rate limiter: enabled=true, rate=5.001280--- PASS: TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle (11.93s)1281=== CONT TestCacheStatsHandler12822026/11/06 08:13:58 INFO Aborted multipart uploads count=1 kept=012832026/11/06 08:13:58 INFO Received cleanup request method=DELETE path=/api/pending_closures12842026/11/06 08:13:58 INFO Aborted multipart uploads count=1 kept=01285--- PASS: TestPendingCleanupUsesOneCutoff (12.64s)1286=== CONT TestCacheConfigHandler1287=== RUN TestCacheConfigHandler/full_config,_no_issuer1288=== PAUSE TestCacheConfigHandler/full_config,_no_issuer1289=== RUN TestCacheConfigHandler/no_cache_url_configured1290=== PAUSE TestCacheConfigHandler/no_cache_url_configured1291=== RUN TestCacheConfigHandler/no_signing_keys1292=== PAUSE TestCacheConfigHandler/no_signing_keys1293=== RUN TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1294=== PAUSE TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1295=== CONT TestService_ReadScope_PublicByDefault12962026/11/06 08:13:59 INFO Received uploads request method=POST path=/api/pending_closures12972026/11/06 08:13:59 INFO Aborted multipart uploads count=0 kept=012982026/11/06 08:13:59 WARN Force mode enabled - objects will be deleted immediately without grace period12992026/11/06 08:13:59 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=013002026/11/06 08:13:59 INFO Aborted multipart uploads count=0 kept=013012026/11/06 08:13:59 INFO Vacuumed table table=pending_closures13022026/11/06 08:13:59 INFO Vacuumed table table=pending_objects13032026/11/06 08:13:59 INFO Vacuumed table table=multipart_uploads13042026/11/06 08:13:59 INFO Vacuumed table table=closures13052026/11/06 08: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=013062026/11/06 08:13:59 INFO Vacuumed table table=objects1307--- PASS: TestGCMetrics (8.36s)1308=== CONT TestUploadHandlersRejectOversizedBody13092026/11/06 08:13:59 INFO Vacuumed table table=pending_closures13102026/11/06 08:13:59 INFO Vacuumed table table=pending_objects13112026/11/06 08:13:59 INFO Vacuumed table table=multipart_uploads13122026/11/06 08:13:59 INFO Vacuumed table table=closures13132026/11/06 08:13:59 INFO Vacuumed table table=objects13142026/11/06 08:13:59 INFO Aborted multipart uploads count=0 kept=01315=== RUN TestUploadHandlersRejectOversizedBody/create_pending_closure1316=== PAUSE TestUploadHandlersRejectOversizedBody/create_pending_closure1317=== RUN TestUploadHandlersRejectOversizedBody/complete_multipart1318=== PAUSE TestUploadHandlersRejectOversizedBody/complete_multipart1319=== RUN TestUploadHandlersRejectOversizedBody/request_more_parts1320=== PAUSE TestUploadHandlersRejectOversizedBody/request_more_parts1321=== CONT TestService_cleanupPendingClosuresHandler13222026/11/06 08:13:59 WARN Force mode enabled - objects will be deleted immediately without grace period13232026/11/06 08:13:59 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=013242026/11/06 08:13:59 INFO Vacuumed table table=pending_closures13252026/11/06 08:13:59 INFO Vacuumed table table=pending_objects13262026/11/06 08:13:59 INFO Vacuumed table table=multipart_uploads13272026/11/06 08:13:59 INFO Vacuumed table table=closures13282026/11/06 08:13:59 INFO Vacuumed table table=objects1329--- PASS: TestPushDedupSurvivesConcurrentGC (9.21s)1330=== CONT TestUploadHandlersRejectInvalidKeys1331=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info1332=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info1333=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal1334=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal1335=== RUN TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key1336=== PAUSE TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key1337=== RUN TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key1338=== PAUSE TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key1339=== CONT TestService_healthCheckHandler13402026/11/06 08:13:59 ERROR failed to check GC advisory lock error="query pg_locks: failed to connect to `user=_tribuchetbld1 database=niks3`: /nonexistent/.s.PGSQL.5432 (/nonexistent): dial error: dial unix /nonexistent/.s.PGSQL.5432: connect: no such file or directory"1341--- PASS: TestGCBugBareHashReferences (8.07s)1342=== CONT TestServerTLSConfig1343=== RUN TestServerTLSConfig/no_client_CA1344=== PAUSE TestServerTLSConfig/no_client_CA1345=== RUN TestServerTLSConfig/missing_CA_file1346--- PASS: TestGCAdvisoryLockBlocksConcurrentRun (7.95s)1347=== PAUSE TestServerTLSConfig/missing_CA_file1348=== RUN TestServerTLSConfig/not_a_PEM_file1349=== PAUSE TestServerTLSConfig/not_a_PEM_file1350=== CONT TestService_NativeMTLS1351=== CONT TestMetricsCommit13522026/11/06 08:14:00 INFO lead: acquired remote=192.0.2.1:123413532026/11/06 08:14:00 INFO lead: acquired remote=192.0.2.1:123413542026/11/06 08:14:00 INFO lead: released remote=192.0.2.1:12341355--- PASS: TestLeadIncumbentAnnouncesAtOnce (7.37s)1356=== CONT TestMetricsInventory13572026/11/06 08:14:00 INFO lead: acquired remote=192.0.2.1:123413582026/11/06 08:14:01 INFO Received uploads request method=POST path=/api/pending_closures13592026/11/06 08:14:01 INFO Received uploads request method=POST path=/api/pending_closures13602026/11/06 08:14:01 INFO Received uploads request method=POST path=/api/pending_closures13612026/11/06 08:14:01 INFO lead: released remote=192.0.2.1:12341362--- PASS: TestLeadEndsOnShutdown (8.70s)1363=== CONT TestNARDeduplicationMetadataUploadBug13642026/11/06 08:14:01 INFO Received uploads request method=POST path=/api/pending_closures13652026/11/06 08:14:02 INFO lead: released remote=192.0.2.1:123413662026/11/06 08:14:02 INFO lead: acquired remote=192.0.2.1:12341367--- PASS: TestConnectWaitsForAPeerMigration (8.36s)1368=== CONT TestCreatePendingClosureRejectsOversizedNAR13692026/11/06 08:14:02 INFO Received uploads request method=POST path=/api/pending_closures1370--- PASS: TestCreatePendingClosureRejectsOversizedNAR (0.00s)1371=== CONT TestCacheConfigHandlerMaxNarSize1372--- PASS: TestCacheConfigHandlerMaxNarSize (0.00s)1373=== CONT TestGenerateLandingPage1374--- PASS: TestGenerateLandingPage (0.00s)1375=== CONT TestService_readinessHandler13762026/11/06 08:14:03 INFO Received complete multipart upload request method=POST path=/api/multipart/complete13772026/11/06 08:14:03 INFO lead: released remote=192.0.2.1:12341378=== CONT TestService_ReadAuthMiddleware1379--- PASS: TestLeadElectsOneAndHandsOver (9.27s)13802026/11/06 08:14:03 INFO Completed multipart upload object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst upload_id=NDY2MGFiYzYtMjNiZC00YTcwLTkxZWMtYTE5MDZmMGY4MmUzLjU0N2JjMTBkLTNhMTUtNDg0OC1hNGRmLWQxMTUzZmQyZTY1ZHgxNzkzOTUyODQxMjY3NjcxMDAw parts=1013812026/11/06 08:14:03 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete13822026/11/06 08:14:03 INFO Completed upload id=1 objects=2 duration=34.662625ms13832026/11/06 08:14:03 INFO Received get closure request method=GET path=/api/closures/0000000000000000000000000000000013842026/11/06 08:14:03 INFO Received uploads request method=POST path=/api/pending_closures13852026/11/06 08:14:03 INFO Starting cleanup of old closures method=DELETE path=/api/closures13862026/11/06 08:14:03 INFO Aborted multipart uploads count=0 kept=013872026/11/06 08:14:03 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=013882026/11/06 08:14:03 INFO Vacuumed table table=pending_closures13892026/11/06 08:14:03 INFO Received complete multipart upload request method=POST path=/api/multipart/complete13902026/11/06 08:14:03 INFO Vacuumed table table=pending_objects13912026/11/06 08:14:03 INFO Vacuumed table table=multipart_uploads13922026/11/06 08:14:03 INFO Vacuumed table table=closures1393=== NAME TestPinProtectsFromGC1394 client_integration_test.go:778: Pinned store path: /private/var/tb/1/scratch/8499ef2246bbc144/build/TestPinProtectsFromGC4244804449/001/store/ijdl0i773f044l8pl6jjld6hwkh36bfy-pinned-file.txt1395 client_integration_test.go:779: Unpinned store path: /private/var/tb/1/scratch/8499ef2246bbc144/build/TestPinProtectsFromGC4244804449/001/store/qranwamfabkhaf4cipcx6h8s9qh6z6qm-unpinned-file.txt13962026/11/06 08:14:03 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst upload_id=NDY2MGFiYzYtMjNiZC00YTcwLTkxZWMtYTE5MDZmMGY4MmUzLjY4ZWMyYTZmLWE1OWYtNDQ5Ny1hM2YzLTMxNmIzNzM2ODFkZngxNzkzOTUyODQxNTg5NDQyMDAw parts=1013972026/11/06 08:14:03 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete13982026/11/06 08:14:03 INFO Vacuumed table table=objects13992026/11/06 08:14:03 INFO Completed upload id=1 objects=2 duration=29.042ms14002026/11/06 08:14:03 INFO Received uploads request method=POST path=/api/pending_closures14012026/11/06 08:14:03 INFO Received uploads request method=POST path=/api/pending_closures14022026/11/06 08:14:03 INFO Received get closure request method=GET path=/api/closures/0000000000000000000000000000000014032026/11/06 08:14:03 INFO Object in database but missing from S3 key=dadb44fdadb44fdadb44fdadb44f0000.narinfo1404--- PASS: TestService_createPendingClosureHandler (9.29s)1405=== CONT TestService_AuthMiddleware_OIDC14062026/11/06 08:14:03 WARN Found objects in DB but missing from S3, will re-upload count=11407--- PASS: TestService_verifyS3Integrity (7.97s)1408=== CONT TestGCTaskStore_GetReturnsLatest1409--- PASS: TestGCTaskStore_GetReturnsLatest (0.00s)1410=== CONT TestGracefulShutdownDrainsInflight14112026/11/06 08:14:03 INFO Starting HTTP server address=127.0.0.1:5690514122026/11/06 08:14:03 INFO Shutdown signal received, draining in-flight requests timeout=10s14132026/11/06 08:14:03 INFO Received uploads request method=POST path=/api/pending_closures14142026/11/06 08:14:03 INFO Received push request method=POST path=/api/pushes14152026/11/06 08:14:03 INFO Received uploads request method=POST path=/api/pending_closures14162026/11/06 08:14:03 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)14172026/11/06 08:14:03 INFO Uploading n5ix46b6r3d7wqd3z6b9vf236qwp3b4h-b (256B)14182026/11/06 08:14:03 INFO Uploading idz72srfanqpnzdmn4gvm380qv7xlajk-shared-dep (136B)1419--- PASS: TestGracefulShutdownDrainsInflight (0.07s)1420=== CONT TestGCTaskStore_Fail1421--- PASS: TestGCTaskStore_Fail (0.00s)1422=== CONT TestGCTaskStore_PhaseUpdates1423--- PASS: TestGCTaskStore_PhaseUpdates (0.00s)1424=== CONT TestGCTaskStore_CompletedAllowsNewTask1425--- PASS: TestGCTaskStore_CompletedAllowsNewTask (0.00s)1426=== CONT TestGCTaskStore_DeduplicateSameParams1427--- PASS: TestGCTaskStore_DeduplicateSameParams (0.00s)1428=== CONT TestGCTaskStore_GetEmpty1429--- PASS: TestGCTaskStore_GetEmpty (0.00s)1430=== CONT TestGCTaskStore_ConflictDifferentParams1431--- PASS: TestGCTaskStore_ConflictDifferentParams (0.00s)1432=== CONT TestGCTaskStore_StartNew1433--- PASS: TestGCTaskStore_StartNew (0.00s)1434=== CONT TestGCEndsOnShutdown1435=== RUN TestGCEndsOnShutdown/before_the_run1436=== PAUSE TestGCEndsOnShutdown/before_the_run1437=== RUN TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete1438=== PAUSE TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete1439=== RUN TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark1440=== PAUSE TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark1441=== CONT TestService_AuthMiddleware_MTLSBoundSubjects14422026/11/06 08:14:03 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)14432026/11/06 08:14:03 INFO Uploading ijdl0i773f044l8pl6jjld6hwkh36bfy-pinned-file.txt (128B)14442026/11/06 08:14:03 WARN Failed to register uploaded object key=n5ix46b6r3d7wqd3z6b9vf236qwp3b4h.ls error="server returned 404: 404 page not found\n"14452026/11/06 08:14:03 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:56921/oidc14462026/11/06 08:14:03 WARN Failed to register uploaded object key=idz72srfanqpnzdmn4gvm380qv7xlajk.ls error="server returned 404: 404 page not found\n"14472026/11/06 08:14:03 WARN Failed to register uploaded object key=nar/0pnc4hh0hyi52mv6jza1ghyhg3nv0504d9gbzmqg1w36idxh4cf0.nar.zst error="server returned 404: 404 page not found\n"14482026/11/06 08:14:03 WARN Failed to register uploaded object key=j4k0jncajnmfm8l9hj0qq7nki414pkhd.ls error="server returned 404: 404 page not found\n"14492026/11/06 08:14:03 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"14502026/11/06 08:14:03 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign14512026/11/06 08:14:03 INFO Signed narinfos id=1 count=214522026/11/06 08:14:03 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign14532026/11/06 08:14:03 WARN Failed to register uploaded object key=nar/0qmhsg42pqsz7x6hh02j8gznnac3yi3qpjhrqbwvz88i194jbb5s.nar.zst error="server returned 404: 404 page not found\n"14542026/11/06 08:14:03 WARN Failed to register uploaded object key=ijdl0i773f044l8pl6jjld6hwkh36bfy.ls error="server returned 404: 404 page not found\n"14552026/11/06 08:14:03 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign14562026/11/06 08:14:03 INFO Signed narinfos id=2 count=214572026/11/06 08:14:03 INFO Uploading 4 narinfos14582026/11/06 08:14:03 INFO Signed narinfos id=1 count=114592026/11/06 08:14:03 INFO Uploading 1 narinfos14602026/11/06 08:14:03 WARN Failed to register uploaded object key=idz72srfanqpnzdmn4gvm380qv7xlajk.narinfo error="server returned 404: 404 page not found\n"14612026/11/06 08:14:03 WARN Failed to register uploaded object key=j4k0jncajnmfm8l9hj0qq7nki414pkhd.narinfo error="server returned 404: 404 page not found\n"14622026/11/06 08:14:03 WARN Failed to register uploaded object key=n5ix46b6r3d7wqd3z6b9vf236qwp3b4h.narinfo error="server returned 404: 404 page not found\n"14632026/11/06 08:14:03 INFO Received complete push request method=POST path=/api/pushes/1/complete14642026/11/06 08:14:03 WARN Failed to register uploaded object key=ijdl0i773f044l8pl6jjld6hwkh36bfy.narinfo error="server returned 404: 404 page not found\n"14652026/11/06 08:14:03 INFO Completed push id=1 objects=3 duration=20.727875ms14662026/11/06 08:14:03 INFO Upload complete. (371ms)14672026/11/06 08:14:04 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete14682026/11/06 08:14:04 WARN Failed to register uploaded object key=idz72srfanqpnzdmn4gvm380qv7xlajk.narinfo error="server returned 404: 404 page not found\n"14692026/11/06 08:14:04 INFO Completed upload id=1 objects=6 duration=73.876167ms14702026/11/06 08:14:04 INFO Received push request method=POST path=/api/pushes14712026/11/06 08:14:04 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete14722026/11/06 08:14:04 INFO Completed upload id=2 objects=6 duration=684.458µs14732026/11/06 08:14:04 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)14742026/11/06 08:14:04 INFO Uploading qranwamfabkhaf4cipcx6h8s9qh6z6qm-unpinned-file.txt (128B)14752026/11/06 08:14:04 INFO Upload complete. (505ms)1476--- PASS: TestConcurrentCommitsSharingObjectsDoNotDeadlock (8.28s)1477=== CONT TestService_AuthMiddleware_MTLSProxyHeader1478=== NAME TestClientFallsBackToClosures1479 client_pushes_test.go:112: Retrieved narinfo from S3:1480 StorePath: /private/var/tb/1/scratch/8499ef2246bbc144/build/TestClientFallsBackToClosures710017509/001/store/idz72srfanqpnzdmn4gvm380qv7xlajk-shared-dep1481 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1482 Compression: zstd1483 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821484 NarSize: 1361485 References: 1486 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1487 client_pushes_test.go:112: Retrieved narinfo from S3:1488 StorePath: /private/var/tb/1/scratch/8499ef2246bbc144/build/TestClientFallsBackToClosures710017509/001/store/j4k0jncajnmfm8l9hj0qq7nki414pkhd-a1489 URL: nar/0pnc4hh0hyi52mv6jza1ghyhg3nv0504d9gbzmqg1w36idxh4cf0.nar.zst1490 Compression: zstd1491 NarHash: sha256:0pnc4hh0hyi52mv6jza1ghyhg3nv0504d9gbzmqg1w36idxh4cf01492 NarSize: 2561493 References: /private/var/tb/1/scratch/8499ef2246bbc144/build/TestClientFallsBackToClosures710017509/001/store/idz72srfanqpnzdmn4gvm380qv7xlajk-shared-dep1494 CA: text:sha256:1k4h0wmys8kfa19fns9v3nr94rrh32fi0gg7kmm4ljrrhcjdzrr01495 client_pushes_test.go:112: Retrieved narinfo from S3:1496 StorePath: /private/var/tb/1/scratch/8499ef2246bbc144/build/TestClientFallsBackToClosures710017509/001/store/n5ix46b6r3d7wqd3z6b9vf236qwp3b4h-b1497 URL: nar/0pnc4hh0hyi52mv6jza1ghyhg3nv0504d9gbzmqg1w36idxh4cf0.nar.zst1498 Compression: zstd1499 NarHash: sha256:0pnc4hh0hyi52mv6jza1ghyhg3nv0504d9gbzmqg1w36idxh4cf01500 NarSize: 2561501 References: /private/var/tb/1/scratch/8499ef2246bbc144/build/TestClientFallsBackToClosures710017509/001/store/idz72srfanqpnzdmn4gvm380qv7xlajk-shared-dep1502 CA: text:sha256:1k4h0wmys8kfa19fns9v3nr94rrh32fi0gg7kmm4ljrrhcjdzrr015032026/11/06 08:14:04 WARN Failed to register uploaded object key=qranwamfabkhaf4cipcx6h8s9qh6z6qm.ls error="server returned 404: 404 page not found\n"15042026/11/06 08:14:04 WARN Failed to register uploaded object key=nar/0gh0wdnr6gmk4r5sfzzh12isnl14rgmkrwy1ws41hpsrlndclg5h.nar.zst error="server returned 404: 404 page not found\n"15052026/11/06 08:14:04 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign15062026/11/06 08:14:04 INFO Signed narinfos id=2 count=115072026/11/06 08:14:04 INFO Uploading 1 narinfos15082026/11/06 08:14:04 INFO Received complete push request method=POST path=/api/pushes/2/complete15092026/11/06 08:14:04 WARN Failed to register uploaded object key=qranwamfabkhaf4cipcx6h8s9qh6z6qm.narinfo error="server returned 404: 404 page not found\n"15102026/11/06 08:14:04 INFO Completed push id=2 objects=3 duration=1.107833ms15112026/11/06 08:14:04 INFO Upload complete. (204ms)1512--- PASS: TestClientFallsBackToClosures (8.15s)1513=== CONT TestIsValidUploadKey/realisation_plus_in_output1514=== CONT TestIsValidUploadKey/narinfo1515=== CONT TestIsValidUploadKey/unknown_type1516=== CONT TestIsValidUploadKey/empty_key1517=== CONT TestIsValidUploadKey/absolute1518=== CONT TestIsValidUploadKey/traversal_nar1519=== CONT TestIsValidUploadKey/traversal1520=== CONT TestIsValidUploadKey/realisation1521=== CONT TestIsValidUploadKey/build_log_equals1522=== CONT TestIsValidUploadKey/listing_key,_narinfo_type1523=== CONT TestIsValidUploadKey/nar_key,_narinfo_type1524=== CONT TestIsValidUploadKey/narinfo_key,_nar_type1525=== CONT TestIsValidUploadKey/index.html1526=== CONT TestIsValidUploadKey/nix-cache-info1527=== CONT TestIsValidUploadKey/build_log_question_mark1528=== CONT TestIsValidUploadKey/listing1529=== CONT TestIsValidUploadKey/nar_plain1530=== CONT TestIsValidUploadKey/nar_xz1531=== CONT TestIsValidUploadKey/nar_zst1532=== CONT TestIsValidUploadKey/build_log_plus_in_name1533=== CONT TestIsValidUploadKey/build_log1534=== CONT TestIsValidUploadKey/build_log_home-manager_file1535--- PASS: TestIsValidUploadKey (0.00s)1536 --- PASS: TestIsValidUploadKey/realisation_plus_in_output (0.00s)1537 --- PASS: TestIsValidUploadKey/narinfo (0.00s)1538 --- PASS: TestIsValidUploadKey/unknown_type (0.00s)1539 --- PASS: TestIsValidUploadKey/empty_key (0.00s)1540 --- PASS: TestIsValidUploadKey/absolute (0.00s)1541 --- PASS: TestIsValidUploadKey/traversal_nar (0.00s)1542 --- PASS: TestIsValidUploadKey/traversal (0.00s)1543 --- PASS: TestIsValidUploadKey/realisation (0.00s)1544 --- PASS: TestIsValidUploadKey/build_log_equals (0.00s)1545 --- PASS: TestIsValidUploadKey/listing_key,_narinfo_type (0.00s)1546 --- PASS: TestIsValidUploadKey/nar_key,_narinfo_type (0.00s)1547 --- PASS: TestIsValidUploadKey/narinfo_key,_nar_type (0.00s)1548 --- PASS: TestIsValidUploadKey/index.html (0.00s)1549 --- PASS: TestIsValidUploadKey/nix-cache-info (0.00s)1550 --- PASS: TestIsValidUploadKey/build_log_question_mark (0.00s)1551 --- PASS: TestIsValidUploadKey/listing (0.00s)1552 --- PASS: TestIsValidUploadKey/nar_plain (0.00s)1553 --- PASS: TestIsValidUploadKey/nar_xz (0.00s)1554 --- PASS: TestIsValidUploadKey/nar_zst (0.00s)1555 --- PASS: TestIsValidUploadKey/build_log_plus_in_name (0.00s)1556 --- PASS: TestIsValidUploadKey/build_log (0.00s)1557 --- PASS: TestIsValidUploadKey/build_log_home-manager_file (0.00s)1558=== CONT TestIsValidCachePath/narinfo1559=== CONT TestIsValidCachePath/index.html1560=== CONT TestIsValidCachePath/short_hash1561=== CONT TestIsValidCachePath/wrong_extension1562=== CONT TestIsValidCachePath/leading_slash1563=== CONT TestIsValidCachePath/empty1564=== CONT TestIsValidCachePath/random_path1565=== CONT TestIsValidCachePath/invalid_char_u1566=== CONT TestIsValidCachePath/invalid_char_e1567=== CONT TestIsValidCachePath/traversal_in_middle1568=== CONT TestIsValidCachePath/traversal_parent1569=== CONT TestIsValidCachePath/nar_uncompressed1570=== CONT TestIsValidCachePath/nix-cache-info1571=== CONT TestIsValidCachePath/realisation1572=== CONT TestIsValidCachePath/log1573=== CONT TestIsValidCachePath/ls1574=== CONT TestIsValidCachePath/nar_xz1575=== CONT TestIsValidCachePath/nar_bz21576=== CONT TestIsValidCachePath/nar_zst1577=== CONT TestIsValidCachePath/narinfo_all_nix_base32_chars1578--- PASS: TestIsValidCachePath (0.01s)1579 --- PASS: TestIsValidCachePath/narinfo (0.00s)1580 --- PASS: TestIsValidCachePath/index.html (0.00s)1581 --- PASS: TestIsValidCachePath/short_hash (0.00s)1582 --- PASS: TestIsValidCachePath/wrong_extension (0.00s)1583 --- PASS: TestIsValidCachePath/leading_slash (0.00s)1584 --- PASS: TestIsValidCachePath/empty (0.00s)1585 --- PASS: TestIsValidCachePath/random_path (0.00s)1586 --- PASS: TestIsValidCachePath/invalid_char_u (0.00s)1587 --- PASS: TestIsValidCachePath/invalid_char_e (0.00s)1588 --- PASS: TestIsValidCachePath/traversal_in_middle (0.00s)1589 --- PASS: TestIsValidCachePath/traversal_parent (0.00s)1590 --- PASS: TestIsValidCachePath/nar_uncompressed (0.00s)1591 --- PASS: TestIsValidCachePath/nix-cache-info (0.00s)1592 --- PASS: TestIsValidCachePath/realisation (0.00s)1593 --- PASS: TestIsValidCachePath/log (0.00s)1594 --- PASS: TestIsValidCachePath/ls (0.00s)1595 --- PASS: TestIsValidCachePath/nar_xz (0.00s)1596 --- PASS: TestIsValidCachePath/nar_bz2 (0.00s)1597 --- PASS: TestIsValidCachePath/nar_zst (0.00s)1598 --- PASS: TestIsValidCachePath/narinfo_all_nix_base32_chars (0.00s)1599=== CONT TestParseSingleRange/none1600=== CONT TestPresentNotReportedWhileGCDeletesClosure/stale16012026/11/06 08:14:04 INFO Starting cleanup of old closures method=DELETE path=/api/closures16022026/11/06 08:14:04 INFO Garbage collection started16032026/11/06 08:14:04 INFO Aborted multipart uploads count=0 kept=016042026/11/06 08:14:04 WARN Force mode enabled - objects will be deleted immediately without grace period16052026/11/06 08:14:04 INFO Received push request method=POST path=/api/pushes16062026/11/06 08:14:04 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)16072026/11/06 08:14:04 INFO Uploading c1jcgl27g02xn0bi09dzxqy2xzjbs6s4-a (256B)16082026/11/06 08:14:04 INFO Uploading slmxksarkk174q4vgbr5lcs0fnd39nsm-shared-dep (136B)1609=== NAME TestOrphanedObjectsGCStressTest1610 orphaned_objects_gc_test.go:422: Created 10 active closures, 5 to-delete closures, 20 orphaned chains16112026/11/06 08:14:04 WARN Failed to register uploaded object key=1bawdyz77xp300r66gavvqcryixqn55i.ls error="server returned 404: 404 page not found\n"16122026/11/06 08:14:04 WARN Failed to register uploaded object key=c1jcgl27g02xn0bi09dzxqy2xzjbs6s4.ls error="server returned 404: 404 page not found\n"16132026/11/06 08:14:04 WARN Failed to register uploaded object key=slmxksarkk174q4vgbr5lcs0fnd39nsm.ls error="server returned 404: 404 page not found\n"16142026/11/06 08:14:04 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"16152026/11/06 08:14:04 WARN Failed to register uploaded object key=nar/0rzw45bfnvqnh9s7n7z02g2rw1528yfcrnc671dlp7yg1az3fz8z.nar.zst error="server returned 404: 404 page not found\n"16162026/11/06 08:14:04 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign16172026/11/06 08:14:04 INFO Signed narinfos id=1 count=316182026/11/06 08:14:04 INFO Uploading 3 narinfos16192026/11/06 08:14:04 INFO Received push request method=POST path=/api/pushes1620 orphaned_objects_gc_test.go:440: Marked 210 objects for deletion16212026/11/06 08:14:04 INFO Uploading 2 paths to 127.0.0.1 (0 already cached)16222026/11/06 08:14:04 INFO Uploading 4qljldddv1vab4zr7rwwhr4n9j30n1d5-shared-dep (136B)16232026/11/06 08:14:04 INFO Uploading jwylqr5dj218z78176dkyvivgp8nn9y6-top (264B)16242026/11/06 08:14:04 WARN Failed to register uploaded object key=c1jcgl27g02xn0bi09dzxqy2xzjbs6s4.narinfo error="server returned 404: 404 page not found\n"16252026/11/06 08:14:04 WARN Failed to register uploaded object key=slmxksarkk174q4vgbr5lcs0fnd39nsm.narinfo error="server returned 404: 404 page not found\n"16262026/11/06 08:14:04 INFO Received complete push request method=POST path=/api/pushes/1/complete16272026/11/06 08:14:04 WARN Failed to register uploaded object key=1bawdyz77xp300r66gavvqcryixqn55i.narinfo error="server returned 404: 404 page not found\n"16282026/11/06 08:14:04 WARN Failed to register uploaded object key=nar/1msncs21ks1zws4p0sc5y70nc5flsi0jicrxa014fnr2az5jnslr.nar.zst error="server returned 404: 404 page not found\n"16292026/11/06 08:14:04 WARN Failed to register uploaded object key=4qljldddv1vab4zr7rwwhr4n9j30n1d5.ls error="server returned 404: 404 page not found\n"16302026/11/06 08:14:04 WARN Failed to register uploaded object key=jwylqr5dj218z78176dkyvivgp8nn9y6.ls error="server returned 404: 404 page not found\n"16312026/11/06 08:14:04 INFO Completed push id=1 objects=8 duration=98.395541ms16322026/11/06 08:14:04 INFO Upload complete. (480ms)1633=== NAME TestClientPushesUseOnePush1634 client_pushes_test.go:97: Retrieved narinfo from S3:1635 StorePath: /private/var/tb/1/scratch/8499ef2246bbc144/build/TestClientPushesUseOnePush152811681/001/store/slmxksarkk174q4vgbr5lcs0fnd39nsm-shared-dep1636 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1637 Compression: zstd16382026/11/06 08:14:04 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign1639 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821640 NarSize: 1361641 References: 1642 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n16432026/11/06 08:14:04 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"16442026/11/06 08:14:04 INFO Signed narinfos id=1 count=216452026/11/06 08:14:04 INFO Uploading 2 narinfos1646 client_pushes_test.go:97: Retrieved narinfo from S3:1647 StorePath: /private/var/tb/1/scratch/8499ef2246bbc144/build/TestClientPushesUseOnePush152811681/001/store/c1jcgl27g02xn0bi09dzxqy2xzjbs6s4-a1648 URL: nar/0rzw45bfnvqnh9s7n7z02g2rw1528yfcrnc671dlp7yg1az3fz8z.nar.zst1649 Compression: zstd1650 NarHash: sha256:0rzw45bfnvqnh9s7n7z02g2rw1528yfcrnc671dlp7yg1az3fz8z1651 NarSize: 2561652 References: /private/var/tb/1/scratch/8499ef2246bbc144/build/TestClientPushesUseOnePush152811681/001/store/slmxksarkk174q4vgbr5lcs0fnd39nsm-shared-dep1653 CA: text:sha256:1gz56cs5c2n945bgqrg1rvl295lqx7rgwd8966lvsd4348zwnkwp1654 client_pushes_test.go:97: Retrieved narinfo from S3:1655 StorePath: /private/var/tb/1/scratch/8499ef2246bbc144/build/TestClientPushesUseOnePush152811681/001/store/1bawdyz77xp300r66gavvqcryixqn55i-b1656 URL: nar/0rzw45bfnvqnh9s7n7z02g2rw1528yfcrnc671dlp7yg1az3fz8z.nar.zst1657 Compression: zstd1658 NarHash: sha256:0rzw45bfnvqnh9s7n7z02g2rw1528yfcrnc671dlp7yg1az3fz8z1659 NarSize: 2561660 References: /private/var/tb/1/scratch/8499ef2246bbc144/build/TestClientPushesUseOnePush152811681/001/store/slmxksarkk174q4vgbr5lcs0fnd39nsm-shared-dep1661 CA: text:sha256:1gz56cs5c2n945bgqrg1rvl295lqx7rgwd8966lvsd4348zwnkwp16622026/11/06 08:14:04 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=016632026/11/06 08:14:04 WARN Failed to register uploaded object key=4qljldddv1vab4zr7rwwhr4n9j30n1d5.narinfo error="server returned 404: 404 page not found\n"16642026/11/06 08:14:04 INFO Received complete push request method=POST path=/api/pushes/1/complete16652026/11/06 08:14:04 WARN Failed to register uploaded object key=jwylqr5dj218z78176dkyvivgp8nn9y6.narinfo error="server returned 404: 404 page not found\n"16662026/11/06 08:14:04 INFO Completed push id=1 objects=6 duration=32.8945ms16672026/11/06 08:14:04 INFO Upload complete. (425ms)1668=== NAME TestClientSharedPathCommittedMidPush1669 client_integration_test.go:727: Retrieved narinfo from S3:16702026/11/06 08:14:04 INFO Vacuumed table table=pending_closures1671 StorePath: /private/var/tb/1/scratch/8499ef2246bbc144/build/TestClientSharedPathCommittedMidPush2755899898/001/store/4qljldddv1vab4zr7rwwhr4n9j30n1d5-shared-dep1672 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1673 Compression: zstd1674 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821675 NarSize: 1361676 References: 1677 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1678 client_integration_test.go:727: Retrieved narinfo from S3:1679 StorePath: /private/var/tb/1/scratch/8499ef2246bbc144/build/TestClientSharedPathCommittedMidPush2755899898/001/store/jwylqr5dj218z78176dkyvivgp8nn9y6-top1680 URL: nar/1msncs21ks1zws4p0sc5y70nc5flsi0jicrxa014fnr2az5jnslr.nar.zst1681 Compression: zstd1682 NarHash: sha256:1msncs21ks1zws4p0sc5y70nc5flsi0jicrxa014fnr2az5jnslr1683 NarSize: 2641684 References: /private/var/tb/1/scratch/8499ef2246bbc144/build/TestClientSharedPathCommittedMidPush2755899898/001/store/4qljldddv1vab4zr7rwwhr4n9j30n1d5-shared-dep1685 CA: text:sha256:1a7hj8vxw1wwxqhbziyhmb9sirkm2g0gb3l5c6mrbmjdz1443mj91686--- PASS: TestClientPushesUseOnePush (7.96s)1687=== CONT TestParseSingleRange/start_far_past_EOF1688=== CONT TestParseSingleRange/start_past_EOF1689=== CONT TestParseSingleRange/single_byte1690=== CONT TestParseSingleRange/suffix_exceeds_size1691=== CONT TestParseSingleRange/suffix1692=== CONT TestParseSingleRange/end_clamped_to_size1693=== CONT TestParseSingleRange/open-ended1694=== CONT TestParseSingleRange/closed1695=== CONT TestParseSingleRange/malformed_end_before_start1696=== CONT TestParseSingleRange/malformed_both_empty1697=== CONT TestParseSingleRange/malformed_no_dash1698=== CONT TestParseSingleRange/multi-range_ignored1699=== CONT TestParseSingleRange/unknown_unit1700--- PASS: TestParseSingleRange (0.00s)1701 --- PASS: TestParseSingleRange/none (0.00s)1702 --- PASS: TestParseSingleRange/start_far_past_EOF (0.00s)1703 --- PASS: TestParseSingleRange/start_past_EOF (0.00s)1704 --- PASS: TestParseSingleRange/single_byte (0.00s)1705 --- PASS: TestParseSingleRange/suffix_exceeds_size (0.00s)1706 --- PASS: TestParseSingleRange/suffix (0.00s)1707 --- PASS: TestParseSingleRange/end_clamped_to_size (0.00s)1708 --- PASS: TestParseSingleRange/open-ended (0.00s)1709 --- PASS: TestParseSingleRange/closed (0.00s)1710 --- PASS: TestParseSingleRange/malformed_end_before_start (0.00s)1711 --- PASS: TestParseSingleRange/malformed_both_empty (0.00s)1712 --- PASS: TestParseSingleRange/malformed_no_dash (0.00s)1713 --- PASS: TestParseSingleRange/multi-range_ignored (0.00s)1714 --- PASS: TestParseSingleRange/unknown_unit (0.00s)1715=== CONT TestPresentNotReportedWhileGCDeletesClosure/fresh17162026/11/06 08:14:05 INFO Vacuumed table table=pending_objects17172026/11/06 08:14:05 INFO Vacuumed table table=multipart_uploads17182026/11/06 08:14:05 INFO Vacuumed table table=closures17192026/11/06 08:14:05 INFO Vacuumed table table=objects1720--- PASS: TestClientSharedPathCommittedMidPush (7.77s)1721=== CONT TestPush_RejectsBadRequests/root_not_in_objects17222026/11/06 08:14:05 INFO Received push request method=POST path=/api/pushes1723=== CONT TestPush_RejectsBadRequests/no_objects17242026/11/06 08:14:05 INFO Received push request method=POST path=/api/pushes1725=== CONT TestPush_RejectsBadRequests/bad_root17262026/11/06 08:14:05 INFO Received push request method=POST path=/api/pushes1727=== CONT TestPush_RejectsBadRequests/no_roots17282026/11/06 08:14:05 INFO Received push request method=POST path=/api/pushes1729=== CONT TestPendingClosureWriteTimeout/empty1730=== CONT TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline1731--- PASS: TestPush_RejectsBadRequests (4.91s)1732 --- PASS: TestPush_RejectsBadRequests/root_not_in_objects (0.01s)1733 --- PASS: TestPush_RejectsBadRequests/no_objects (0.00s)1734 --- PASS: TestPush_RejectsBadRequests/bad_root (0.00s)1735 --- PASS: TestPush_RejectsBadRequests/no_roots (0.00s)1736=== NAME TestClientWithDependencies1737 client_integration_test.go:660: Built derivation: /private/var/tb/1/scratch/8499ef2246bbc144/build/TestClientWithDependencies3947222200/001/store/8jkr13mgvw232pxc920ylfp7gnjznrsr-test-script1738=== NAME TestClientMultipleUploads1739 client_integration_test.go:405: Created store path 0: /private/var/tb/1/scratch/8499ef2246bbc144/build/TestClientMultipleUploads156581545/001/store/j492pc558fhdal24ajpk981i6pkmi19d-test-file-0.txt1740=== NAME TestClientWithDependencies1741 client_integration_test.go:662: Found 1 dependencies (including self)1742=== NAME TestClientMultipleUploads1743 client_integration_test.go:405: Created store path 1: /private/var/tb/1/scratch/8499ef2246bbc144/build/TestClientMultipleUploads156581545/001/store/lvqgm3fs56118qg4bj1rb7r92q1i2h1l-test-file-1.txt17442026/11/06 08:14:05 INFO Received push request method=POST path=/api/pushes1745 client_integration_test.go:405: Created store path 2: /private/var/tb/1/scratch/8499ef2246bbc144/build/TestClientMultipleUploads156581545/001/store/wavwgi3g906k7lcgyiya31sy3ppnssy9-test-file-2.txt17462026/11/06 08:14:05 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)17472026/11/06 08:14:05 INFO Uploading 8jkr13mgvw232pxc920ylfp7gnjznrsr-test-script (136B)17482026/11/06 08:14:05 WARN Failed to register uploaded object key=8jkr13mgvw232pxc920ylfp7gnjznrsr.ls error="server returned 404: 404 page not found\n"17492026/11/06 08:14:05 WARN Failed to register uploaded object key=nar/1s7yghixzpinyqm7g59kyn3sav81pmnsdi5v63m6x4r2vacy907j.nar.zst error="server returned 404: 404 page not found\n"17502026/11/06 08:14:05 WARN Failed to register uploaded object key=log/zlgckc4xia4k2l89f60l5xk3yvcd71j8-test-script.drv error="server returned 404: 404 page not found\n"17512026/11/06 08:14:05 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign17522026/11/06 08:14:05 INFO Signed narinfos id=1 count=117532026/11/06 08:14:05 INFO Uploading 1 narinfos1754=== NAME TestClientIntegration1755 client_integration_test.go:291: Created store path: /private/var/tb/1/scratch/8499ef2246bbc144/build/TestClientIntegration3150713582/002/store/4bnb4193jp8pwmw9xh5yvvf682zidb07-test-file.txt17562026/11/06 08:14:05 INFO Received push request method=POST path=/api/pushes17572026/11/06 08:14:05 INFO Uploading 3 paths to 127.0.0.1 (0 already cached)17582026/11/06 08:14:05 INFO Uploading lvqgm3fs56118qg4bj1rb7r92q1i2h1l-test-file-1.txt (160B)17592026/11/06 08:14:05 INFO Uploading wavwgi3g906k7lcgyiya31sy3ppnssy9-test-file-2.txt (160B)17602026/11/06 08:14:05 INFO Uploading j492pc558fhdal24ajpk981i6pkmi19d-test-file-0.txt (160B)17612026/11/06 08:14:05 WARN Failed to register uploaded object key=8jkr13mgvw232pxc920ylfp7gnjznrsr.narinfo error="server returned 404: 404 page not found\n"17622026/11/06 08:14:05 INFO Received complete push request method=POST path=/api/pushes/1/complete17632026/11/06 08:14:05 INFO Completed push id=1 objects=4 duration=52.501458ms17642026/11/06 08:14:05 INFO Upload complete. (388ms)1765=== NAME TestClientWithDependencies1766 client_integration_test.go:664: Skipping nix copy test - isolated store (/private/var/tb/1/scratch/8499ef2246bbc144/build/TestClientWithDependencies3947222200/001/store) requires matching store prefix17672026/11/06 08:14:05 WARN Failed to register uploaded object key=j492pc558fhdal24ajpk981i6pkmi19d.ls error="server returned 404: 404 page not found\n"17682026/11/06 08:14:05 WARN Failed to register uploaded object key=wavwgi3g906k7lcgyiya31sy3ppnssy9.ls error="server returned 404: 404 page not found\n"17692026/11/06 08:14:05 WARN Failed to register uploaded object key=lvqgm3fs56118qg4bj1rb7r92q1i2h1l.ls error="server returned 404: 404 page not found\n"17702026/11/06 08:14:05 WARN Failed to register uploaded object key=nar/1823g6vx4q5zqvr73m7lkq1wpk40fin7bsc792di430yk7sg4lka.nar.zst error="server returned 404: 404 page not found\n"17712026/11/06 08:14:05 WARN Failed to register uploaded object key=nar/13p9pqi0ga6fx2apcwls9hjnv7nmf740ggpn5zvfzdsp5vz2bbg4.nar.zst error="server returned 404: 404 page not found\n"17722026/11/06 08:14:05 INFO Received push request method=POST path=/api/pushes17732026/11/06 08:14:05 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign17742026/11/06 08:14:05 WARN Failed to register uploaded object key=nar/0ahq3izw3h0b0c08p3xdfclh758fwxnp85ccvflasb4vnfsv50ri.nar.zst error="server returned 404: 404 page not found\n"17752026/11/06 08:14:05 INFO Signed narinfos id=1 count=317762026/11/06 08:14:05 INFO Uploading 3 narinfos17772026/11/06 08:14:05 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)17782026/11/06 08:14:05 INFO Uploading 4bnb4193jp8pwmw9xh5yvvf682zidb07-test-file.txt (152B)17792026/11/06 08:14:05 WARN Failed to register uploaded object key=lvqgm3fs56118qg4bj1rb7r92q1i2h1l.narinfo error="server returned 404: 404 page not found\n"17802026/11/06 08:14:05 WARN Failed to register uploaded object key=wavwgi3g906k7lcgyiya31sy3ppnssy9.narinfo error="server returned 404: 404 page not found\n"17812026/11/06 08:14:05 INFO Received complete push request method=POST path=/api/pushes/1/complete17822026/11/06 08:14:05 WARN Failed to register uploaded object key=j492pc558fhdal24ajpk981i6pkmi19d.narinfo error="server returned 404: 404 page not found\n"17832026/11/06 08:14:05 WARN Failed to register uploaded object key=4bnb4193jp8pwmw9xh5yvvf682zidb07.ls error="server returned 404: 404 page not found\n"17842026/11/06 08:14:05 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign17852026/11/06 08:14:05 WARN Failed to register uploaded object key=nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst error="server returned 404: 404 page not found\n"17862026/11/06 08:14:05 INFO Signed narinfos id=1 count=117872026/11/06 08:14:05 INFO Uploading 1 narinfos1788--- PASS: TestClientWithDependencies (8.36s)1789=== CONT TestPendingClosureWriteTimeout/670k_objects17902026/11/06 08:14:05 INFO Completed push id=1 objects=9 duration=49.744417ms1791=== CONT TestPendingClosureWriteTimeout/400_objects1792=== CONT TestProxyWriteTimeout/narinfo1793=== CONT TestProxyWriteTimeout/10_GiB_nar1794=== CONT TestProxyWriteTimeout/unknown_size17952026/11/06 08:14:05 INFO Upload complete. (413ms)1796=== CONT TestProxyWriteTimeout/1_GiB_nar1797=== NAME TestClientMultipleUploads1798 client_integration_test.go:416: Uploaded 3 paths in 455.4395ms1799--- PASS: TestProxyWriteTimeout (0.00s)1800 --- PASS: TestProxyWriteTimeout/narinfo (0.00s)1801 --- PASS: TestProxyWriteTimeout/10_GiB_nar (0.00s)1802 --- PASS: TestProxyWriteTimeout/unknown_size (0.00s)1803 --- PASS: TestProxyWriteTimeout/1_GiB_nar (0.00s)1804=== CONT TestResolveDBConnectionString/flag_wins1805=== CONT TestResolveDBConnectionString/PGHOST_allows_empty1806=== CONT TestResolveDBConnectionString/nothing_configured1807=== CONT TestResolveDBConnectionString/missing_file_is_an_error1808=== CONT TestResolveDBConnectionString/file_when_flag_empty1809=== CONT TestForceGCDuringPushOffersSweptObject/before_pending_rows1810--- PASS: TestResolveDBConnectionString (0.02s)1811 --- PASS: TestResolveDBConnectionString/flag_wins (0.00s)1812 --- PASS: TestResolveDBConnectionString/PGHOST_allows_empty (0.00s)1813 --- PASS: TestResolveDBConnectionString/nothing_configured (0.00s)1814 --- PASS: TestResolveDBConnectionString/missing_file_is_an_error (0.00s)1815 --- PASS: TestResolveDBConnectionString/file_when_flag_empty (0.00s)18162026/11/06 08:14:05 INFO Received complete push request method=POST path=/api/pushes/1/complete18172026/11/06 08:14:05 WARN Failed to register uploaded object key=4bnb4193jp8pwmw9xh5yvvf682zidb07.narinfo error="server returned 404: 404 page not found\n"18182026/11/06 08:14:06 INFO Completed push id=1 objects=3 duration=76.363708ms18192026/11/06 08:14:06 INFO Upload complete. (402ms)1820--- PASS: TestClientMultipleUploads (8.18s)1821=== CONT TestForceGCDuringPushOffersSweptObject/after_presence_check18222026/11/06 08:14:06 INFO All 1 paths already cached1823=== NAME TestClientIntegration1824 client_integration_test.go:317: Retrieved narinfo from S3:1825 StorePath: /private/var/tb/1/scratch/8499ef2246bbc144/build/TestClientIntegration3150713582/002/store/4bnb4193jp8pwmw9xh5yvvf682zidb07-test-file.txt1826 URL: nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst1827 Compression: zstd1828 NarHash: sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11829 NarSize: 1521830 References: 1831 CA: fixed:r:sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11832 client_integration_test.go:318: Retrieved .ls file from S3 (compressed size: 77 bytes)1833 client_integration_test.go:318: Decompressed .ls content (64 bytes):1834 {"version":1,"root":{"type":"regular","size":39,"narOffset":96}}1835--- PASS: TestCacheStatsHandler (7.27s)1836=== CONT TestService_verifyS3ReuploadsStaleNarinfo/lost,_other_NAR_pushed18372026/11/06 08:14:06 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=018382026/11/06 08:14:06 INFO Received create pin request method=POST path=/api/pins/myapp18392026/11/06 08:14:06 INFO Created/updated pin name=myapp store_path=/private/var/tb/1/scratch/8499ef2246bbc144/build/TestPinProtectsFromGC4244804449/001/store/ijdl0i773f044l8pl6jjld6hwkh36bfy-pinned-file.txt narinfo_key=ijdl0i773f044l8pl6jjld6hwkh36bfy.narinfo18402026/11/06 08:14:06 INFO Starting cleanup of old closures method=DELETE path=/api/closures18412026/11/06 08:14:06 INFO Garbage collection started18422026/11/06 08:14:06 INFO Aborted multipart uploads count=0 kept=018432026/11/06 08:14:06 WARN Force mode enabled - objects will be deleted immediately without grace period18442026/11/06 08:14:06 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=01845=== NAME TestClientCADerivations18462026/11/06 08:14:06 INFO Vacuumed table table=pending_closures1847 client_ca_test.go:136: Built CA derivation: /private/var/tb/1/scratch/8499ef2246bbc144/build/TestClientCADerivations1574347271/001/store/8vd57n65md95bwr4lsfjzz9az6i7n917-ca-test18482026/11/06 08:14:06 INFO Vacuumed table table=pending_objects18492026/11/06 08:14:06 INFO Vacuumed table table=multipart_uploads1850=== RUN TestService_RequireScope_OIDC/builder_may_write1851=== PAUSE TestService_RequireScope_OIDC/builder_may_write1852=== RUN TestService_RequireScope_OIDC/builder_may_not_admin1853=== PAUSE TestService_RequireScope_OIDC/builder_may_not_admin1854=== RUN TestService_RequireScope_OIDC/ops_may_admin1855=== PAUSE TestService_RequireScope_OIDC/ops_may_admin1856=== RUN TestService_RequireScope_OIDC/ops_may_not_write1857=== PAUSE TestService_RequireScope_OIDC/ops_may_not_write1858=== RUN TestService_RequireScope_OIDC/reader_may_not_write1859=== PAUSE TestService_RequireScope_OIDC/reader_may_not_write1860=== RUN TestService_RequireScope_OIDC/static_token_may_admin1861=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin1862=== RUN TestService_RequireScope_OIDC/static_token_may_write1863=== PAUSE TestService_RequireScope_OIDC/static_token_may_write1864=== RUN TestService_RequireScope_OIDC/reader_may_read1865=== PAUSE TestService_RequireScope_OIDC/reader_may_read1866=== RUN TestService_RequireScope_OIDC/writer_implies_read1867=== PAUSE TestService_RequireScope_OIDC/writer_implies_read1868=== RUN TestService_RequireScope_OIDC/anonymous_may_not_read1869=== PAUSE TestService_RequireScope_OIDC/anonymous_may_not_read1870=== RUN TestService_RequireScope_OIDC/reader_may_read_with_netrc1871=== PAUSE TestService_RequireScope_OIDC/reader_may_read_with_netrc1872=== RUN TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1873=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1874=== RUN TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read1875=== PAUSE TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read1876=== RUN TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1877=== PAUSE TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1878=== CONT TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost,_second_pushed18792026/11/06 08:14:06 INFO Vacuumed table table=closures18802026/11/06 08:14:06 INFO Vacuumed table table=objects18812026/11/06 08:14:06 INFO Received push request method=POST path=/api/pushes18822026/11/06 08:14:06 INFO Object in database but missing from S3 key=4bnb4193jp8pwmw9xh5yvvf682zidb07.ls18832026/11/06 08:14:06 WARN Found objects in DB but missing from S3, will re-upload count=118842026/11/06 08:14:06 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)1885=== NAME TestClientCADerivations1886 client_ca_test.go:139: Found 1 dependencies (including self)18872026/11/06 08:14:06 INFO Received complete push request method=POST path=/api/pushes/2/complete18882026/11/06 08:14:06 WARN Failed to register uploaded object key=4bnb4193jp8pwmw9xh5yvvf682zidb07.ls error="server returned 404: 404 page not found\n"18892026/11/06 08:14:06 INFO Completed push id=2 objects=3 duration=1.207667ms18902026/11/06 08:14:06 INFO Upload complete. (172ms)1891=== NAME TestClientIntegration1892 client_integration_test.go:335: Retrieved .ls file from S3 (compressed size: 62 bytes)1893 client_integration_test.go:335: Decompressed .ls content (49 bytes):1894 {"version":1,"root":{"type":"regular","size":39}}18952026/11/06 08:14:06 INFO Received push request method=POST path=/api/pushes18962026/11/06 08:14:06 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)18972026/11/06 08:14:06 INFO Uploading 8vd57n65md95bwr4lsfjzz9az6i7n917-ca-test (144B)1898--- PASS: TestService_ReadScope_PublicByDefault (7.91s)1899=== CONT TestService_verifyS3ReuploadsStaleNarinfo/lost,_same_NAR_pushed19002026/11/06 08:14:06 WARN Failed to register uploaded object key=8vd57n65md95bwr4lsfjzz9az6i7n917.ls error="server returned 404: 404 page not found\n"19012026/11/06 08:14:06 WARN Failed to register uploaded object key=log/kiivqr0cshaslkmin7ky1vx690xnpm0i-ca-test.drv error="server returned 404: 404 page not found\n"19022026/11/06 08:14:06 WARN Failed to register uploaded object key=nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst error="server returned 404: 404 page not found\n"19032026/11/06 08:14:06 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign19042026/11/06 08:14:06 INFO Signed narinfos id=1 count=119052026/11/06 08:14:06 INFO Uploading 1 narinfos19062026/11/06 08:14:06 INFO Received complete push request method=POST path=/api/pushes/1/complete19072026/11/06 08:14:06 WARN Failed to register uploaded object key=8vd57n65md95bwr4lsfjzz9az6i7n917.narinfo error="server returned 404: 404 page not found\n"19082026/11/06 08:14:06 INFO Received push request method=POST path=/api/pushes19092026/11/06 08:14:07 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)19102026/11/06 08:14:07 INFO Completed push id=1 objects=4 duration=43.54475ms19112026/11/06 08:14:07 INFO Upload complete. (499ms)1912=== NAME TestClientCADerivations1913 client_ca_test.go:180: Narinfo contains CA field: StorePath: /private/var/tb/1/scratch/8499ef2246bbc144/build/TestClientCADerivations1574347271/001/store/8vd57n65md95bwr4lsfjzz9az6i7n917-ca-test1914 URL: nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst1915 Compression: zstd1916 NarHash: sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1917 NarSize: 1441918 References: 1919 Deriver: /private/var/tb/1/scratch/8499ef2246bbc144/build/TestClientCADerivations1574347271/001/store/kiivqr0cshaslkmin7ky1vx690xnpm0i-ca-test.drv1920 CA: fixed:r:sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1921 client_ca_test.go:185: Checking for realisation files in S3...1922 client_ca_test.go:207: No realisation files uploaded - this is expected for locally built CA derivations1923 client_ca_test.go:208: Locally built CA derivations don't have DrvOutput IDs until they're substituted from a cache19242026/11/06 08:14:07 INFO Received complete push request method=POST path=/api/pushes/3/complete19252026/11/06 08:14:07 WARN Failed to register uploaded object key=4bnb4193jp8pwmw9xh5yvvf682zidb07.ls error="server returned 404: 404 page not found\n"19262026/11/06 08:14:07 INFO Completed push id=3 objects=3 duration=68.716917ms19272026/11/06 08:14:07 INFO Upload complete. (224ms)1928=== NAME TestClientIntegration1929 client_integration_test.go:352: Retrieved .ls file from S3 (compressed size: 62 bytes)1930 client_integration_test.go:352: Decompressed .ls content (49 bytes):1931 {"version":1,"root":{"type":"regular","size":39}}1932 client_integration_test.go:363: Testing garbage collection...1933=== NAME TestClientCADerivations1934 client_ca_test.go:258: nix copy output: error: binary cache 's3://bucket76?endpoint=http://localhost:56639®ion=eu-west-1' is for Nix stores with prefix '/nix/store', not '/private/var/tb/1/scratch/8499ef2246bbc144/build/TestClientCADerivations1574347271/001/store'1935 client_ca_test.go:259: nix copy failed (might be expected with isolated stores): exit status 119362026/11/06 08:14:07 INFO Starting cleanup of old closures method=DELETE path=/api/closures19372026/11/06 08:14:07 INFO Garbage collection started19382026/11/06 08:14:07 INFO Aborted multipart uploads count=0 kept=01939--- PASS: TestService_healthCheckHandler (7.60s)1940=== CONT TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost19412026/11/06 08:14:07 WARN Force mode enabled - objects will be deleted immediately without grace period1942--- PASS: TestClientCADerivations (8.59s)1943=== CONT TestService_verifyS3ReuploadsStaleNarinfo/intact,_other_NAR_pushed19442026/11/06 08:14:07 INFO Received cleanup request method=DELETE path=/api/pending_closures19452026/11/06 08:14:07 INFO Aborted multipart uploads count=0 kept=019462026/11/06 08:14:07 INFO Received uploads request method=POST path=/api/pending_closures19472026/11/06 08:14:07 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=019482026/11/06 08:14:07 INFO Vacuumed table table=pending_closures19492026/11/06 08:14:07 INFO Vacuumed table table=pending_objects19502026/11/06 08:14:07 INFO Vacuumed table table=multipart_uploads19512026/11/06 08:14:07 INFO Received cleanup request method=DELETE path=/api/pending_closures19522026/11/06 08:14:07 INFO Aborted multipart uploads count=1 kept=019532026/11/06 08:14:08 INFO Vacuumed table table=closures19542026/11/06 08:14:08 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete19552026-11-06 08:14:08.022 UTC [98278] ERROR: Closure does not exist: id=119562026-11-06 08:14:08.022 UTC [98278] CONTEXT: PL/pgSQL function commit_pending_closure(bigint) line 13 at RAISE19572026-11-06 08:14:08.022 UTC [98278] STATEMENT: -- name: CommitPendingClosure :one1958 SELECT commit_pending_closure($1::bigint)::bigint1959 1960--- PASS: TestService_cleanupPendingClosuresHandler (8.48s)1961=== CONT TestClientErrorHandling/InvalidStorePath19622026/11/06 08:14:08 INFO Vacuumed table table=objects19632026/11/06 08:14:08 INFO Received push request method=POST path=/api/pushes1964=== NAME TestPinProtectsFromGC1965 client_integration_test.go:887: Pin successfully protected closure from garbage collection19662026/11/06 08:14:08 INFO Received complete push request method=POST path=/api/pushes/1/complete19672026/11/06 08:14:08 INFO Completed push id=1 objects=4 duration=48.715083ms19682026/11/06 08:14:08 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete19692026/11/06 08:14:08 INFO Completed upload id=2 objects=2 duration=915.625µs1970--- PASS: TestMetricsCommit (8.58s)1971=== CONT TestClientErrorHandling/ServerNotAvailable1972--- PASS: TestPinProtectsFromGC (11.46s)1973=== CONT TestClientErrorHandling/InvalidAuthToken1974--- PASS: TestDeleteClosuresRacingPins (12.66s)1975=== CONT TestCacheConfigHandler/full_config,_no_issuer1976=== CONT TestCacheConfigHandler/no_signing_keys1977=== CONT TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1978=== CONT TestCacheConfigHandler/no_cache_url_configured1979--- PASS: TestCacheConfigHandler (0.00s)1980 --- PASS: TestCacheConfigHandler/full_config,_no_issuer (0.00s)1981 --- PASS: TestCacheConfigHandler/no_signing_keys (0.00s)1982 --- PASS: TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator (0.00s)1983 --- PASS: TestCacheConfigHandler/no_cache_url_configured (0.00s)1984=== CONT TestUploadHandlersRejectOversizedBody/create_pending_closure19852026/11/06 08:14:08 INFO Received uploads request method=POST path=/19862026/11/06 08:14:08 WARN mTLS auth: subject not in bound subjects subject="CN=reader"19872026/11/06 08:14:08 WARN mTLS auth: subject not in bound subjects subject="CN=reader"1988--- PASS: TestService_NativeMTLS (8.69s)1989=== CONT TestUploadHandlersRejectOversizedBody/complete_multipart19902026/11/06 08:14:08 INFO Received complete multipart upload request method=POST path=/1991=== CONT TestUploadHandlersRejectOversizedBody/request_more_parts19922026/11/06 08:14:08 INFO Received request for more parts method=POST path=/1993=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info19942026/11/06 08:14:08 INFO Received uploads request method=POST path=/1995=== CONT TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key19962026/11/06 08:14:08 INFO Received complete multipart upload request method=POST path=/1997=== CONT TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key19982026/11/06 08:14:08 INFO Received request for more parts method=POST path=/1999=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal20002026/11/06 08:14:08 INFO Received uploads request method=POST path=/2001--- PASS: TestUploadHandlersRejectInvalidKeys (0.00s)2002 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info (0.00s)2003 --- PASS: TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key (0.00s)2004 --- PASS: TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key (0.01s)2005 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal (0.00s)2006=== CONT TestServerTLSConfig/no_client_CA2007=== CONT TestServerTLSConfig/not_a_PEM_file2008=== CONT TestServerTLSConfig/missing_CA_file2009--- PASS: TestServerTLSConfig (0.01s)2010 --- PASS: TestServerTLSConfig/no_client_CA (0.00s)2011 --- PASS: TestServerTLSConfig/not_a_PEM_file (0.02s)2012 --- PASS: TestServerTLSConfig/missing_CA_file (0.00s)2013=== CONT TestGCEndsOnShutdown/before_the_run20142026/11/06 08:14:08 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/present2015--- PASS: TestMetricsInventory (8.43s)2016=== CONT TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark20172026/11/06 08:14:09 WARN Request failed, retrying attempt=2 backoff=210.523465ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present2018=== CONT TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete2019--- PASS: TestUploadHandlersRejectOversizedBody (0.14s)2020 --- PASS: TestUploadHandlersRejectOversizedBody/complete_multipart (0.02s)2021 --- PASS: TestUploadHandlersRejectOversizedBody/request_more_parts (0.06s)2022 --- PASS: TestUploadHandlersRejectOversizedBody/create_pending_closure (0.50s)20232026/11/06 08:14:09 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=02024=== NAME TestClientIntegration2025 client_integration_test.go:370: Objects in database after GC:2026 client_integration_test.go:370: Successfully deleted all objects with GC --force20272026/11/06 08:14:09 WARN Request failed, retrying attempt=3 backoff=403.306755ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present2028--- PASS: TestClientIntegration (10.98s)2029=== CONT TestService_RequireScope_OIDC/builder_may_write2030=== CONT TestService_RequireScope_OIDC/reader_may_read2031=== CONT TestService_RequireScope_OIDC/empty_netrc_password_may_not_read2032=== CONT TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read20332026/11/06 08:14:09 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]2034=== CONT TestService_RequireScope_OIDC/static_token_may_admin_with_netrc2035=== CONT TestService_RequireScope_OIDC/reader_may_read_with_netrc2036=== CONT TestService_RequireScope_OIDC/anonymous_may_not_read2037=== CONT TestService_RequireScope_OIDC/writer_implies_read2038=== CONT TestService_RequireScope_OIDC/reader_may_not_write2039=== CONT TestService_RequireScope_OIDC/static_token_may_write2040=== CONT TestService_RequireScope_OIDC/static_token_may_admin2041=== CONT TestService_RequireScope_OIDC/ops_may_admin2042=== CONT TestService_RequireScope_OIDC/ops_may_not_write2043=== CONT TestService_RequireScope_OIDC/builder_may_not_admin2044--- PASS: TestService_RequireScope_OIDC (7.76s)2045 --- PASS: TestService_RequireScope_OIDC/builder_may_write (0.00s)2046 --- PASS: TestService_RequireScope_OIDC/reader_may_read (0.00s)2047 --- PASS: TestService_RequireScope_OIDC/empty_netrc_password_may_not_read (0.00s)2048 --- PASS: TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read (0.00s)2049 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin_with_netrc (0.00s)2050 --- PASS: TestService_RequireScope_OIDC/reader_may_read_with_netrc (0.00s)2051 --- PASS: TestService_RequireScope_OIDC/anonymous_may_not_read (0.00s)2052 --- PASS: TestService_RequireScope_OIDC/writer_implies_read (0.00s)2053 --- PASS: TestService_RequireScope_OIDC/reader_may_not_write (0.00s)2054 --- PASS: TestService_RequireScope_OIDC/static_token_may_write (0.00s)2055 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin (0.00s)2056 --- PASS: TestService_RequireScope_OIDC/ops_may_admin (0.00s)2057 --- PASS: TestService_RequireScope_OIDC/ops_may_not_write (0.00s)2058 --- PASS: TestService_RequireScope_OIDC/builder_may_not_admin (0.00s)20592026/11/06 08:14:09 WARN Request failed, retrying attempt=4 backoff=814.894945ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present20602026/11/06 08:14:09 WARN readiness check failed error="closed pool"2061--- PASS: TestService_readinessHandler (7.08s)2062=== NAME TestNARDeduplicationMetadataUploadBug2063 metadata_upload_test.go:48: First store path: /private/var/tb/1/scratch/8499ef2246bbc144/build/TestNARDeduplicationMetadataUploadBug66680011/001/store/g6l3c16gij422mp0fnl0fn1f76zwyn2g-file1.txt20642026/11/06 08:14:09 INFO Received push request method=POST path=/api/pushes20652026/11/06 08:14:09 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)20662026/11/06 08:14:09 INFO Uploading g6l3c16gij422mp0fnl0fn1f76zwyn2g-file1.txt (160B)20672026/11/06 08:14:10 WARN Failed to register uploaded object key=g6l3c16gij422mp0fnl0fn1f76zwyn2g.ls error="server returned 404: 404 page not found\n"2068--- PASS: TestService_ReadAuthMiddleware (6.83s)20692026/11/06 08:14:10 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign20702026/11/06 08:14:10 WARN Failed to register uploaded object key=nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst error="server returned 404: 404 page not found\n"20712026/11/06 08:14:10 INFO Signed narinfos id=1 count=120722026/11/06 08:14:10 INFO Uploading 1 narinfos20732026/11/06 08:14:10 INFO Received complete push request method=POST path=/api/pushes/1/complete20742026/11/06 08:14:10 WARN Failed to register uploaded object key=g6l3c16gij422mp0fnl0fn1f76zwyn2g.narinfo error="server returned 404: 404 page not found\n"20752026/11/06 08:14:10 INFO Completed push id=1 objects=3 duration=43.400583ms20762026/11/06 08:14:10 INFO Upload complete. (332ms)2077=== NAME TestNARDeduplicationMetadataUploadBug2078 metadata_upload_test.go:54: Retrieved narinfo from S3:2079 StorePath: /private/var/tb/1/scratch/8499ef2246bbc144/build/TestNARDeduplicationMetadataUploadBug66680011/001/store/g6l3c16gij422mp0fnl0fn1f76zwyn2g-file1.txt2080 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst2081 Compression: zstd2082 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf2083 NarSize: 1602084 References: 2085 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf2086 metadata_upload_test.go:55: Retrieved .ls file from S3 (compressed size: 77 bytes)2087 metadata_upload_test.go:55: Decompressed .ls content (64 bytes):2088 {"version":1,"root":{"type":"regular","size":44,"narOffset":96}}2089 metadata_upload_test.go:64: Second store path (same content): /private/var/tb/1/scratch/8499ef2246bbc144/build/TestNARDeduplicationMetadataUploadBug66680011/001/store/8anpq1k2x8fkqwzmd7pmazcz085c9aqg-file2.txt20902026/11/06 08:14:10 WARN Request failed, retrying attempt=5 backoff=1.653517673s error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present20912026/11/06 08:14:10 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted,O=Other"20922026/11/06 08:14:10 WARN mTLS auth: bound subjects configured but subject DN unavailable20932026/11/06 08:14:10 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted"2094--- PASS: TestService_AuthMiddleware_MTLSBoundSubjects (6.74s)20952026/11/06 08:14:10 INFO Received push request method=POST path=/api/pushes20962026/11/06 08:14:10 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)20972026/11/06 08:14:10 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign20982026/11/06 08:14:10 INFO Signed narinfos id=2 count=120992026/11/06 08:14:10 INFO Uploading 1 narinfos21002026/11/06 08:14:10 WARN Failed to register uploaded object key=8anpq1k2x8fkqwzmd7pmazcz085c9aqg.ls error="server returned 404: 404 page not found\n"21012026/11/06 08:14:10 INFO Received complete push request method=POST path=/api/pushes/2/complete21022026/11/06 08:14:10 WARN Failed to register uploaded object key=8anpq1k2x8fkqwzmd7pmazcz085c9aqg.narinfo error="server returned 404: 404 page not found\n"21032026/11/06 08:14:10 INFO Completed push id=2 objects=3 duration=2.615667ms21042026/11/06 08:14:10 INFO Upload complete. (186ms)2105=== NAME TestNARDeduplicationMetadataUploadBug2106 metadata_upload_test.go:76: Retrieved narinfo from S3:2107 StorePath: /private/var/tb/1/scratch/8499ef2246bbc144/build/TestNARDeduplicationMetadataUploadBug66680011/001/store/8anpq1k2x8fkqwzmd7pmazcz085c9aqg-file2.txt2108 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst2109 Compression: zstd2110 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf2111 NarSize: 1602112 References: 2113 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf2114 metadata_upload_test.go:77: Retrieved .ls file from S3 (compressed size: 62 bytes)2115 metadata_upload_test.go:77: Decompressed .ls content (49 bytes):2116 {"version":1,"root":{"type":"regular","size":44}}2117--- PASS: TestNARDeduplicationMetadataUploadBug (9.48s)2118=== RUN TestService_AuthMiddleware_OIDC/valid_OIDC_token2119=== PAUSE TestService_AuthMiddleware_OIDC/valid_OIDC_token2120=== RUN TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected2121=== PAUSE TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected2122=== RUN TestService_AuthMiddleware_OIDC/malformed_token_rejected2123=== PAUSE TestService_AuthMiddleware_OIDC/malformed_token_rejected2124=== RUN TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2125=== PAUSE TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2126=== CONT TestService_AuthMiddleware_OIDC/valid_OIDC_token2127=== CONT TestService_AuthMiddleware_OIDC/malformed_token_rejected21282026/11/06 08:14:10 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]2129=== CONT TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2130=== CONT TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected21312026/11/06 08:14:10 WARN Authentication failed token_preview=eyJhbGciOi...V1j5MYzI_A token_length=701 oidc_error="no rule matched: claim \"repository_owner\" value [otherorg] not in allowed patterns [myorg]" oidc_provider=test tried_providers=[test]2132--- PASS: TestService_AuthMiddleware_OIDC (7.19s)2133 --- PASS: TestService_AuthMiddleware_OIDC/malformed_token_rejected (0.00s)2134 --- PASS: TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured (0.00s)2135 --- PASS: TestService_AuthMiddleware_OIDC/valid_OIDC_token (0.01s)2136 --- PASS: TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected (0.00s)2137--- PASS: TestService_AuthMiddleware_MTLSProxyHeader (7.08s)21382026/11/06 08:14:12 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-config21392026/11/06 08:14:12 INFO Received uploads request method=POST path=/api/pending_closures21402026/11/06 08:14:12 WARN Request failed, retrying attempt=2 backoff=218.205039ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config2141--- PASS: TestPresentNotReportedWhileGCDeletesClosure (0.00s)2142 --- PASS: TestPresentNotReportedWhileGCDeletesClosure/stale (7.82s)2143 --- PASS: TestPresentNotReportedWhileGCDeletesClosure/fresh (7.41s)21442026/11/06 08:14:12 INFO Received uploads request method=POST path=/api/pending_closures21452026/11/06 08:14:12 INFO Aborted multipart uploads count=0 kept=021462026/11/06 08:14:12 WARN Force mode enabled - objects will be deleted immediately without grace period21472026/11/06 08:14:12 WARN Request failed, retrying attempt=3 backoff=374.137289ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21482026/11/06 08:14:12 INFO Received uploads request method=POST path=/api/pending_closures21492026/11/06 08:14:12 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=021502026/11/06 08:14:12 INFO Vacuumed table table=pending_closures21512026/11/06 08:14:12 INFO Vacuumed table table=pending_objects21522026/11/06 08:14:12 INFO Vacuumed table table=multipart_uploads21532026/11/06 08:14:12 INFO Vacuumed table table=closures21542026/11/06 08:14:12 INFO Vacuumed table table=objects21552026/11/06 08:14:12 WARN Request failed, retrying attempt=4 backoff=775.36527ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21562026/11/06 08:14:13 INFO Received uploads request method=POST path=/api/pending_closures21572026/11/06 08:14:13 INFO Aborted multipart uploads count=0 kept=02158--- PASS: TestPendingClosureWriteTimeout (0.00s)2159 --- PASS: TestPendingClosureWriteTimeout/empty (0.00s)2160 --- PASS: TestPendingClosureWriteTimeout/670k_objects (0.00s)2161 --- PASS: TestPendingClosureWriteTimeout/400_objects (0.00s)2162 --- PASS: TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline (7.95s)21632026/11/06 08:14:13 WARN Force mode enabled - objects will be deleted immediately without grace period21642026/11/06 08:14:13 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=021652026/11/06 08:14:13 INFO Vacuumed table table=pending_closures21662026/11/06 08:14:13 INFO Vacuumed table table=pending_objects21672026/11/06 08:14:13 INFO Vacuumed table table=multipart_uploads21682026/11/06 08:14:13 INFO Vacuumed table table=closures21692026/11/06 08:14:13 INFO Vacuumed table table=objects2170--- PASS: TestForceGCDuringPushOffersSweptObject (0.00s)2171 --- PASS: TestForceGCDuringPushOffersSweptObject/before_pending_rows (6.98s)2172 --- PASS: TestForceGCDuringPushOffersSweptObject/after_presence_check (7.17s)21732026/11/06 08:14:13 INFO Received uploads request method=POST path=/api/pending_closures21742026/11/06 08:14:13 INFO Received uploads request method=POST path=/api/pending_closures21752026/11/06 08:14:13 WARN Request failed, retrying attempt=5 backoff=1.652579626s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21762026/11/06 08:14:13 INFO Received uploads request method=POST path=/api/pending_closures21772026/11/06 08:14:14 INFO Received complete multipart upload request method=POST path=/api/multipart/complete21782026/11/06 08:14:14 INFO Received uploads request method=POST path=/api/pending_closures21792026/11/06 08:14:14 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000100000000000000000000.nar.zst upload_id=NDY2MGFiYzYtMjNiZC00YTcwLTkxZWMtYTE5MDZmMGY4MmUzLjdkODcxNTg1LTIyZjctNGUzMS05ODY2LWE5YzNlYmE5YmY0YXgxNzkzOTUyODUyNzMxOTQ3MDAw parts=1021802026/11/06 08:14:14 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete21812026/11/06 08:14:14 INFO Completed upload id=1 objects=3 duration=14.439375ms21822026/11/06 08:14:14 INFO Received uploads request method=POST path=/api/pending_closures21832026/11/06 08:14:14 INFO Object in database but missing from S3 key=nar/dadb44fdadb44fdadb44fdadb44f000100000000000000000000.nar.zst21842026/11/06 08:14:14 WARN Narinfo references a NAR missing from S3, will re-upload narinfo=dadb44fdadb44fdadb44fdadb44f0001.narinfo21852026/11/06 08:14:15 INFO Received complete multipart upload request method=POST path=/api/multipart/complete21862026/11/06 08:14:15 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000400000000000000000000.nar.zst upload_id=NDY2MGFiYzYtMjNiZC00YTcwLTkxZWMtYTE5MDZmMGY4MmUzLmU5YWUzZTk1LTBjMTUtNGMyZC05OWY5LWMxNGU5ZDNhOGNjNHgxNzkzOTUyODUzMjUzOTM4MDAw parts=1021872026/11/06 08:14:15 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete21882026/11/06 08:14:15 INFO Completed upload id=1 objects=3 duration=13.661625ms21892026/11/06 08:14:15 INFO Received uploads request method=POST path=/api/pending_closures21902026/11/06 08:14:15 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"21912026/11/06 08:14:15 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-config21922026/11/06 08:14:15 INFO Received complete multipart upload request method=POST path=/api/multipart/complete21932026/11/06 08:14:15 WARN Request failed, retrying attempt=2 backoff=184.640129ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21942026/11/06 08:14:15 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000500000000000000000000.nar.zst upload_id=NDY2MGFiYzYtMjNiZC00YTcwLTkxZWMtYTE5MDZmMGY4MmUzLjNlOWRmOTYxLWM2NjctNDI0NS1iOTJmLWJlMjIzNzcxYWJhOXgxNzkzOTUyODUzNTQ2NDA1MDAw parts=1021952026/11/06 08:14:15 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete21962026/11/06 08:14:15 INFO Completed upload id=1 objects=3 duration=23.584792ms21972026/11/06 08:14:15 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"21982026/11/06 08:14:15 WARN Request failed, retrying attempt=3 backoff=372.840464ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21992026/11/06 08:14:15 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"22002026/11/06 08:14:15 INFO Received complete multipart upload request method=POST path=/api/multipart/complete22012026/11/06 08:14:15 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000300000000000000000000.nar.zst upload_id=NDY2MGFiYzYtMjNiZC00YTcwLTkxZWMtYTE5MDZmMGY4MmUzLjY3N2ZhZTcyLWJmOTgtNDZjZS04YjVlLWJjZjg3OWRhNzcwZngxNzkzOTUyODUzOTA5OTgzMDAw parts=1022022026/11/06 08:14:15 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete22032026/11/06 08:14:15 INFO Completed upload id=1 objects=3 duration=12.641792ms22042026/11/06 08:14:15 INFO Received uploads request method=POST path=/api/pending_closures22052026/11/06 08:14:16 INFO Aborted multipart uploads count=0 kept=022062026/11/06 08:14:16 WARN Force mode enabled - objects will be deleted immediately without grace period22072026-11-06 08:14:16.045 UTC [98431] ERROR: canceling statement due to user request22082026-11-06 08:14:16.045 UTC [98431] STATEMENT: -- name: MarkStaleObjects :execrows2209 WITH RECURSIVE ct AS (2210 SELECT timezone('UTC', now()) AS now2211 ),2212 closure_reach AS (2213 -- Start with all closure keys2214 SELECT o.key, o.refs2215 FROM objects o2216 INNER JOIN closures c ON o.key = c.key2217 UNION2218 -- Recursively add all referenced objects2219 SELECT o.key, o.refs2220 FROM objects o2221 INNER JOIN closure_reach cr ON o.key = ANY(cr.refs)2222 ),2223 reachable_objects AS (2224 SELECT DISTINCT key FROM closure_reach2225 ),2226 stale_objects AS (2227 SELECT o.key2228 FROM objects AS o, ct2229 WHERE2230 NOT EXISTS (2231 SELECT 12232 FROM reachable_objects ro2233 WHERE ro.key = o.key2234 )2235 AND NOT EXISTS (2236 SELECT 12237 FROM pending_objects AS po2238 WHERE po.key = o.key2239 )2240 AND o.deleted_at IS NULL -- Only mark fresh objects2241 ORDER BY o.key COLLATE "C" -- lock in key order, like commit_pending_closure2242 FOR UPDATE2243 )2244 UPDATE objects2245 SET2246 deleted_at = ct.now,2247 first_deleted_at = COALESCE(first_deleted_at, ct.now)2248 FROM stale_objects, ct2249 WHERE objects.key = stale_objects.key2250 22512026/11/06 08:14:16 WARN Request failed, retrying attempt=4 backoff=838.941075ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22522026/11/06 08:14:16 INFO Received uploads request method=POST path=/api/pending_closures22532026/11/06 08:14:16 INFO Object in database but missing from S3 key=nar/dadb44fdadb44fdadb44fdadb44f000500000000000000000000.nar.zst22542026/11/06 08:14:16 WARN Found objects in DB but missing from S3, will re-upload count=122552026/11/06 08:14:16 INFO Received complete multipart upload request method=POST path=/api/multipart/complete22562026/11/06 08:14:16 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000200000000000000000000.nar.zst upload_id=NDY2MGFiYzYtMjNiZC00YTcwLTkxZWMtYTE5MDZmMGY4MmUzLmJjZjg5OTQ4LWJlMzctNDI4Ni05ZmQwLWJmMThkNzFmNjhkNHgxNzkzOTUyODU0MzUzNjU2MDAw parts=1022572026/11/06 08:14:16 INFO Aborted multipart uploads count=0 kept=022582026/11/06 08:14:16 WARN Force mode enabled - objects will be deleted immediately without grace period22592026/11/06 08:14:16 ERROR failed to remove object object=nar/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa.nar.zst error="Post \"http://localhost:56639/bucket105/?delete=\": context canceled"2260--- PASS: TestGCEndsOnShutdown (0.00s)2261 --- PASS: TestGCEndsOnShutdown/before_the_run (6.92s)2262 --- PASS: TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark (7.09s)2263 --- PASS: TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete (7.35s)22642026/11/06 08:14:16 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete22652026/11/06 08:14:16 INFO Completed upload id=1 objects=3 duration=10.851417ms22662026/11/06 08:14:16 INFO Received uploads request method=POST path=/api/pending_closures22672026/11/06 08:14:16 INFO Received complete multipart upload request method=POST path=/api/multipart/complete22682026/11/06 08:14:16 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f100400000000000000000000.nar.zst upload_id=NDY2MGFiYzYtMjNiZC00YTcwLTkxZWMtYTE5MDZmMGY4MmUzLjMyOTY4NDljLTgyZTYtNDY3ZS04ZmJjLWZkZGVhZTE1MTU3ZngxNzkzOTUyODU1MjcxMDE4MDAw parts=1022692026/11/06 08:14:16 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete22702026/11/06 08:14:16 INFO Completed upload id=2 objects=3 duration=911.25µs22712026/11/06 08:14:16 WARN Request failed, retrying attempt=5 backoff=1.527665741s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22722026/11/06 08:14:17 INFO Received uploads request method=POST path=/api/pending_closures22732026/11/06 08:14:17 INFO Object in database but missing from S3 key=nar/dadb44fdadb44fdadb44fdadb44f000400000000000000000000.nar.zst22742026/11/06 08:14:17 WARN Narinfo references a NAR missing from S3, will re-upload narinfo=dadb44fdadb44fdadb44fdadb44f0004.narinfo22752026/11/06 08:14:17 INFO Received complete multipart upload request method=POST path=/api/multipart/complete22762026/11/06 08:14:17 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f100300000000000000000000.nar.zst upload_id=NDY2MGFiYzYtMjNiZC00YTcwLTkxZWMtYTE5MDZmMGY4MmUzLjRhMTRkNWQ0LWZmZDItNDc3Ni1hZDNmLTZhYTdlYTBlNTIzM3gxNzkzOTUyODU1OTMwNjA1MDAw parts=1022772026/11/06 08:14:17 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete22782026/11/06 08:14:17 INFO Completed upload id=2 objects=3 duration=673.708µs22792026/11/06 08:14:17 INFO Received uploads request method=POST path=/api/pending_closures22802026/11/06 08:14:17 INFO Object in database but missing from S3 key=nar/dadb44fdadb44fdadb44fdadb44f000300000000000000000000.nar.zst22812026/11/06 08:14:17 WARN Narinfo references a NAR missing from S3, will re-upload narinfo=dadb44fdadb44fdadb44fdadb44f0003.narinfo2282--- PASS: TestService_verifyS3ReuploadsStaleNarinfo (0.00s)2283 --- PASS: TestService_verifyS3ReuploadsStaleNarinfo/lost,_other_NAR_pushed (8.93s)2284 --- PASS: TestService_verifyS3ReuploadsStaleNarinfo/lost,_same_NAR_pushed (9.32s)2285 --- PASS: TestService_verifyS3ReuploadsStaleNarinfo/intact,_other_NAR_pushed (9.15s)2286 --- PASS: TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost,_second_pushed (10.70s)2287 --- PASS: TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost (10.26s)22882026/11/06 08:14:18 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_closures22892026/11/06 08:14:18 WARN Request failed, retrying attempt=2 backoff=188.698709ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures22902026/11/06 08:14:18 WARN Request failed, retrying attempt=3 backoff=370.556373ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures22912026/11/06 08:14:19 WARN Request failed, retrying attempt=4 backoff=831.407074ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures22922026/11/06 08:14:19 WARN Request failed, retrying attempt=5 backoff=1.492213559s error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures2293--- PASS: TestClientErrorHandling (0.00s)2294 --- PASS: TestClientErrorHandling/InvalidStorePath (6.85s)2295 --- PASS: TestClientErrorHandling/InvalidAuthToken (7.33s)2296 --- PASS: TestClientErrorHandling/ServerNotAvailable (13.10s)2297=== NAME TestOrphanedObjectsGCStressTest2298 orphaned_objects_gc_test.go:503: Stress test completed successfully:2299 orphaned_objects_gc_test.go:504: - Active objects preserved: 202300 orphaned_objects_gc_test.go:505: - Objects deleted: 2102301 orphaned_objects_gc_test.go:506: - Total GC'd: 2102302--- PASS: TestOrphanedObjectsGCStressTest (37.08s)2303PASS2304{"timestamp":"2026-11-06T08:14:22.389226Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:56904","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(6)"}2305{"timestamp":"2026-11-06T08:14:22.389576Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:57006","error_kind":"io_error","error":"Cancelled","result":"transport_error","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":2561,"threadName":"rustfs-worker","threadId":"ThreadId(5)"}2306{"timestamp":"2026-11-06T08:14:22.389633Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:57153","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(8)"}2307{"timestamp":"2026-11-06T08:14:22.393785Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:57129","error_kind":"io_error","error":"Cancelled","result":"transport_error","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":2561,"threadName":"rustfs-worker","threadId":"ThreadId(7)"}23082026-11-06 08:14:22.522 UTC [97956] LOG: received smart shutdown request23092026-11-06 08:14:22.524 UTC [97956] LOG: background worker "logical replication launcher" (PID 97966) exited with exit code 123102026-11-06 08:14:22.527 UTC [97961] LOG: shutting down23112026-11-06 08:14:22.527 UTC [97961] LOG: checkpoint starting: shutdown immediate23122026-11-06 08:14:24.227 UTC [97961] LOG: checkpoint complete: wrote 11772 buffers (71.9%), wrote 5 SLRU buffers; 0 WAL file(s) added, 0 removed, 32 recycled; write=0.960 s, sync=0.700 s, total=1.701 s; sync files=35725, longest=0.001 s, average=0.001 s; distance=525231 kB, estimate=525231 kB; lsn=0/21878F40, redo lsn=0/21878F4023132026-11-06 08:14:24.238 UTC [97956] LOG: database system is shut down2314Running OIDC tests...2315=== RUN TestAudienceForIssuer2316=== PAUSE TestAudienceForIssuer2317=== RUN TestGlobMatch2318=== PAUSE TestGlobMatch2319=== RUN TestValidateToken_ValidToken2320=== PAUSE TestValidateToken_ValidToken2321=== RUN TestValidateToken_WrongAudience2322=== PAUSE TestValidateToken_WrongAudience2323=== RUN TestValidateToken_Expired2324=== PAUSE TestValidateToken_Expired2325=== RUN TestValidateToken_BoundClaimsMismatch2326=== PAUSE TestValidateToken_BoundClaimsMismatch2327=== RUN TestValidateToken_BoundSubjectMismatch2328=== PAUSE TestValidateToken_BoundSubjectMismatch2329=== RUN TestValidateToken_MultipleProviders2330=== PAUSE TestValidateToken_MultipleProviders2331=== RUN TestValidateToken_NoMatchingProvider2332=== PAUSE TestValidateToken_NoMatchingProvider2333=== RUN TestValidateToken_KubernetesServiceAccount2334=== PAUSE TestValidateToken_KubernetesServiceAccount2335=== RUN TestNewValidator_KubernetesRequiresCA2336=== PAUSE TestNewValidator_KubernetesRequiresCA2337=== RUN TestValidateToken_KubernetesIssuerFromOwnToken2338=== PAUSE TestValidateToken_KubernetesIssuerFromOwnToken2339=== RUN TestPins_ReservedForMatchingRule2340=== PAUSE TestPins_ReservedForMatchingRule2341=== RUN TestPins_TopLevelShorthand2342=== PAUSE TestPins_TopLevelShorthand2343=== RUN TestPins_ConfigValidation2344=== PAUSE TestPins_ConfigValidation2345=== RUN TestScopes_LegacyProviderDefaultsToWrite2346=== PAUSE TestScopes_LegacyProviderDefaultsToWrite2347=== RUN TestScopes_Rules2348=== PAUSE TestScopes_Rules2349=== RUN TestScopes_ConfigValidation2350=== PAUSE TestScopes_ConfigValidation2351=== CONT TestAudienceForIssuer2352--- PASS: TestAudienceForIssuer (0.00s)2353=== CONT TestValidateToken_NoMatchingProvider2354=== CONT TestPins_ReservedForMatchingRule2355=== CONT TestValidateToken_KubernetesServiceAccount2356=== CONT TestValidateToken_Expired2357=== CONT TestGlobMatch2358=== RUN TestGlobMatch/foo_foo2359=== CONT TestValidateToken_BoundSubjectMismatch2360=== CONT TestPins_ConfigValidation2361=== PAUSE TestGlobMatch/foo_foo2362=== RUN TestGlobMatch/foo_bar2363=== PAUSE TestGlobMatch/foo_bar2364=== RUN TestGlobMatch/*_2365=== PAUSE TestGlobMatch/*_2366=== RUN TestGlobMatch/*_anything2367=== PAUSE TestGlobMatch/*_anything2368=== RUN TestGlobMatch/foo*_foo2369=== PAUSE TestGlobMatch/foo*_foo2370=== RUN TestGlobMatch/foo*_foobar2371=== PAUSE TestGlobMatch/foo*_foobar2372=== RUN TestGlobMatch/foo*_bar2373=== PAUSE TestGlobMatch/foo*_bar2374=== RUN TestGlobMatch/*bar_bar2375=== PAUSE TestGlobMatch/*bar_bar2376=== RUN TestGlobMatch/*bar_foobar2377=== PAUSE TestGlobMatch/*bar_foobar2378=== RUN TestGlobMatch/*bar_foo2379=== PAUSE TestGlobMatch/*bar_foo2380=== RUN TestGlobMatch/foo*bar_foobar2381=== PAUSE TestGlobMatch/foo*bar_foobar2382=== RUN TestGlobMatch/foo*bar_foo123bar2383=== PAUSE TestGlobMatch/foo*bar_foo123bar2384=== RUN TestGlobMatch/foo*bar_foobarbaz2385=== PAUSE TestGlobMatch/foo*bar_foobarbaz2386=== RUN TestGlobMatch/*/*_foo/bar2387=== CONT TestScopes_ConfigValidation2388=== CONT TestScopes_LegacyProviderDefaultsToWrite2389=== CONT TestValidateToken_ValidToken2390=== CONT TestValidateToken_WrongAudience2391=== CONT TestPins_TopLevelShorthand2392=== CONT TestValidateToken_MultipleProviders2393=== CONT TestValidateToken_BoundClaimsMismatch2394=== CONT TestNewValidator_KubernetesRequiresCA2395=== CONT TestValidateToken_KubernetesIssuerFromOwnToken2396=== CONT TestScopes_Rules2397--- PASS: TestPins_ConfigValidation (0.00s)2398--- PASS: TestScopes_ConfigValidation (0.00s)2399=== PAUSE TestGlobMatch/*/*_foo/bar2400=== RUN TestGlobMatch/*/*_foo2401=== PAUSE TestGlobMatch/*/*_foo2402=== RUN TestGlobMatch/refs/heads/*_refs/heads/main2403=== PAUSE TestGlobMatch/refs/heads/*_refs/heads/main2404=== RUN TestGlobMatch/refs/heads/*_refs/tags/v1.02405=== PAUSE TestGlobMatch/refs/heads/*_refs/tags/v1.02406=== RUN TestGlobMatch/refs/*/main_refs/heads/main2407=== PAUSE TestGlobMatch/refs/*/main_refs/heads/main2408=== RUN TestGlobMatch/fo?_foo2409=== PAUSE TestGlobMatch/fo?_foo2410=== RUN TestGlobMatch/fo?_fo2411=== PAUSE TestGlobMatch/fo?_fo2412=== RUN TestGlobMatch/fo?_fooo2413=== PAUSE TestGlobMatch/fo?_fooo2414=== RUN TestGlobMatch/?oo_foo2415=== PAUSE TestGlobMatch/?oo_foo2416=== RUN TestGlobMatch/?oo_boo2417=== PAUSE TestGlobMatch/?oo_boo2418=== RUN TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2419=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2420=== RUN TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2421=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2422=== CONT TestGlobMatch/foo_foo2423=== CONT TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2424=== CONT TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2425=== CONT TestGlobMatch/?oo_boo2426=== CONT TestGlobMatch/?oo_foo2427=== CONT TestGlobMatch/fo?_fooo2428=== CONT TestGlobMatch/fo?_fo2429=== CONT TestGlobMatch/fo?_foo2430=== CONT TestGlobMatch/refs/*/main_refs/heads/main2431=== CONT TestGlobMatch/refs/heads/*_refs/tags/v1.02432=== CONT TestGlobMatch/refs/heads/*_refs/heads/main2433=== CONT TestGlobMatch/*/*_foo2434=== CONT TestGlobMatch/*/*_foo/bar2435=== CONT TestGlobMatch/foo*bar_foobarbaz2436=== CONT TestGlobMatch/foo*bar_foo123bar2437=== CONT TestGlobMatch/foo*bar_foobar2438=== CONT TestGlobMatch/*bar_foo2439=== CONT TestGlobMatch/*bar_foobar2440=== CONT TestGlobMatch/*bar_bar2441=== CONT TestGlobMatch/foo*_bar2442=== CONT TestGlobMatch/foo*_foobar2443=== CONT TestGlobMatch/foo*_foo2444=== CONT TestGlobMatch/*_anything2445=== CONT TestGlobMatch/*_2446=== CONT TestGlobMatch/foo_bar2447--- PASS: TestGlobMatch (0.02s)2448 --- PASS: TestGlobMatch/foo_foo (0.00s)2449 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main (0.00s)2450 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main (0.00s)2451 --- PASS: TestGlobMatch/?oo_boo (0.00s)2452 --- PASS: TestGlobMatch/?oo_foo (0.00s)2453 --- PASS: TestGlobMatch/fo?_fooo (0.00s)2454 --- PASS: TestGlobMatch/fo?_fo (0.00s)2455 --- PASS: TestGlobMatch/fo?_foo (0.00s)2456 --- PASS: TestGlobMatch/refs/*/main_refs/heads/main (0.00s)2457 --- PASS: TestGlobMatch/refs/heads/*_refs/tags/v1.0 (0.00s)2458 --- PASS: TestGlobMatch/refs/heads/*_refs/heads/main (0.00s)2459 --- PASS: TestGlobMatch/*/*_foo (0.00s)2460 --- PASS: TestGlobMatch/*/*_foo/bar (0.00s)2461 --- PASS: TestGlobMatch/foo*bar_foobarbaz (0.00s)2462 --- PASS: TestGlobMatch/foo*bar_foo123bar (0.00s)2463 --- PASS: TestGlobMatch/foo*bar_foobar (0.00s)2464 --- PASS: TestGlobMatch/*bar_foo (0.00s)2465 --- PASS: TestGlobMatch/*bar_foobar (0.00s)2466 --- PASS: TestGlobMatch/*bar_bar (0.00s)2467 --- PASS: TestGlobMatch/foo*_bar (0.00s)2468 --- PASS: TestGlobMatch/foo*_foobar (0.00s)2469 --- PASS: TestGlobMatch/foo*_foo (0.00s)2470 --- PASS: TestGlobMatch/*_anything (0.00s)2471 --- PASS: TestGlobMatch/*_ (0.00s)2472 --- PASS: TestGlobMatch/foo_bar (0.00s)24732026/11/06 08:14:25 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:57180/oidc2474--- PASS: TestScopes_Rules (0.06s)24752026/11/06 08:14:25 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:57182/oidc24762026/11/06 08:14:25 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:57184/oidc24772026/11/06 08:14:25 INFO OIDC provider initialized name=kubernetes issuer=https://oidc.eks.invalid/id/ABC1232478--- PASS: TestValidateToken_ValidToken (0.06s)2479--- PASS: TestPins_ReservedForMatchingRule (0.09s)24802026/11/06 08:14:26 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:57187/oidc2481--- PASS: TestValidateToken_WrongAudience (0.10s)2482--- PASS: TestValidateToken_KubernetesIssuerFromOwnToken (0.09s)24832026/11/06 08:14:26 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:57193/oidc24842026/11/06 08:14:26 INFO OIDC provider initialized name=kubernetes issuer=https://127.0.0.1:571912485--- PASS: TestValidateToken_BoundSubjectMismatch (0.11s)24862026/11/06 08:14:26 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:57195/oidc2487--- PASS: TestScopes_LegacyProviderDefaultsToWrite (0.10s)2488--- PASS: TestValidateToken_KubernetesServiceAccount (0.11s)24892026/11/06 08:14:26 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:57198/oidc2490--- PASS: TestPins_TopLevelShorthand (0.11s)24912026/11/06 08:14:26 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:57200/oidc2492--- PASS: TestValidateToken_Expired (0.13s)24932026/11/06 08:14:26 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:57190/oidc2494--- PASS: TestValidateToken_NoMatchingProvider (0.14s)24952026/11/06 08:14:26 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:57197/oidc24962026/11/06 08:14:26 INFO OIDC provider initialized name=provider2 issuer=http://127.0.0.1:57206/oidc2497--- PASS: TestValidateToken_MultipleProviders (0.13s)24982026/11/06 08:14:26 http: TLS handshake error from 127.0.0.1:57203: read tcp 127.0.0.1:57202->127.0.0.1:57203: use of closed network connection2499--- PASS: TestNewValidator_KubernetesRequiresCA (0.14s)25002026/11/06 08:14:26 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:57209/oidc2501--- PASS: TestValidateToken_BoundClaimsMismatch (0.16s)2502PASS2503Running hook tests...2504=== RUN TestSendPathsEmpty2505=== PAUSE TestSendPathsEmpty2506=== RUN TestQueueEnqueueAndFetch2507=== PAUSE TestQueueEnqueueAndFetch2508=== RUN TestQueueDeduplication2509=== PAUSE TestQueueDeduplication2510=== RUN TestQueueRemove2511=== PAUSE TestQueueRemove2512=== RUN TestQueueFetchBatchLimit2513=== PAUSE TestQueueFetchBatchLimit2514=== RUN TestQueueRetryMovesToBack2515=== PAUSE TestQueueRetryMovesToBack2516=== RUN TestQueueFetchRemoveLifecycle2517=== PAUSE TestQueueFetchRemoveLifecycle2518=== RUN TestQueueConcurrentWriters2519=== PAUSE TestQueueConcurrentWriters2520=== RUN TestQueueRemoveLargeClosure2521=== PAUSE TestQueueRemoveLargeClosure2522=== RUN TestServerClientIntegration2523--- PASS: TestServerClientIntegration (0.00s)2524=== RUN TestServerQueueError25252026/11/06 08:14:26 ERROR Failed to queue paths error="permission denied" count=12526--- PASS: TestServerQueueError (0.00s)2527=== RUN TestGetListenerSocketActivation2528 server_test.go:145: systemd socket activation does not exist on darwin2529--- SKIP: TestGetListenerSocketActivation (0.00s)2530=== RUN TestServerStalledClientDoesNotBlockShutdown2531=== PAUSE TestServerStalledClientDoesNotBlockShutdown2532=== RUN TestServerBacksOffOnAcceptErrors2533=== PAUSE TestServerBacksOffOnAcceptErrors2534=== RUN TestDrainIsolatesPoisonPath2535=== PAUSE TestDrainIsolatesPoisonPath2536=== RUN TestRunNotBlockedByPoisonHead2537=== PAUSE TestRunNotBlockedByPoisonHead2538=== RUN TestDrainGivesUpWhenServerDown2539=== PAUSE TestDrainGivesUpWhenServerDown2540=== RUN TestFailedPathPrunedByLaterClosure2541=== PAUSE TestFailedPathPrunedByLaterClosure2542=== RUN TestWorkerUploadsAndRemoves2543=== PAUSE TestWorkerUploadsAndRemoves2544=== RUN TestWorkerSkipsGCdPaths2545=== PAUSE TestWorkerSkipsGCdPaths2546=== RUN TestWorkerPrunesClosureDeps2547=== PAUSE TestWorkerPrunesClosureDeps2548=== RUN TestDrainTimeout2549=== PAUSE TestDrainTimeout2550=== RUN TestWorkerRemoveFailureIsNotProgress2551=== PAUSE TestWorkerRemoveFailureIsNotProgress2552=== RUN TestWorkerKeepsPathItCannotStat2553=== PAUSE TestWorkerKeepsPathItCannotStat2554=== CONT TestSendPathsEmpty2555=== CONT TestQueueRemoveLargeClosure2556=== CONT TestWorkerKeepsPathItCannotStat2557=== CONT TestWorkerRemoveFailureIsNotProgress2558=== CONT TestDrainTimeout2559=== CONT TestWorkerPrunesClosureDeps2560=== CONT TestWorkerSkipsGCdPaths2561--- PASS: TestSendPathsEmpty (0.00s)2562=== CONT TestWorkerUploadsAndRemoves2563=== CONT TestQueueRemove2564=== CONT TestQueueFetchBatchLimit2565=== CONT TestQueueDeduplication2566=== CONT TestQueueConcurrentWriters2567=== CONT TestQueueEnqueueAndFetch2568=== CONT TestQueueFetchRemoveLifecycle2569=== CONT TestQueueRetryMovesToBack2570=== CONT TestRunNotBlockedByPoisonHead2571=== CONT TestFailedPathPrunedByLaterClosure2572=== CONT TestDrainGivesUpWhenServerDown2573=== CONT TestServerBacksOffOnAcceptErrors25742026/11/06 08:14:26 ERROR Accept failed error="too many open files"2575=== CONT TestDrainIsolatesPoisonPath2576=== CONT TestServerStalledClientDoesNotBlockShutdown25772026/11/06 08:14:26 ERROR Accept failed error="too many open files"25782026/11/06 08:14:26 INFO Uploading batch count=125792026/11/06 08:14:26 ERROR Upload failed error="upload failed" count=125802026/11/06 08:14:26 INFO Upload queue status pending=225812026/11/06 08:14:26 INFO Uploading batch count=22582--- PASS: TestQueueEnqueueAndFetch (0.01s)25832026/11/06 08:14:26 INFO Upload queue status pending=225842026/11/06 08:14:26 WARN Store path no longer exists (garbage collected?), removing from queue path=/private/var/tb/1/scratch/8499ef2246bbc144/build/TestWorkerSkipsGCdPaths3905359983/002/nonexistent25852026/11/06 08:14:26 INFO Upload queue status pending=225862026/11/06 08:14:26 INFO Uploading batch count=125872026/11/06 08:14:26 INFO Uploading batch count=12588--- PASS: TestQueueFetchBatchLimit (0.02s)25892026/11/06 08:14:26 INFO Upload queue status pending=325902026/11/06 08:14:26 INFO Uploading batch count=125912026/11/06 08:14:26 INFO Uploading batch count=125922026/11/06 08:14:26 ERROR Upload failed error="upload failed" count=12593--- PASS: TestQueueFetchRemoveLifecycle (0.02s)25942026/11/06 08:14:26 INFO Uploading batch count=225952026/11/06 08:14:26 ERROR Upload failed error="upload failed" count=225962026/11/06 08:14:26 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/1/scratch/8499ef2246bbc144/build/TestDrainGivesUpWhenServerDown2505632470/002/a25972026/11/06 08:14:26 INFO Uploading batch count=12598--- PASS: TestQueueRetryMovesToBack (0.01s)25992026/11/06 08:14:26 INFO Uploading batch count=426002026/11/06 08:14:26 ERROR Upload failed error="upload failed" count=426012026/11/06 08:14:26 WARN Cannot stat store path, will retry later path=/private/var/tb/1/scratch/8499ef2246bbc144/build/TestWorkerKeepsPathItCannotStat2326425136/002/locked/aaa error="stat /private/var/tb/1/scratch/8499ef2246bbc144/build/TestWorkerKeepsPathItCannotStat2326425136/002/locked/aaa: permission denied"26022026/11/06 08:14:26 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/1/scratch/8499ef2246bbc144/build/TestDrainGivesUpWhenServerDown2505632470/002/b26032026/11/06 08:14:26 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/1/scratch/8499ef2246bbc144/build/TestDrainIsolatesPoisonPath3135304733/002/bbb26042026/11/06 08:14:26 WARN Store path no longer exists (garbage collected?), removing from queue path=/private/var/tb/1/scratch/8499ef2246bbc144/build/TestWorkerRemoveFailureIsNotProgress1093492038/002/nonexistent2605--- PASS: TestQueueRemove (0.02s)26062026/11/06 08:14:26 WARN Cannot stat store path, will retry later path=/private/var/tb/1/scratch/8499ef2246bbc144/build/TestWorkerKeepsPathItCannotStat2326425136/002/locked/aaa error="stat /private/var/tb/1/scratch/8499ef2246bbc144/build/TestWorkerKeepsPathItCannotStat2326425136/002/locked/aaa: permission denied"26072026/11/06 08:14:26 INFO Uploading batch count=226082026/11/06 08:14:26 ERROR Upload failed error="upload failed" count=226092026/11/06 08:14:26 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/1/scratch/8499ef2246bbc144/build/TestDrainGivesUpWhenServerDown2505632470/002/c26102026/11/06 08:14:26 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=126112026/11/06 08:14:26 WARN Store path no longer exists (garbage collected?), removing from queue path=/private/var/tb/1/scratch/8499ef2246bbc144/build/TestWorkerRemoveFailureIsNotProgress1093492038/002/nonexistent26122026/11/06 08:14:26 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=126132026/11/06 08:14:26 WARN Store path no longer exists (garbage collected?), removing from queue path=/private/var/tb/1/scratch/8499ef2246bbc144/build/TestWorkerRemoveFailureIsNotProgress1093492038/002/nonexistent26142026/11/06 08:14:26 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=126152026/11/06 08:14:26 ERROR Drain finished with paths left in queue remaining=126162026/11/06 08:14:26 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/1/scratch/8499ef2246bbc144/build/TestDrainGivesUpWhenServerDown2505632470/002/d2617--- PASS: TestFailedPathPrunedByLaterClosure (0.01s)26182026/11/06 08:14:26 INFO Uploading batch count=126192026/11/06 08:14:26 ERROR Upload failed error="upload failed" count=126202026/11/06 08:14:26 WARN Cannot stat store path, will retry later path=/private/var/tb/1/scratch/8499ef2246bbc144/build/TestWorkerKeepsPathItCannotStat2326425136/002/locked/aaa error="stat /private/var/tb/1/scratch/8499ef2246bbc144/build/TestWorkerKeepsPathItCannotStat2326425136/002/locked/aaa: permission denied"26212026/11/06 08:14:26 INFO Uploading batch count=22622--- PASS: TestWorkerRemoveFailureIsNotProgress (0.02s)26232026/11/06 08:14:26 INFO Uploading batch count=226242026/11/06 08:14:26 ERROR Upload failed error="upload failed" count=226252026/11/06 08:14:26 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/1/scratch/8499ef2246bbc144/build/TestDrainGivesUpWhenServerDown2505632470/002/e26262026/11/06 08:14:26 INFO Uploading batch count=126272026/11/06 08:14:26 ERROR Upload failed error="upload failed" count=126282026/11/06 08:14:26 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/1/scratch/8499ef2246bbc144/build/TestDrainGivesUpWhenServerDown2505632470/002/f26292026/11/06 08:14:26 INFO Uploading batch count=126302026/11/06 08:14:26 ERROR Upload failed error="upload failed" count=12631--- PASS: TestQueueDeduplication (0.02s)26322026/11/06 08:14:26 ERROR Drain finished with paths left in queue remaining=126332026/11/06 08:14:26 ERROR Drain finished with paths left in queue remaining=1026342026/11/06 08:14:26 ERROR Drain finished with paths left in queue remaining=12635--- PASS: TestDrainIsolatesPoisonPath (0.01s)2636--- PASS: TestWorkerKeepsPathItCannotStat (0.02s)2637--- PASS: TestDrainGivesUpWhenServerDown (0.01s)26382026/11/06 08:14:26 ERROR Accept failed error="too many open files"2639--- PASS: TestWorkerUploadsAndRemoves (0.03s)2640--- PASS: TestWorkerSkipsGCdPaths (0.04s)2641--- PASS: TestWorkerPrunesClosureDeps (0.04s)2642--- PASS: TestQueueRemoveLargeClosure (0.04s)2643--- PASS: TestQueueConcurrentWriters (0.04s)26442026/11/06 08:14:26 ERROR Accept failed error="too many open files"26452026/11/06 08:14:26 ERROR Accept failed error="too many open files"26462026/11/06 08:14:26 ERROR Accept failed error="too many open files"26472026/11/06 08:14:26 ERROR Failed to decode request error="read unix /private/var/tb/1/scratch/8499ef2246bbc144/build/hook3456155788/test.sock->: i/o timeout"26482026/11/06 08:14:26 ERROR Failed to write response error="write unix /private/var/tb/1/scratch/8499ef2246bbc144/build/hook3456155788/test.sock->: i/o timeout"2649--- PASS: TestServerStalledClientDoesNotBlockShutdown (0.20s)26502026/11/06 08:14:26 ERROR Upload failed error="context deadline exceeded" count=226512026/11/06 08:14:26 ERROR Drain finished with paths left in queue remaining=42652--- PASS: TestDrainTimeout (0.22s)26532026/11/06 08:14:26 ERROR Accept failed error="too many open files"26542026/11/06 08:14:27 ERROR Accept failed error="too many open files"2655--- PASS: TestServerBacksOffOnAcceptErrors (0.64s)26562026/11/06 08:14:27 INFO Uploading batch count=126572026/11/06 08:14:27 INFO Uploading batch count=126582026/11/06 08:14:27 INFO Uploading batch count=126592026/11/06 08:14:27 ERROR Upload failed error="upload failed" count=126602026/11/06 08:14:27 INFO Uploading batch count=126612026/11/06 08:14:27 ERROR Upload failed error="upload failed" count=126622026/11/06 08:14:27 INFO Uploading batch count=126632026/11/06 08:14:27 ERROR Upload failed error="upload failed" count=126642026/11/06 08:14:27 INFO Uploading batch count=126652026/11/06 08:14:27 ERROR Upload failed error="upload failed" count=126662026/11/06 08:14:27 ERROR Drain finished with paths left in queue remaining=12667--- PASS: TestRunNotBlockedByPoisonHead (1.03s)2668PASS2669Running signing tests...2670=== RUN TestExternalSigner2671=== PAUSE TestExternalSigner2672=== RUN TestExternalSignerWrongPublicKey2673=== PAUSE TestExternalSignerWrongPublicKey2674=== RUN TestExternalSignerErrors2675=== PAUSE TestExternalSignerErrors2676=== RUN TestExternalSignerRestartsAfterCrash2677=== PAUSE TestExternalSignerRestartsAfterCrash2678=== RUN TestExternalSignerProgramErrorKeepsProcess2679=== PAUSE TestExternalSignerProgramErrorKeepsProcess2680=== RUN TestExternalSignerClose2681=== PAUSE TestExternalSignerClose2682=== RUN TestExternalSignerRejectsInvalidPublicKey2683=== PAUSE TestExternalSignerRejectsInvalidPublicKey2684=== RUN TestExternalSignerCancellation2685=== PAUSE TestExternalSignerCancellation2686=== RUN TestGenerateFingerprint2687=== PAUSE TestGenerateFingerprint2688=== RUN TestParseSigningKey2689=== PAUSE TestParseSigningKey2690=== RUN TestSign2691=== PAUSE TestSign2692=== RUN TestSignBatch2693=== PAUSE TestSignBatch2694=== RUN TestNilKeyPublicKey2695=== PAUSE TestNilKeyPublicKey2696=== RUN TestSignErrors2697=== PAUSE TestSignErrors2698=== CONT TestExternalSigner2699=== CONT TestExternalSignerCancellation2700=== CONT TestExternalSignerProgramErrorKeepsProcess2701=== CONT TestExternalSignerRejectsInvalidPublicKey2702=== RUN TestExternalSignerRejectsInvalidPublicKey/#002703=== PAUSE TestExternalSignerRejectsInvalidPublicKey/#002704=== RUN TestExternalSignerRejectsInvalidPublicKey/no-colon2705=== PAUSE TestExternalSignerRejectsInvalidPublicKey/no-colon2706=== RUN TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2707=== CONT TestExternalSignerClose2708=== CONT TestExternalSignerErrors2709=== RUN TestExternalSignerErrors/program_error2710=== PAUSE TestExternalSignerErrors/program_error2711=== RUN TestExternalSignerErrors/exit_at_startup2712=== PAUSE TestExternalSignerErrors/exit_at_startup2713=== CONT TestExternalSignerRestartsAfterCrash2714=== CONT TestSignBatch2715=== CONT TestSignErrors2716=== CONT TestNilKeyPublicKey2717--- PASS: TestNilKeyPublicKey (0.00s)2718=== CONT TestParseSigningKey2719=== RUN TestParseSigningKey/valid_32-byte_key2720=== PAUSE TestParseSigningKey/valid_32-byte_key2721=== RUN TestParseSigningKey/valid_32-byte_key_with_different_name2722=== CONT TestSign2723=== CONT TestGenerateFingerprint2724=== RUN TestGenerateFingerprint/basic_with_references2725=== PAUSE TestGenerateFingerprint/basic_with_references2726=== RUN TestGenerateFingerprint/no_references2727=== PAUSE TestGenerateFingerprint/no_references2728=== CONT TestExternalSignerWrongPublicKey2729=== PAUSE TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2730=== RUN TestExternalSignerErrors/unrequested_key2731=== PAUSE TestExternalSignerErrors/unrequested_key2732=== RUN TestExternalSignerErrors/exit_on_request2733=== PAUSE TestExternalSignerErrors/exit_on_request2734=== RUN TestExternalSignerErrors/invalid_JSON2735=== PAUSE TestExternalSignerErrors/invalid_JSON2736=== RUN TestExternalSignerErrors/null2737=== PAUSE TestExternalSignerErrors/null2738=== RUN TestExternalSignerErrors/wrong_shape2739=== PAUSE TestExternalSignerErrors/wrong_shape2740=== RUN TestExternalSignerErrors/wrong_id2741=== PAUSE TestExternalSignerErrors/wrong_id2742=== RUN TestExternalSignerErrors/missing_signatures2743=== PAUSE TestExternalSignerErrors/missing_signatures2744=== RUN TestExternalSignerErrors/null_signatures2745=== PAUSE TestExternalSignerErrors/null_signatures2746=== RUN TestExternalSignerErrors/wrong_signatures_shape2747=== PAUSE TestExternalSignerErrors/wrong_signatures_shape2748=== RUN TestExternalSignerErrors/too_few_signatures2749=== PAUSE TestExternalSignerErrors/too_few_signatures2750=== RUN TestExternalSignerErrors/missing_signature_name2751=== PAUSE TestExternalSignerErrors/missing_signature_name2752=== RUN TestExternalSignerErrors/invalid_signature_base642753=== PAUSE TestExternalSignerErrors/invalid_signature_base642754=== RUN TestExternalSignerErrors/wrong_signature_name2755=== PAUSE TestExternalSignerErrors/wrong_signature_name2756=== RUN TestExternalSignerErrors/wrong_signature_length2757=== PAUSE TestExternalSignerErrors/wrong_signature_length2758=== CONT TestExternalSignerErrors/program_error2759=== CONT TestExternalSignerErrors/null_signatures2760=== CONT TestExternalSignerErrors/missing_signatures2761=== CONT TestExternalSignerErrors/wrong_id2762=== CONT TestExternalSignerErrors/wrong_shape2763=== RUN TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2764=== RUN TestSignErrors/nil_key2765=== PAUSE TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2766=== RUN TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2767=== PAUSE TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2768=== CONT TestExternalSignerRejectsInvalidPublicKey/#002769=== CONT TestExternalSignerErrors/missing_signature_name2770--- PASS: TestSign (0.00s)2771=== CONT TestExternalSignerErrors/wrong_signature_length2772=== CONT TestExternalSignerErrors/null2773=== CONT TestExternalSignerErrors/too_few_signatures2774=== PAUSE TestParseSigningKey/valid_32-byte_key_with_different_name2775=== CONT TestExternalSignerErrors/wrong_signature_name2776=== CONT TestExternalSignerErrors/exit_at_startup2777=== RUN TestGenerateFingerprint/unsorted_references_get_sorted2778=== PAUSE TestGenerateFingerprint/unsorted_references_get_sorted2779=== RUN TestGenerateFingerprint/invalid_nar_hash_prefix2780=== PAUSE TestGenerateFingerprint/invalid_nar_hash_prefix2781=== RUN TestGenerateFingerprint/invalid_nar_hash_length2782=== PAUSE TestGenerateFingerprint/invalid_nar_hash_length2783=== RUN TestGenerateFingerprint/invalid_store_path_prefix2784=== PAUSE TestGenerateFingerprint/invalid_store_path_prefix2785=== RUN TestGenerateFingerprint/invalid_reference_prefix2786=== PAUSE TestGenerateFingerprint/invalid_reference_prefix2787=== PAUSE TestSignErrors/nil_key2788=== RUN TestSignErrors/nil_narinfo2789=== PAUSE TestSignErrors/nil_narinfo2790=== RUN TestSignErrors/invalid_narinfo2791=== PAUSE TestSignErrors/invalid_narinfo2792=== RUN TestSignErrors/canceled2793=== PAUSE TestSignErrors/canceled2794=== CONT TestExternalSignerErrors/wrong_signatures_shape2795--- PASS: TestSignBatch (0.00s)2796=== CONT TestExternalSignerErrors/exit_on_request2797=== CONT TestExternalSignerErrors/invalid_JSON2798=== CONT TestExternalSignerErrors/unrequested_key2799=== CONT TestExternalSignerErrors/invalid_signature_base642800=== RUN TestParseSigningKey/no_colon2801=== PAUSE TestParseSigningKey/no_colon2802=== RUN TestParseSigningKey/empty_name2803=== PAUSE TestParseSigningKey/empty_name2804=== RUN TestParseSigningKey/invalid_base642805=== PAUSE TestParseSigningKey/invalid_base642806=== RUN TestParseSigningKey/wrong_length2807=== PAUSE TestParseSigningKey/wrong_length2808=== CONT TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2809=== CONT TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2810=== CONT TestExternalSignerRejectsInvalidPublicKey/no-colon2811=== CONT TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2812--- PASS: TestExternalSignerRejectsInvalidPublicKey (0.00s)2813 --- PASS: TestExternalSignerRejectsInvalidPublicKey/#00 (0.00s)2814 --- PASS: TestExternalSignerRejectsInvalidPublicKey/test-key:YQ== (0.00s)2815 --- PASS: TestExternalSignerRejectsInvalidPublicKey/test-key:invalid! (0.00s)2816 --- PASS: TestExternalSignerRejectsInvalidPublicKey/no-colon (0.00s)2817 --- PASS: TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA= (0.00s)2818=== CONT TestGenerateFingerprint/basic_with_references2819=== CONT TestGenerateFingerprint/invalid_nar_hash_length2820=== CONT TestGenerateFingerprint/invalid_reference_prefix2821=== CONT TestGenerateFingerprint/unsorted_references_get_sorted2822=== CONT TestGenerateFingerprint/invalid_nar_hash_prefix2823=== CONT TestGenerateFingerprint/no_references2824=== CONT TestGenerateFingerprint/invalid_store_path_prefix2825--- PASS: TestGenerateFingerprint (0.00s)2826 --- PASS: TestGenerateFingerprint/basic_with_references (0.00s)2827 --- PASS: TestGenerateFingerprint/invalid_nar_hash_length (0.00s)2828 --- PASS: TestGenerateFingerprint/invalid_reference_prefix (0.00s)2829 --- PASS: TestGenerateFingerprint/unsorted_references_get_sorted (0.00s)2830 --- PASS: TestGenerateFingerprint/invalid_nar_hash_prefix (0.00s)2831 --- PASS: TestGenerateFingerprint/no_references (0.00s)2832 --- PASS: TestGenerateFingerprint/invalid_store_path_prefix (0.00s)2833=== CONT TestSignErrors/nil_key2834=== CONT TestSignErrors/invalid_narinfo2835=== CONT TestSignErrors/nil_narinfo2836=== CONT TestSignErrors/canceled2837--- PASS: TestSignErrors (0.00s)2838 --- PASS: TestSignErrors/nil_key (0.00s)2839 --- PASS: TestSignErrors/invalid_narinfo (0.00s)2840 --- PASS: TestSignErrors/nil_narinfo (0.00s)2841 --- PASS: TestSignErrors/canceled (0.00s)2842=== CONT TestParseSigningKey/valid_32-byte_key2843=== CONT TestParseSigningKey/wrong_length2844=== CONT TestParseSigningKey/empty_name2845=== CONT TestParseSigningKey/no_colon2846=== CONT TestParseSigningKey/valid_32-byte_key_with_different_name2847=== CONT TestParseSigningKey/invalid_base642848--- PASS: TestParseSigningKey (0.00s)2849 --- PASS: TestParseSigningKey/valid_32-byte_key (0.00s)2850 --- PASS: TestParseSigningKey/wrong_length (0.00s)2851 --- PASS: TestParseSigningKey/empty_name (0.00s)2852 --- PASS: TestParseSigningKey/no_colon (0.00s)2853 --- PASS: TestParseSigningKey/invalid_base64 (0.00s)2854 --- PASS: TestParseSigningKey/valid_32-byte_key_with_different_name (0.00s)2855--- PASS: TestExternalSignerCancellation (0.24s)2856--- PASS: TestExternalSignerClose (0.45s)2857--- PASS: TestExternalSigner (1.24s)2858--- PASS: TestExternalSignerWrongPublicKey (1.41s)2859--- PASS: TestExternalSignerProgramErrorKeepsProcess (1.79s)2860--- PASS: TestExternalSignerRestartsAfterCrash (3.15s)2861/private/var/tb/1/scratch/8499ef2246bbc144/build/TestExternalSignerRestartsAfterCrash1084517782/001/sign program: line 7: /private/var/tb/1/scratch/8499ef2246bbc144/build/TestExternalSignerRestartsAfterCrash1084517782/001/sign program.starts: No such file or directory2862--- PASS: TestExternalSignerErrors (0.00s)2863 --- PASS: TestExternalSignerErrors/unrequested_key (0.64s)2864 --- PASS: TestExternalSignerErrors/wrong_signatures_shape (0.83s)2865 --- PASS: TestExternalSignerErrors/wrong_id (1.03s)2866 --- PASS: TestExternalSignerErrors/exit_on_request (1.60s)2867 --- PASS: TestExternalSignerErrors/wrong_signature_length (1.98s)2868 --- PASS: TestExternalSignerErrors/null (2.17s)2869 --- PASS: TestExternalSignerErrors/exit_at_startup (2.36s)2870 --- PASS: TestExternalSignerErrors/missing_signature_name (2.55s)2871 --- PASS: TestExternalSignerErrors/invalid_signature_base64 (2.74s)2872 --- PASS: TestExternalSignerErrors/missing_signatures (2.93s)2873 --- PASS: TestExternalSignerErrors/wrong_signature_name (3.31s)2874 --- PASS: TestExternalSignerErrors/program_error (3.52s)2875 --- PASS: TestExternalSignerErrors/too_few_signatures (3.75s)2876 --- PASS: TestExternalSignerErrors/wrong_shape (4.17s)2877 --- PASS: TestExternalSignerErrors/invalid_JSON (4.35s)2878 --- PASS: TestExternalSignerErrors/null_signatures (4.55s)2879PASS2880Running OpenBao signer tests...2881=== RUN TestSign2882=== PAUSE TestSign2883=== RUN TestSignErrors2884=== PAUSE TestSignErrors2885=== RUN TestServe2886=== PAUSE TestServe2887=== RUN TestServeRejectsGarbage2888=== PAUSE TestServeRejectsGarbage2889=== CONT TestSign2890=== CONT TestServeRejectsGarbage2891=== CONT TestSignErrors2892=== RUN TestSignErrors/http_error2893--- PASS: TestServeRejectsGarbage (0.00s)2894=== CONT TestServe2895=== PAUSE TestSignErrors/http_error2896=== RUN TestSignErrors/invalid_json2897=== PAUSE TestSignErrors/invalid_json2898=== RUN TestSignErrors/no_prefix2899=== PAUSE TestSignErrors/no_prefix2900=== RUN TestSignErrors/invalid_base642901=== PAUSE TestSignErrors/invalid_base642902=== CONT TestSignErrors/http_error2903=== CONT TestSignErrors/no_prefix2904=== CONT TestSignErrors/invalid_json2905=== CONT TestSignErrors/invalid_base642906--- PASS: TestServe (0.00s)2907--- PASS: TestSignErrors (0.00s)2908 --- PASS: TestSignErrors/invalid_base64 (0.00s)2909 --- PASS: TestSignErrors/http_error (0.00s)2910 --- PASS: TestSignErrors/invalid_json (0.00s)2911 --- PASS: TestSignErrors/no_prefix (0.00s)2912--- PASS: TestSign (0.00s)2913PASS