niks3-go-unit-tests
checks.aarch64-darwin.go-unit-tests
· build #449
· raw
1tribuchet: building on mac022Running client tests...3=== RUN TestDoServerRequestAttachesToken4=== PAUSE TestDoServerRequestAttachesToken5=== RUN TestUploadBuildLog_FileBodyReplayedOnRetry6=== PAUSE TestUploadBuildLog_FileBodyReplayedOnRetry7=== RUN TestRegisterUploadedObjectReusesConnections8=== PAUSE TestRegisterUploadedObjectReusesConnections9=== RUN TestRunGarbageCollection_FinishedOnAnotherReplica10=== PAUSE TestRunGarbageCollection_FinishedOnAnotherReplica11=== RUN TestRunGarbageCollection_NotFoundAfterLocalRun12=== PAUSE TestRunGarbageCollection_NotFoundAfterLocalRun13=== RUN TestCaseHackSuffix14=== PAUSE TestCaseHackSuffix15=== RUN TestFilterOversizedClosures16=== PAUSE TestFilterOversizedClosures17=== RUN TestUploadMultipart_PartsInParallel18=== PAUSE TestUploadMultipart_PartsInParallel19=== RUN TestUploadMultipart_FailedPartBufferNotReused20=== PAUSE TestUploadMultipart_FailedPartBufferNotReused21=== RUN TestPartSizeForNAR22=== PAUSE TestPartSizeForNAR23=== RUN TestUploadMultipart_SupersededByPeer24=== PAUSE TestUploadMultipart_SupersededByPeer25=== RUN TestDumpPathCaseHackMatchesNix26--- PASS: TestDumpPathCaseHackMatchesNix (0.13s)27=== RUN TestDumpPathCaseHackCollision28--- PASS: TestDumpPathCaseHackCollision (0.00s)29=== RUN TestSupersededNARStillUploadsListing30=== PAUSE TestSupersededNARStillUploadsListing31=== RUN TestDumpPathMatchesNix32=== PAUSE TestDumpPathMatchesNix33=== RUN TestDumpPathSingleFile34=== PAUSE TestDumpPathSingleFile35=== RUN TestDumpPathWriterError36=== PAUSE TestDumpPathWriterError37=== RUN TestEncodeNixBase3238=== PAUSE TestEncodeNixBase3239=== RUN TestEncodeNixBase32WithRealHash40=== PAUSE TestEncodeNixBase32WithRealHash41=== RUN TestConvertHashToNix3242=== PAUSE TestConvertHashToNix3243=== RUN TestGetStorePathHash44=== PAUSE TestGetStorePathHash45=== RUN TestPathInfoHashCompatibility46=== PAUSE TestPathInfoHashCompatibility47=== RUN TestParsePathInfoJSON48=== PAUSE TestParsePathInfoJSON49=== RUN TestParsePathInfoJSONMultiplePaths50=== PAUSE TestParsePathInfoJSONMultiplePaths51=== RUN TestPathInfoCACompatibility52=== PAUSE TestPathInfoCACompatibility53=== RUN TestRateLimiterFeedback54=== PAUSE TestRateLimiterFeedback55=== RUN TestRateLimiterFeedback_400DoesNotCountAsSuccess56=== PAUSE TestRateLimiterFeedback_400DoesNotCountAsSuccess57=== RUN TestRegisterUploadedObject_BoundedAgainstSilentServer58=== PAUSE TestRegisterUploadedObject_BoundedAgainstSilentServer59=== RUN TestResolveStorePath60=== PAUSE TestResolveStorePath61=== RUN TestDoWithRetry_BodyReplayedViaGetBody62=== PAUSE TestDoWithRetry_BodyReplayedViaGetBody63=== RUN TestRetryTimeoutOutlastsMaxRetries64=== PAUSE TestRetryTimeoutOutlastsMaxRetries65=== RUN TestDoWithRetry_FinalResponseBodyReadable66=== PAUSE TestDoWithRetry_FinalResponseBodyReadable67=== RUN TestShellSplit68=== PAUSE TestShellSplit69=== RUN TestShellSplitErrors70=== PAUSE TestShellSplitErrors71=== RUN TestStreamPushReportsEveryPath72=== PAUSE TestStreamPushReportsEveryPath73=== RUN TestStreamPushBatchesUnderLoad74=== PAUSE TestStreamPushBatchesUnderLoad75=== RUN TestStreamPushIsolatesFailures76=== PAUSE TestStreamPushIsolatesFailures77=== RUN TestStreamPushGivesUpOnDeadServer78=== PAUSE TestStreamPushGivesUpOnDeadServer79=== RUN TestStreamPushRequestLine80=== PAUSE TestStreamPushRequestLine81=== RUN TestStreamPushReportsSignatures82=== PAUSE TestStreamPushReportsSignatures83=== RUN TestStreamPushReportsSkippedPaths84=== PAUSE TestStreamPushReportsSkippedPaths85=== RUN TestClientSignaturesByStorePath86=== PAUSE TestClientSignaturesByStorePath87=== RUN TestStreamPushStopsWhenCanceled88=== PAUSE TestStreamPushStopsWhenCanceled89=== RUN TestSetClientTLS90=== PAUSE TestSetClientTLS91=== RUN TestSetClientTLSDoesNotMutateDefaultTransport92=== PAUSE TestSetClientTLSDoesNotMutateDefaultTransport93=== RUN TestSetClientTLSErrors94=== PAUSE TestSetClientTLSErrors95=== RUN TestStaticToken96=== PAUSE TestStaticToken97=== RUN TestFileTokenReadsAndCaches98=== PAUSE TestFileTokenReadsAndCaches99=== RUN TestFileTokenMissing100=== PAUSE TestFileTokenMissing101=== RUN TestFileTokenEmpty102=== PAUSE TestFileTokenEmpty103=== RUN TestScriptTokenNoExpiryRerunsEveryCall104=== PAUSE TestScriptTokenNoExpiryRerunsEveryCall105=== RUN TestScriptTokenCachesUntilRefresh106=== PAUSE TestScriptTokenCachesUntilRefresh107=== RUN TestScriptTokenEmptyToken108=== PAUSE TestScriptTokenEmptyToken109=== RUN TestScriptTokenBadJSON110=== PAUSE TestScriptTokenBadJSON111=== RUN TestScriptTokenScriptFails112=== PAUSE TestScriptTokenScriptFails113=== RUN TestScriptTokenEmptyCommand114=== PAUSE TestScriptTokenEmptyCommand115=== CONT TestDoServerRequestAttachesToken116=== CONT TestDoWithRetry_BodyReplayedViaGetBody117=== CONT TestPathInfoHashCompatibility118=== RUN TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)119=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)120=== CONT TestDumpPathWriterError121=== CONT TestResolveStorePath122=== CONT TestRegisterUploadedObject_BoundedAgainstSilentServer123=== CONT TestRateLimiterFeedback_400DoesNotCountAsSuccess124=== CONT TestRateLimiterFeedback125=== CONT TestPathInfoCACompatibility1262026/11/01 16:14:04 WARN Rate limiter enabled after throttle name=server-test rate=5127=== CONT TestParsePathInfoJSONMultiplePaths128=== CONT TestParsePathInfoJSON129=== RUN TestPathInfoHashCompatibility/old_string_format_with_colon130=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_colon131=== RUN TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI132=== PAUSE TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI133=== RUN TestPathInfoHashCompatibility/new_structured_format_with_sha512134=== CONT TestGetStorePathHash135=== CONT TestConvertHashToNix32136=== RUN TestConvertHashToNix32/SRI_format_to_Nix32137=== RUN TestGetStorePathHash/valid_store_path138=== PAUSE TestGetStorePathHash/valid_store_path139=== RUN TestGetStorePathHash/basename_without_hyphen_should_error140=== PAUSE TestGetStorePathHash/basename_without_hyphen_should_error141=== RUN TestGetStorePathHash/hash_with_invalid_characters_should_error142=== PAUSE TestGetStorePathHash/hash_with_invalid_characters_should_error143=== RUN TestGetStorePathHash/hash_with_wrong_length_should_error144=== PAUSE TestGetStorePathHash/hash_with_wrong_length_should_error145--- PASS: TestResolveStorePath (0.00s)146=== CONT TestStaticToken147--- PASS: TestStaticToken (0.00s)148=== CONT TestSetClientTLSErrors149=== RUN TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths150=== PAUSE TestConvertHashToNix32/SRI_format_to_Nix32151=== RUN TestConvertHashToNix32/already_Nix32_format152=== CONT TestEncodeNixBase32153=== CONT TestSetClientTLS154=== CONT TestScriptTokenEmptyCommand155=== CONT TestScriptTokenScriptFails156=== CONT TestScriptTokenBadJSON157=== CONT TestScriptTokenEmptyToken158=== CONT TestScriptTokenCachesUntilRefresh159=== CONT TestScriptTokenNoExpiryRerunsEveryCall160=== CONT TestFileTokenEmpty161=== CONT TestFileTokenMissing162=== RUN TestRateLimiterFeedback/429_enables_limiter163=== RUN TestPathInfoCACompatibility/null_ca_field164=== RUN TestParsePathInfoJSON/Nix_format165=== CONT TestEncodeNixBase32WithRealHash166=== PAUSE TestPathInfoHashCompatibility/new_structured_format_with_sha512167=== CONT TestFileTokenReadsAndCaches168--- PASS: TestEncodeNixBase32WithRealHash (0.00s)1692026/11/01 16:14:04 WARN Rate limiter enabled after throttle name=server-test rate=51702026/11/01 16:14:04 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:58766171=== PAUSE TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths172=== PAUSE TestRateLimiterFeedback/429_enables_limiter173=== PAUSE TestParsePathInfoJSON/Nix_format174=== RUN TestEncodeNixBase32/test_string_hash175=== PAUSE TestPathInfoCACompatibility/null_ca_field176--- PASS: TestScriptTokenEmptyCommand (0.00s)177--- PASS: TestDoServerRequestAttachesToken (0.00s)178=== CONT TestStreamPushStopsWhenCanceled179--- PASS: TestStreamPushStopsWhenCanceled (0.00s)180=== RUN TestPathInfoCACompatibility/old_string_format_-_text181=== PAUSE TestPathInfoCACompatibility/old_string_format_-_text182=== CONT TestStreamPushGivesUpOnDeadServer183=== CONT TestStreamPushRequestLine184=== RUN TestPathInfoCACompatibility/old_string_format_-_fixed_recursive185=== PAUSE TestPathInfoCACompatibility/old_string_format_-_fixed_recursive186=== RUN TestPathInfoCACompatibility/new_structured_format_-_text187=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_text188=== RUN TestPathInfoCACompatibility/new_structured_format_-_nar_method189=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_nar_method190=== CONT TestClientSignaturesByStorePath191=== CONT TestDumpPathSingleFile192=== CONT TestDumpPathMatchesNix193=== CONT TestUploadMultipart_PartsInParallel1942026/11/01 16:14:04 WARN Rate limiter backed off name=server-test rate=51952026/11/01 16:14:04 WARN Request returned retryable status, retrying attempt=2 backoff=0s status=503 url=http://127.0.0.1:58766196=== RUN TestSetClientTLS/rejects_connection_without_client_cert1972026/11/01 16:14:04 ERROR Upload failed error="connection refused" count=201982026/11/01 16:14:04 ERROR Server seems unavailable, giving up on batch untried=171992026/11/01 16:14:04 ERROR Upload failed error=boom count=1200=== PAUSE TestSetClientTLS/rejects_connection_without_client_cert201=== CONT TestStreamPushIsolatesFailures202=== CONT TestSetClientTLSDoesNotMutateDefaultTransport203=== RUN TestSetClientTLSErrors/missing_cert_file204=== CONT TestStreamPushReportsSkippedPaths205=== CONT TestStreamPushReportsSignatures206=== RUN TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths207=== RUN TestRateLimiterFeedback/503_enables_limiter208=== RUN TestParsePathInfoJSON/Lix_format209=== PAUSE TestEncodeNixBase32/test_string_hash210--- PASS: TestFileTokenReadsAndCaches (0.01s)211=== PAUSE TestConvertHashToNix32/already_Nix32_format212=== RUN TestSetClientTLS/succeeds_with_client_cert_and_CA213--- PASS: TestScriptTokenScriptFails (0.01s)214--- PASS: TestFileTokenMissing (0.01s)215--- PASS: TestClientSignaturesByStorePath (0.00s)216--- PASS: TestFileTokenEmpty (0.01s)217--- PASS: TestDoWithRetry_BodyReplayedViaGetBody (0.01s)218=== PAUSE TestSetClientTLS/succeeds_with_client_cert_and_CA219=== PAUSE TestRateLimiterFeedback/503_enables_limiter220=== RUN TestConvertHashToNix32/invalid_format221=== PAUSE TestConvertHashToNix32/invalid_format222=== PAUSE TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths223=== RUN TestEncodeNixBase32/empty_input224=== PAUSE TestEncodeNixBase32/empty_input225=== CONT TestUploadMultipart_SupersededByPeer226=== RUN TestUploadMultipart_SupersededByPeer/exists227=== PAUSE TestUploadMultipart_SupersededByPeer/exists228=== RUN TestUploadMultipart_SupersededByPeer/missing229=== PAUSE TestUploadMultipart_SupersededByPeer/missing230=== PAUSE TestParsePathInfoJSON/Lix_format231=== RUN TestParsePathInfoJSON/empty_input232=== PAUSE TestParsePathInfoJSON/empty_input233=== RUN TestParsePathInfoJSON/whitespace_only234=== PAUSE TestParsePathInfoJSON/whitespace_only235=== RUN TestParsePathInfoJSON/invalid_JSON236=== PAUSE TestParsePathInfoJSON/invalid_JSON237=== CONT TestPartSizeForNAR238=== RUN TestPartSizeForNAR/zero_stays_at_minimum239=== PAUSE TestPartSizeForNAR/zero_stays_at_minimum240=== RUN TestPartSizeForNAR/small_stays_at_minimum241=== PAUSE TestPartSizeForNAR/small_stays_at_minimum242=== RUN TestPartSizeForNAR/80_GiB_fits_at_minimum243=== PAUSE TestPartSizeForNAR/80_GiB_fits_at_minimum244=== RUN TestPartSizeForNAR/115_GiB_needs_larger_parts245=== PAUSE TestPartSizeForNAR/115_GiB_needs_larger_parts246=== RUN TestPartSizeForNAR/1_TiB247=== PAUSE TestPartSizeForNAR/1_TiB248=== RUN TestPartSizeForNAR/5_TiB_S3_max_object249=== PAUSE TestPartSizeForNAR/5_TiB_S3_max_object250=== RUN TestPartSizeForNAR/capped_at_5_GiB251=== PAUSE TestPartSizeForNAR/capped_at_5_GiB252=== RUN TestSetClientTLS/preserves_debug_logging_transport253=== PAUSE TestSetClientTLS/preserves_debug_logging_transport254=== CONT TestUploadMultipart_FailedPartBufferNotReused255=== CONT TestCaseHackSuffix256=== CONT TestFilterOversizedClosures257=== RUN TestFilterOversizedClosures/no_limit_keeps_everything258=== PAUSE TestFilterOversizedClosures/no_limit_keeps_everything259=== RUN TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped260=== PAUSE TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped261=== RUN TestRateLimiterFeedback/200_does_not_enable_limiter262=== CONT TestRunGarbageCollection_NotFoundAfterLocalRun263=== PAUSE TestRateLimiterFeedback/200_does_not_enable_limiter264=== RUN TestFilterOversizedClosures/all_closures_skipped265=== CONT TestRegisterUploadedObjectReusesConnections266=== CONT TestSupersededNARStillUploadsListing267=== PAUSE TestSetClientTLSErrors/missing_cert_file268=== RUN TestSetClientTLSErrors/missing_key_file269=== RUN TestRateLimiterFeedback/400_does_not_enable_limiter270=== PAUSE TestFilterOversizedClosures/all_closures_skipped271=== CONT TestRunGarbageCollection_FinishedOnAnotherReplica272--- PASS: TestStreamPushGivesUpOnDeadServer (0.01s)273=== CONT TestUploadBuildLog_FileBodyReplayedOnRetry2742026/11/01 16:14:04 INFO Garbage collection started275--- PASS: TestStreamPushReportsSkippedPaths (0.00s)276=== CONT TestShellSplitErrors277--- PASS: TestShellSplitErrors (0.00s)278=== CONT TestStreamPushBatchesUnderLoad279=== RUN TestSupersededNARStillUploadsListing/small_NAR2802026/11/01 16:14:04 ERROR Upload failed error="bad path" count=3281--- PASS: TestStreamPushIsolatesFailures (0.00s)282=== RUN TestStreamPushBatchesUnderLoad/oneAtATime=false283=== PAUSE TestStreamPushBatchesUnderLoad/oneAtATime=false284=== RUN TestStreamPushBatchesUnderLoad/oneAtATime=true285=== PAUSE TestSupersededNARStillUploadsListing/small_NAR286=== RUN TestSupersededNARStillUploadsListing/dump_cut_short287=== PAUSE TestSupersededNARStillUploadsListing/dump_cut_short288=== RUN TestSupersededNARStillUploadsListing/listing_upload_fails289=== PAUSE TestSupersededNARStillUploadsListing/listing_upload_fails290=== CONT TestStreamPushReportsEveryPath291=== CONT TestDoWithRetry_FinalResponseBodyReadable292=== PAUSE TestSetClientTLSErrors/missing_key_file293=== RUN TestSetClientTLSErrors/missing_ca_file294=== PAUSE TestSetClientTLSErrors/missing_ca_file295=== RUN TestSetClientTLSErrors/invalid_ca_file296=== PAUSE TestSetClientTLSErrors/invalid_ca_file297=== PAUSE TestRateLimiterFeedback/400_does_not_enable_limiter298=== PAUSE TestStreamPushBatchesUnderLoad/oneAtATime=true2992026/11/01 16:14:04 ERROR Upload failed error=boom count=1300--- PASS: TestStreamPushReportsSignatures (0.00s)301=== CONT TestGetStorePathHash/hash_with_wrong_length_should_error302=== CONT TestGetStorePathHash/hash_with_invalid_characters_should_error303=== CONT TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)304--- PASS: TestStreamPushReportsEveryPath (0.00s)305=== CONT TestGetStorePathHash/basename_without_hyphen_should_error306--- PASS: TestScriptTokenEmptyToken (0.02s)307=== CONT TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI308=== CONT TestPathInfoHashCompatibility/new_structured_format_with_sha512309=== CONT TestPathInfoCACompatibility/null_ca_field310=== CONT TestPathInfoCACompatibility/new_structured_format_-_nar_method311=== CONT TestShellSplit312--- PASS: TestShellSplit (0.00s)313=== CONT TestPathInfoCACompatibility/new_structured_format_-_text3142026/11/01 16:14:04 WARN Rate limiter enabled after throttle name=server-test rate=53152026/11/01 16:14:04 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:58784316=== CONT TestPathInfoCACompatibility/old_string_format_-_fixed_recursive317=== CONT TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths318=== CONT TestPathInfoCACompatibility/old_string_format_-_text319=== CONT TestPathInfoHashCompatibility/old_string_format_with_colon320=== CONT TestRetryTimeoutOutlastsMaxRetries321=== CONT TestConvertHashToNix32/SRI_format_to_Nix32322=== CONT TestConvertHashToNix32/invalid_format323=== CONT TestConvertHashToNix32/already_Nix32_format324=== CONT TestParsePathInfoJSON/Nix_format325=== CONT TestPartSizeForNAR/zero_stays_at_minimum326=== CONT TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths327=== CONT TestSetClientTLS/rejects_connection_without_client_cert328=== CONT TestEncodeNixBase32/empty_input329=== CONT TestUploadMultipart_SupersededByPeer/missing330=== CONT TestGetStorePathHash/valid_store_path331=== CONT TestParsePathInfoJSON/whitespace_only332=== CONT TestParsePathInfoJSON/empty_input333=== CONT TestPartSizeForNAR/5_TiB_S3_max_object334=== CONT TestPartSizeForNAR/1_TiB335=== CONT TestPartSizeForNAR/115_GiB_needs_larger_parts336=== CONT TestPartSizeForNAR/80_GiB_fits_at_minimum337=== CONT TestPartSizeForNAR/small_stays_at_minimum338=== CONT TestParsePathInfoJSON/Lix_format339=== CONT TestSetClientTLS/succeeds_with_client_cert_and_CA340=== CONT TestEncodeNixBase32/test_string_hash341=== CONT TestSetClientTLS/preserves_debug_logging_transport342=== CONT TestParsePathInfoJSON/invalid_JSON343=== CONT TestFilterOversizedClosures/no_limit_keeps_everything344=== CONT TestFilterOversizedClosures/all_closures_skipped3452026/11/01 16:14:04 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=50346=== CONT TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped3472026/11/01 16:14:04 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=2000348=== CONT TestSupersededNARStillUploadsListing/small_NAR349=== CONT TestSupersededNARStillUploadsListing/dump_cut_short350--- PASS: TestPathInfoCACompatibility (0.01s)351 --- PASS: TestPathInfoCACompatibility/null_ca_field (0.00s)352 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_nar_method (0.00s)353 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_text (0.00s)354 --- PASS: TestPathInfoCACompatibility/old_string_format_-_fixed_recursive (0.00s)355 --- PASS: TestPathInfoCACompatibility/old_string_format_-_text (0.00s)356=== CONT TestUploadMultipart_SupersededByPeer/exists357=== CONT TestPartSizeForNAR/capped_at_5_GiB358=== CONT TestSupersededNARStillUploadsListing/listing_upload_fails359--- PASS: TestConvertHashToNix32 (0.01s)360 --- PASS: TestConvertHashToNix32/SRI_format_to_Nix32 (0.00s)361 --- PASS: TestConvertHashToNix32/invalid_format (0.00s)362 --- PASS: TestConvertHashToNix32/already_Nix32_format (0.00s)363--- PASS: TestParsePathInfoJSONMultiplePaths (0.01s)364 --- PASS: TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths (0.00s)365 --- PASS: TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths (0.00s)366--- PASS: TestPathInfoHashCompatibility (0.00s)367 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) (0.00s)368 --- PASS: TestPathInfoHashCompatibility/new_structured_format_with_sha512 (0.00s)369 --- PASS: TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI (0.00s)370 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_colon (0.00s)371--- PASS: TestGetStorePathHash (0.00s)372 --- PASS: TestGetStorePathHash/hash_with_wrong_length_should_error (0.00s)373 --- PASS: TestGetStorePathHash/hash_with_invalid_characters_should_error (0.00s)374 --- PASS: TestGetStorePathHash/basename_without_hyphen_should_error (0.00s)375 --- PASS: TestGetStorePathHash/valid_store_path (0.00s)376--- PASS: TestSetClientTLSDoesNotMutateDefaultTransport (0.00s)377--- PASS: TestScriptTokenBadJSON (0.02s)378--- PASS: TestPartSizeForNAR (0.00s)379 --- PASS: TestPartSizeForNAR/zero_stays_at_minimum (0.00s)380 --- PASS: TestPartSizeForNAR/5_TiB_S3_max_object (0.00s)381 --- PASS: TestPartSizeForNAR/1_TiB (0.00s)382 --- PASS: TestPartSizeForNAR/115_GiB_needs_larger_parts (0.00s)383 --- PASS: TestPartSizeForNAR/80_GiB_fits_at_minimum (0.00s)384 --- PASS: TestPartSizeForNAR/small_stays_at_minimum (0.00s)385 --- PASS: TestPartSizeForNAR/capped_at_5_GiB (0.00s)386--- PASS: TestEncodeNixBase32 (0.01s)387 --- PASS: TestEncodeNixBase32/empty_input (0.00s)388 --- PASS: TestEncodeNixBase32/test_string_hash (0.00s)389--- PASS: TestParsePathInfoJSON (0.01s)390 --- PASS: TestParsePathInfoJSON/Nix_format (0.00s)391 --- PASS: TestParsePathInfoJSON/whitespace_only (0.00s)392 --- PASS: TestParsePathInfoJSON/empty_input (0.00s)393 --- PASS: TestParsePathInfoJSON/Lix_format (0.00s)394 --- PASS: TestParsePathInfoJSON/invalid_JSON (0.00s)395--- PASS: TestFilterOversizedClosures (0.01s)396 --- PASS: TestFilterOversizedClosures/no_limit_keeps_everything (0.00s)397 --- PASS: TestFilterOversizedClosures/all_closures_skipped (0.00s)398 --- PASS: TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped (0.00s)399--- PASS: TestRunGarbageCollection_NotFoundAfterLocalRun (0.00s)4002026/11/01 16:14:04 WARN Rate limiter backed off name=server-test rate=5401--- PASS: TestDoWithRetry_FinalResponseBodyReadable (0.00s)402=== CONT TestSetClientTLSErrors/missing_cert_file403=== CONT TestSetClientTLSErrors/invalid_ca_file4042026/11/01 16:14:04 WARN Rate limiter enabled after throttle name=s3-test rate=54052026/11/01 16:14:04 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:58803406=== CONT TestSetClientTLSErrors/missing_ca_file4072026/11/01 16:14:04 INFO Uploading abc-hello (1.0GB)4082026/11/01 16:14:04 INFO Uploading abc-hello (1.0GB)4092026/11/01 16:14:04 INFO Garbage collection started410=== CONT TestSetClientTLSErrors/missing_key_file411=== CONT TestRateLimiterFeedback/429_enables_limiter412=== CONT TestStreamPushBatchesUnderLoad/oneAtATime=false413=== CONT TestStreamPushBatchesUnderLoad/oneAtATime=true414--- PASS: TestStreamPushBatchesUnderLoad (0.00s)415 --- PASS: TestStreamPushBatchesUnderLoad/oneAtATime=false (0.00s)416 --- PASS: TestStreamPushBatchesUnderLoad/oneAtATime=true (0.00s)417=== CONT TestRateLimiterFeedback/400_does_not_enable_limiter418--- PASS: TestSetClientTLSErrors (0.02s)419 --- PASS: TestSetClientTLSErrors/missing_cert_file (0.00s)420 --- PASS: TestSetClientTLSErrors/invalid_ca_file (0.00s)421 --- PASS: TestSetClientTLSErrors/missing_key_file (0.00s)422 --- PASS: TestSetClientTLSErrors/missing_ca_file (0.01s)423--- PASS: TestUploadBuildLog_FileBodyReplayedOnRetry (0.02s)424=== CONT TestRateLimiterFeedback/200_does_not_enable_limiter4252026/11/01 16:14:04 WARN Request returned retryable status, retrying attempt=1 backoff=1ms status=502 url=http://127.0.0.1:58854426=== CONT TestRateLimiterFeedback/503_enables_limiter4272026/11/01 16:14:04 WARN Rate limiter enabled after throttle name=server-test rate=54282026/11/01 16:14:04 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=429 url=http://127.0.0.1:588684292026/11/01 16:14:04 WARN Rate limiter backed off name=server-test rate=54302026/11/01 16:14:04 WARN Request returned retryable status, retrying attempt=2 backoff=1ms status=502 url=http://127.0.0.1:58854431--- PASS: TestUploadMultipart_SupersededByPeer (0.00s)432 --- PASS: TestUploadMultipart_SupersededByPeer/exists (0.01s)433 --- PASS: TestUploadMultipart_SupersededByPeer/missing (0.02s)4342026/11/01 16:14:04 WARN Rate limiter enabled after throttle name=server-test rate=54352026/11/01 16:14:04 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:588794362026/11/01 16:14:04 WARN Request returned retryable status, retrying attempt=1 backoff=1ms status=502 url=http://127.0.0.1:588544372026/11/01 16:14:04 WARN Rate limiter enabled after throttle name=s3-test rate=54382026/11/01 16:14:04 WARN Rate limiter backed off name=server-test rate=5439--- PASS: TestRateLimiterFeedback (0.02s)440 --- PASS: TestRateLimiterFeedback/400_does_not_enable_limiter (0.00s)441 --- PASS: TestRateLimiterFeedback/429_enables_limiter (0.00s)442 --- PASS: TestRateLimiterFeedback/503_enables_limiter (0.01s)443 --- PASS: TestRateLimiterFeedback/200_does_not_enable_limiter (0.01s)4442026/11/01 16:14:04 WARN Request returned retryable status, retrying attempt=2 backoff=1ms status=502 url=http://127.0.0.1:58854445--- PASS: TestStreamPushRequestLine (0.04s)4462026/11/01 16:14:04 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=04472026/11/01 16:14:04 WARN Garbage collection finished on another replica. Its statistics are not available here448--- PASS: TestRunGarbageCollection_FinishedOnAnotherReplica (0.03s)4492026/11/01 16:14:04 WARN Request returned retryable status, retrying attempt=3 backoff=1ms status=502 url=http://127.0.0.1:588544502026/11/01 16:14:04 WARN Request returned retryable status, retrying attempt=4 backoff=1ms status=502 url=http://127.0.0.1:58854451--- PASS: TestScriptTokenCachesUntilRefresh (0.05s)4522026/11/01 16:14:04 WARN Request returned retryable status, retrying attempt=5 backoff=1ms status=502 url=http://127.0.0.1:588544532026/11/01 16:14:04 WARN Request returned retryable status, retrying attempt=6 backoff=1ms status=502 url=http://127.0.0.1:588544542026/11/01 16:14:04 WARN Request returned retryable status, retrying attempt=7 backoff=1ms status=502 url=http://127.0.0.1:588544552026/11/01 16:14:04 WARN Request returned retryable status, retrying attempt=8 backoff=1ms status=502 url=http://127.0.0.1:588544562026/11/01 16:14:04 WARN Request returned retryable status, retrying attempt=9 backoff=1ms status=502 url=http://127.0.0.1:588544572026/11/01 16:14:04 WARN Request returned retryable status, retrying attempt=10 backoff=1ms status=502 url=http://127.0.0.1:58854458--- PASS: TestRegisterUploadedObjectReusesConnections (0.05s)4592026/11/01 16:14:04 WARN Request returned retryable status, retrying attempt=11 backoff=1ms status=502 url=http://127.0.0.1:588544602026/11/01 16:14:04 http: TLS handshake error from 127.0.0.1:58855: remote error: tls: bad certificate461--- PASS: TestSetClientTLS (0.01s)462 --- PASS: TestSetClientTLS/preserves_debug_logging_transport (0.03s)463 --- PASS: TestSetClientTLS/succeeds_with_client_cert_and_CA (0.04s)464 --- PASS: TestSetClientTLS/rejects_connection_without_client_cert (0.04s)4652026/11/01 16:14:04 WARN Request returned retryable status, retrying attempt=12 backoff=1ms status=502 url=http://127.0.0.1:58854466--- PASS: TestScriptTokenNoExpiryRerunsEveryCall (0.07s)4672026/11/01 16:14:04 WARN Request returned retryable status, retrying attempt=13 backoff=1ms status=502 url=http://127.0.0.1:588544682026/11/01 16:14:04 WARN Request returned retryable status, retrying attempt=14 backoff=1ms status=502 url=http://127.0.0.1:588544692026/11/01 16:14:04 WARN Request returned retryable status, retrying attempt=15 backoff=1ms status=502 url=http://127.0.0.1:588544702026/11/01 16:14:04 WARN Request returned retryable status, retrying attempt=16 backoff=1ms status=502 url=http://127.0.0.1:58854471--- PASS: TestDumpPathWriterError (0.08s)4722026/11/01 16:14:04 WARN Request returned retryable status, retrying attempt=17 backoff=1ms status=502 url=http://127.0.0.1:588544732026/11/01 16:14:04 INFO Uploading abc-hello (1.0GB)474--- PASS: TestRetryTimeoutOutlastsMaxRetries (0.06s)4752026/11/01 16:14:04 WARN Request failed, retrying attempt=1 backoff=100ms error="Put \"http://127.0.0.1:58856/part/2\": uploading part 1: server returned 404: no such upload\n" url=http://127.0.0.1:58856/part/24762026/11/01 16:14:04 ERROR Failed to close zstd encoder error="io: read/write on closed pipe"477--- PASS: TestDumpPathSingleFile (0.09s)478--- PASS: TestCaseHackSuffix (0.08s)479--- PASS: TestDumpPathMatchesNix (0.10s)480--- PASS: TestSupersededNARStillUploadsListing (0.00s)481 --- PASS: TestSupersededNARStillUploadsListing/listing_upload_fails (0.01s)482 --- PASS: TestSupersededNARStillUploadsListing/small_NAR (0.02s)483 --- PASS: TestSupersededNARStillUploadsListing/dump_cut_short (0.56s)484--- PASS: TestUploadMultipart_FailedPartBufferNotReused (0.58s)485--- PASS: TestUploadMultipart_PartsInParallel (0.62s)4862026/11/01 16:14:05 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:58767/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:58767/api/uploads/complete4872026/11/01 16:14:05 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"4882026/11/01 16:14:05 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:58767/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:58767/api/uploads/complete4892026/11/01 16:14:05 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"4902026/11/01 16:14:05 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:58767/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:58767/api/uploads/complete4912026/11/01 16:14:05 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"492--- PASS: TestRateLimiterFeedback_400DoesNotCountAsSuccess (1.00s)493--- PASS: TestRegisterUploadedObject_BoundedAgainstSilentServer (1.00s)494PASS495Running server tests...496The files belonging to this database system will be owned by user "_tribuchetbld3".497This user must also own the server process.498499The database cluster will be initialized with locale "C".500The default database encoding has accordingly been set to "SQL_ASCII".501The default text search configuration will be set to "english".502503Data page checksums are enabled.504505creating directory /private/var/tb/3/scratch/4a1a633e2471393e/build/postgres3672006957/data ... ok506creating subdirectories ... ok507selecting dynamic shared memory implementation ... posix508selecting default "max_connections" ... 100509selecting default "shared_buffers" ... 128MB510selecting default time zone ... UTC511creating configuration files ... ok512running bootstrap script ... ok513performing post-bootstrap initialization ... ok514syncing data to disk ... ok515516initdb: warning: enabling "trust" authentication for local connections517initdb: 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.518519Success. You can now start the database server using:520521 pg_ctl -D /private/var/tb/3/scratch/4a1a633e2471393e/build/postgres3672006957/data -l logfile start5225232026-11-01 16:14:07.696 UTC [94831] LOG: starting PostgreSQL 18.6 on aarch64-apple-darwin25.6.0, compiled by clang version 21.1.8, 64-bit5242026-11-01 16:14:07.696 UTC [94831] LOG: listening on Unix socket "/private/var/tb/3/scratch/4a1a633e2471393e/build/postgres3672006957/.s.PGSQL.5432"5252026-11-01 16:14:07.699 UTC [94838] LOG: database system was shut down at 2026-11-01 16:14:07 UTC5262026-11-01 16:14:07.700 UTC [94831] LOG: database system is ready to accept connections527/private/var/tb/3/scratch/4a1a633e2471393e/build/postgres3672006957:5432 - accepting connections528{"timestamp":"2026-11-01T16:14:09.993814Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"18b234f7-91fb-4cd6-9485-a76ca4e5ffc5","trace_id":"unknown","span_id":"unknown","peer_addr":"127.0.0.1","method":"GET","uri":"/health/ready","status_code":503,"suppressed_errors":0,"duration_ms":1,"result":"server_error","target":"rustfs::server::http","filename":"rustfs/src/server/layer.rs","line_number":502,"threadName":"rustfs-worker","threadId":"ThreadId(5)"}529{"timestamp":"2026-11-01T16:14:10.100579Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"072276be-e7d8-4655-8f33-cd68da72b3d0","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(3)"}530=== RUN TestService_AuthMiddleware531=== PAUSE TestService_AuthMiddleware532=== RUN TestService_AuthMiddleware_MTLSProxyHeader533=== PAUSE TestService_AuthMiddleware_MTLSProxyHeader534=== RUN TestService_AuthMiddleware_MTLSBoundSubjects535=== PAUSE TestService_AuthMiddleware_MTLSBoundSubjects536=== RUN TestService_ReadAuthMiddleware537=== PAUSE TestService_ReadAuthMiddleware538=== RUN TestService_AuthMiddleware_OIDC539=== PAUSE TestService_AuthMiddleware_OIDC540=== RUN TestService_RequireScope_OIDC541=== PAUSE TestService_RequireScope_OIDC542=== RUN TestService_ReadScope_PublicByDefault543=== PAUSE TestService_ReadScope_PublicByDefault544=== RUN TestCacheConfigHandler545=== PAUSE TestCacheConfigHandler546=== RUN TestCacheStatsHandler547=== PAUSE TestCacheStatsHandler548=== RUN TestClientCADerivations549=== PAUSE TestClientCADerivations550=== RUN TestClientErrorHandling551=== PAUSE TestClientErrorHandling552=== RUN TestClientIntegration553=== PAUSE TestClientIntegration554=== RUN TestClientMultipleUploads555=== PAUSE TestClientMultipleUploads556=== RUN TestClientWithDependencies557=== PAUSE TestClientWithDependencies558=== RUN TestClientSharedPathCommittedMidPush559=== PAUSE TestClientSharedPathCommittedMidPush560=== RUN TestPinProtectsFromGC561=== PAUSE TestPinProtectsFromGC562=== RUN TestClientPushesUseOnePush563=== PAUSE TestClientPushesUseOnePush564=== RUN TestClientFallsBackToClosures565=== PAUSE TestClientFallsBackToClosures566=== RUN TestDeleteClosuresRacingPins567=== PAUSE TestDeleteClosuresRacingPins568=== RUN TestConcurrentCommitsSharingObjectsDoNotDeadlock569=== PAUSE TestConcurrentCommitsSharingObjectsDoNotDeadlock570=== RUN TestResolveDBConnectionString571=== PAUSE TestResolveDBConnectionString572=== RUN TestConnectWaitsForAPeerMigration573=== PAUSE TestConnectWaitsForAPeerMigration574=== RUN TestLeadElectsOneAndHandsOver575=== PAUSE TestLeadElectsOneAndHandsOver576=== RUN TestLeadIncumbentWinsAfterRestart5772026/11/01 16:14:10 INFO lead: acquired remote=192.0.2.1:12345782026/11/01 16:14:11 INFO lead: released remote=192.0.2.1:12345792026/11/01 16:14:11 INFO lead: acquired remote=192.0.2.1:12345802026/11/01 16:14:12 INFO lead: released remote=192.0.2.1:1234581--- PASS: TestLeadIncumbentWinsAfterRestart (2.23s)582=== RUN TestLeadIncumbentAnnouncesAtOnce583=== PAUSE TestLeadIncumbentAnnouncesAtOnce584=== RUN TestLeadEndsOnShutdown585=== PAUSE TestLeadEndsOnShutdown586=== RUN TestLeadEndsWhenItsConnectionHangs5872026/11/01 16:14:12 INFO lead: acquired remote=192.0.2.1:12345882026-11-01 16:14:13.991 UTC [94894] FATAL: terminating connection due to administrator command5892026/11/01 16:14:14 INFO lead: acquired remote=192.0.2.1:12345902026/11/01 16:14:15 WARN lead: lock connection lost error="timeout: context deadline exceeded"5912026/11/01 16:14:15 INFO lead: released remote=192.0.2.1:12345922026/11/01 16:14:15 INFO lead: released remote=192.0.2.1:1234593--- PASS: TestLeadEndsWhenItsConnectionHangs (2.95s)594=== RUN TestGCAdvisoryLockBlocksConcurrentRun595=== PAUSE TestGCAdvisoryLockBlocksConcurrentRun596=== RUN TestGCBugBareHashReferences597=== PAUSE TestGCBugBareHashReferences598=== RUN TestGCMetrics599=== PAUSE TestGCMetrics600=== RUN TestPushDedupSurvivesConcurrentGC601=== PAUSE TestPushDedupSurvivesConcurrentGC602=== RUN TestDeduplicatedObjectsRecordedAsPending603=== PAUSE TestDeduplicatedObjectsRecordedAsPending604=== RUN TestGCSweepSkipsPendingObjects605=== PAUSE TestGCSweepSkipsPendingObjects606=== RUN TestTombstonedObjectOfferedWithoutWaiting607=== PAUSE TestTombstonedObjectOfferedWithoutWaiting608=== RUN TestGCSweepDeliversEachKeyOnce609=== PAUSE TestGCSweepDeliversEachKeyOnce610=== RUN TestCreatePendingClosureVerifyS3FailureReleasesConnection611=== PAUSE TestCreatePendingClosureVerifyS3FailureReleasesConnection612=== RUN TestForceGCDuringPushOffersSweptObject613=== PAUSE TestForceGCDuringPushOffersSweptObject614=== RUN TestFailedS3DeleteKeepsTombstone615=== PAUSE TestFailedS3DeleteKeepsTombstone616=== RUN TestSweepSkipsRowsLockedByPush617=== PAUSE TestSweepSkipsRowsLockedByPush618=== RUN TestRegisterCompletedObjectNeedsPendingRow619=== PAUSE TestRegisterCompletedObjectNeedsPendingRow620=== RUN TestGetExistingObjectsLocksRows621=== PAUSE TestGetExistingObjectsLocksRows622=== RUN TestSweepRechecksPendingAfterLocking623=== PAUSE TestSweepRechecksPendingAfterLocking624=== RUN TestPushWaitsForSweepHoldingRow625=== PAUSE TestPushWaitsForSweepHoldingRow626=== RUN TestCommitRacingPendingCleanupKeepsObjects627=== PAUSE TestCommitRacingPendingCleanupKeepsObjects628=== RUN TestGCEndsOnShutdown629=== PAUSE TestGCEndsOnShutdown630=== RUN TestGCTaskStore_StartNew631=== PAUSE TestGCTaskStore_StartNew632=== RUN TestGCTaskStore_DeduplicateSameParams633=== PAUSE TestGCTaskStore_DeduplicateSameParams634=== RUN TestGCTaskStore_ConflictDifferentParams635=== PAUSE TestGCTaskStore_ConflictDifferentParams636=== RUN TestGCTaskStore_GetEmpty637=== PAUSE TestGCTaskStore_GetEmpty638=== RUN TestGCTaskStore_GetReturnsLatest639=== PAUSE TestGCTaskStore_GetReturnsLatest640=== RUN TestGCTaskStore_CompletedAllowsNewTask641=== PAUSE TestGCTaskStore_CompletedAllowsNewTask642=== RUN TestGCTaskStore_PhaseUpdates643=== PAUSE TestGCTaskStore_PhaseUpdates644=== RUN TestGCTaskStore_Fail645=== PAUSE TestGCTaskStore_Fail646=== RUN TestGracefulShutdownDrainsInflight647=== PAUSE TestGracefulShutdownDrainsInflight648=== RUN TestService_healthCheckHandler649=== PAUSE TestService_healthCheckHandler650=== RUN TestService_readinessHandler651=== PAUSE TestService_readinessHandler652=== RUN TestGenerateLandingPage653=== PAUSE TestGenerateLandingPage654=== RUN TestCacheConfigHandlerMaxNarSize655=== PAUSE TestCacheConfigHandlerMaxNarSize656=== RUN TestCreatePendingClosureRejectsOversizedNAR657=== PAUSE TestCreatePendingClosureRejectsOversizedNAR658=== RUN TestNARDeduplicationMetadataUploadBug659=== PAUSE TestNARDeduplicationMetadataUploadBug660=== RUN TestMetricsInventory661=== PAUSE TestMetricsInventory662=== RUN TestMetricsCommit663=== PAUSE TestMetricsCommit664=== RUN TestService_NativeMTLS665=== PAUSE TestService_NativeMTLS666=== RUN TestServerTLSConfig667=== PAUSE TestServerTLSConfig668=== RUN TestMultipartCleanup669=== PAUSE TestMultipartCleanup670=== RUN TestMultipartUploadAbortedWhenCancelledBeforeRecorded671=== PAUSE TestMultipartUploadAbortedWhenCancelledBeforeRecorded672=== RUN TestPendingCleanupUsesOneCutoff673=== PAUSE TestPendingCleanupUsesOneCutoff674=== RUN TestObjectStatsTrigger675=== PAUSE TestObjectStatsTrigger676=== RUN TestObjectStatsUpdatedOncePerCommit677=== PAUSE TestObjectStatsUpdatedOncePerCommit678=== RUN TestOrphanedObjectsGC679=== PAUSE TestOrphanedObjectsGC680=== RUN TestOrphanedObjectsGCStressTest681=== PAUSE TestOrphanedObjectsGCStressTest682=== RUN TestCreatePin_ReservedPins683=== PAUSE TestCreatePin_ReservedPins684=== RUN TestPresentReportsOnlyClosureRoots685=== PAUSE TestPresentReportsOnlyClosureRoots686=== RUN TestPresentRefreshesOnlyStaleClosures687=== PAUSE TestPresentRefreshesOnlyStaleClosures688=== RUN TestPresentNotReportedWhileGCDeletesClosure689=== PAUSE TestPresentNotReportedWhileGCDeletesClosure690=== RUN TestParseSingleRange691=== PAUSE TestParseSingleRange692=== RUN TestProxyHeadersOnlyTrustedOnSocket6932026/11/01 16:14:15 INFO Starting HTTP server address=127.0.0.1:589476942026/11/01 16:14:15 INFO Starting HTTP server address=proxy.sock6952026/11/01 16:14:15 WARN mTLS auth: subject not in bound subjects subject="CN=someone"6962026/11/01 16:14:15 INFO Shutdown signal received, draining in-flight requests timeout=10s697--- PASS: TestProxyHeadersOnlyTrustedOnSocket (0.16s)698=== RUN TestIsValidCachePath699=== PAUSE TestIsValidCachePath700=== RUN TestReadProxyNarinfo701=== PAUSE TestReadProxyNarinfo702=== RUN TestReadProxyNarinfoAlreadyDecompressed703=== PAUSE TestReadProxyNarinfoAlreadyDecompressed704=== RUN TestReadProxyContentNegotiation705=== PAUSE TestReadProxyContentNegotiation706=== RUN TestReadProxyNarStreaming707=== PAUSE TestReadProxyNarStreaming708=== RUN TestReadProxy404709=== PAUSE TestReadProxy404710=== RUN TestReadProxyInvalidPath711=== PAUSE TestReadProxyInvalidPath712=== RUN TestReadProxyHead713=== PAUSE TestReadProxyHead714=== RUN TestReadProxyOutlastsServerWriteTimeout715=== PAUSE TestReadProxyOutlastsServerWriteTimeout716=== RUN TestReadProxyConditionalGet717=== PAUSE TestReadProxyConditionalGet718=== RUN TestReadProxyRootRedirectsToIndexHTML719=== PAUSE TestReadProxyRootRedirectsToIndexHTML720=== RUN TestReadProxyDisabled721=== PAUSE TestReadProxyDisabled722=== RUN TestReadRedirectNar723=== PAUSE TestReadRedirectNar724=== RUN TestReadRedirectKeepsNarinfoProxied725=== PAUSE TestReadRedirectKeepsNarinfoProxied726=== RUN TestReadProxyRangeRequest727=== PAUSE TestReadProxyRangeRequest728=== RUN TestReadRedirectUsesPublicS3URL729=== PAUSE TestReadRedirectUsesPublicS3URL730=== RUN TestPush_OverlappingRootsStoreOneRowPerKey731=== PAUSE TestPush_OverlappingRootsStoreOneRowPerKey732=== RUN TestPush_CompleteCommitsEveryRoot733=== PAUSE TestPush_CompleteCommitsEveryRoot734=== RUN TestPush_RepeatedRootCommitsOnce735=== PAUSE TestPush_RepeatedRootCommitsOnce736=== RUN TestPush_CompleteWaitsForCleanupOfThePush737=== PAUSE TestPush_CompleteWaitsForCleanupOfThePush738=== RUN TestPush_RootsAreLockedInByteOrder739=== PAUSE TestPush_RootsAreLockedInByteOrder740=== RUN TestPush_SkippedKeySurvivesGCBeforeCommit741=== PAUSE TestPush_SkippedKeySurvivesGCBeforeCommit742=== RUN TestPush_RejectsBadRequests743=== PAUSE TestPush_RejectsBadRequests744=== RUN TestPush_SignsNarinfosOfItsPendingObjects745=== PAUSE TestPush_SignsNarinfosOfItsPendingObjects746=== RUN TestRedundantMultipartUpload747=== PAUSE TestRedundantMultipartUpload748=== RUN TestCompleteMultipartUpload_ErrorButObjectExists749=== PAUSE TestCompleteMultipartUpload_ErrorButObjectExists750=== RUN TestCompletedNarNotReofferedAcrossClosures751=== PAUSE TestCompletedNarNotReofferedAcrossClosures752=== RUN TestPresignedUploadRegisteredBeforeCommit753=== PAUSE TestPresignedUploadRegisteredBeforeCommit754=== RUN TestService_Rustfstest755=== PAUSE TestService_Rustfstest756=== RUN TestParseSize757=== PAUSE TestParseSize758=== RUN TestSkippedUploadsHandler759=== PAUSE TestSkippedUploadsHandler760=== RUN TestSystemdListenerNotActivated761--- PASS: TestSystemdListenerNotActivated (0.00s)762=== RUN TestWatchdogBeatsWhenHealthy763--- PASS: TestWatchdogBeatsWhenHealthy (0.03s)764=== RUN TestWatchdogSkipsWhenUnhealthy7652026/11/01 16:14:15 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7662026/11/01 16:14:15 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7672026/11/01 16:14:15 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7682026/11/01 16:14:15 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7692026/11/01 16:14:15 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7702026/11/01 16:14:15 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7712026/11/01 16:14:15 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7722026/11/01 16:14:15 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7732026/11/01 16:14:15 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7742026/11/01 16:14:15 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"775--- PASS: TestWatchdogSkipsWhenUnhealthy (0.20s)776=== RUN TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle777=== PAUSE TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle778=== RUN TestProxyWriteTimeout779=== PAUSE TestProxyWriteTimeout780=== RUN TestPendingClosureWriteTimeout781=== PAUSE TestPendingClosureWriteTimeout782=== RUN TestIsValidUploadKey783=== PAUSE TestIsValidUploadKey784=== RUN TestUploadHandlersRejectInvalidKeys785=== PAUSE TestUploadHandlersRejectInvalidKeys786=== RUN TestUploadHandlersRejectOversizedBody787=== PAUSE TestUploadHandlersRejectOversizedBody788=== RUN TestService_cleanupPendingClosuresHandler789=== PAUSE TestService_cleanupPendingClosuresHandler790=== RUN TestService_createPendingClosureHandler791=== PAUSE TestService_createPendingClosureHandler792=== RUN TestService_verifyS3Integrity793=== PAUSE TestService_verifyS3Integrity794=== RUN TestService_verifyS3ReuploadsNarinfoOfLostNAR795=== PAUSE TestService_verifyS3ReuploadsNarinfoOfLostNAR796=== RUN TestCompleteMultipartUnregistered797=== PAUSE TestCompleteMultipartUnregistered798=== RUN TestCreatePendingClosure_SmallNARUsesSimplePUT799=== PAUSE TestCreatePendingClosure_SmallNARUsesSimplePUT800=== CONT TestReadProxyRangeRequest801=== CONT TestReadProxyConditionalGet802=== CONT TestClientSharedPathCommittedMidPush803=== CONT TestService_AuthMiddleware804=== CONT TestCommitRacingPendingCleanupKeepsObjects805=== CONT TestPinProtectsFromGC806=== CONT TestReadRedirectNar807=== CONT TestReadProxyDisabled808=== CONT TestGCEndsOnShutdown809=== RUN TestGCEndsOnShutdown/before_the_run810=== CONT TestGCTaskStore_StartNew811=== PAUSE TestGCEndsOnShutdown/before_the_run812=== RUN TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete813=== PAUSE TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete814--- PASS: TestGCTaskStore_StartNew (0.00s)815=== CONT TestPushWaitsForSweepHoldingRow816=== CONT TestSweepRechecksPendingAfterLocking817=== CONT TestGetExistingObjectsLocksRows818=== CONT TestRegisterCompletedObjectNeedsPendingRow819=== CONT TestSweepSkipsRowsLockedByPush820=== CONT TestFailedS3DeleteKeepsTombstone821=== CONT TestForceGCDuringPushOffersSweptObject822=== RUN TestForceGCDuringPushOffersSweptObject/before_pending_rows823=== CONT TestCreatePendingClosureVerifyS3FailureReleasesConnection824=== PAUSE TestForceGCDuringPushOffersSweptObject/before_pending_rows825=== RUN TestForceGCDuringPushOffersSweptObject/after_presence_check826=== CONT TestGCSweepDeliversEachKeyOnce827=== CONT TestGCSweepSkipsPendingObjects828=== CONT TestDeduplicatedObjectsRecordedAsPending829=== CONT TestReadRedirectKeepsNarinfoProxied830=== CONT TestPushDedupSurvivesConcurrentGC831=== CONT TestReadProxyRootRedirectsToIndexHTML832=== RUN TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark833=== PAUSE TestForceGCDuringPushOffersSweptObject/after_presence_check834=== CONT TestTombstonedObjectOfferedWithoutWaiting835=== PAUSE TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark836=== CONT TestGCMetrics837=== CONT TestGCBugBareHashReferences838--- PASS: TestReadProxyRangeRequest (0.82s)839=== CONT TestGCAdvisoryLockBlocksConcurrentRun8402026/11/01 16:14:17 WARN Authentication failed token_preview=wrongtoken token_length=10 reason="static API token mismatch"841--- PASS: TestService_AuthMiddleware (1.28s)842=== CONT TestLeadEndsOnShutdown843--- PASS: TestReadProxyConditionalGet (1.69s)844=== CONT TestLeadIncumbentAnnouncesAtOnce8452026/11/01 16:14:17 INFO Received push request method=POST path=/api/pushes8462026/11/01 16:14:17 INFO Uploading 2 paths to 127.0.0.1 (0 already cached)8472026/11/01 16:14:17 INFO Uploading fkszjlirk9bqpvvr7040bqx0bxzf3bd1-shared-dep (136B)8482026/11/01 16:14:17 INFO Uploading w4wa032gxgcz7rf96791gp3s6grf60nx-top (264B)8492026/11/01 16:14:17 WARN Failed to register uploaded object key=nar/0mgyagkily7p4vmdhhyvdway09g092xiw3yh0h6zrasy577i4rf5.nar.zst error="server returned 404: 404 page not found\n"8502026/11/01 16:14:17 WARN Failed to register uploaded object key=fkszjlirk9bqpvvr7040bqx0bxzf3bd1.ls error="server returned 404: 404 page not found\n"8512026/11/01 16:14:17 WARN Failed to register uploaded object key=w4wa032gxgcz7rf96791gp3s6grf60nx.ls error="server returned 404: 404 page not found\n"8522026/11/01 16:14:17 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"8532026/11/01 16:14:17 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign8542026/11/01 16:14:17 INFO Signed narinfos id=1 count=28552026/11/01 16:14:17 INFO Uploading 2 narinfos8562026/11/01 16:14:17 WARN Failed to register uploaded object key=fkszjlirk9bqpvvr7040bqx0bxzf3bd1.narinfo error="server returned 404: 404 page not found\n"8572026/11/01 16:14:17 INFO Received complete push request method=POST path=/api/pushes/1/complete8582026/11/01 16:14:17 WARN Failed to register uploaded object key=w4wa032gxgcz7rf96791gp3s6grf60nx.narinfo error="server returned 404: 404 page not found\n"8592026/11/01 16:14:17 INFO Completed push id=1 objects=6 duration=22.214583ms8602026/11/01 16:14:17 INFO Upload complete. (347ms)861=== NAME TestClientSharedPathCommittedMidPush862 client_integration_test.go:727: Retrieved narinfo from S3:863 StorePath: /private/var/tb/3/scratch/4a1a633e2471393e/build/TestClientSharedPathCommittedMidPush297999502/001/store/fkszjlirk9bqpvvr7040bqx0bxzf3bd1-shared-dep864 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst865 Compression: zstd866 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82867 NarSize: 136868 References: 869 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n870 client_integration_test.go:727: Retrieved narinfo from S3:871 StorePath: /private/var/tb/3/scratch/4a1a633e2471393e/build/TestClientSharedPathCommittedMidPush297999502/001/store/w4wa032gxgcz7rf96791gp3s6grf60nx-top872 URL: nar/0mgyagkily7p4vmdhhyvdway09g092xiw3yh0h6zrasy577i4rf5.nar.zst873 Compression: zstd874 NarHash: sha256:0mgyagkily7p4vmdhhyvdway09g092xiw3yh0h6zrasy577i4rf5875 NarSize: 264876 References: /private/var/tb/3/scratch/4a1a633e2471393e/build/TestClientSharedPathCommittedMidPush297999502/001/store/fkszjlirk9bqpvvr7040bqx0bxzf3bd1-shared-dep877 CA: text:sha256:0rq24v07y24j29v1n324qi87mnxb8pbp8j1z5wz2mnjph7r2vb9h878--- PASS: TestClientSharedPathCommittedMidPush (2.05s)879=== CONT TestLeadElectsOneAndHandsOver8802026/11/01 16:14:18 INFO Aborted multipart uploads count=0 kept=08812026/11/01 16:14:18 WARN Force mode enabled - objects will be deleted immediately without grace period8822026/11/01 16:14:18 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=08832026/11/01 16:14:18 INFO Vacuumed table table=pending_closures8842026/11/01 16:14:18 INFO Vacuumed table table=pending_objects8852026/11/01 16:14:18 INFO Vacuumed table table=multipart_uploads8862026/11/01 16:14:18 INFO Vacuumed table table=closures8872026/11/01 16:14:18 INFO Vacuumed table table=objects888--- PASS: TestCommitRacingPendingCleanupKeepsObjects (2.30s)889=== CONT TestConnectWaitsForAPeerMigration8902026/11/01 16:14:18 INFO Received uploads request method=POST path=/api/pending_closures8912026/11/01 16:14:18 INFO Received uploads request method=POST path=/api/pending_closures8922026/11/01 16:14:18 INFO Aborted multipart uploads count=0 kept=08932026/11/01 16:14:18 WARN Force mode enabled - objects will be deleted immediately without grace period8942026/11/01 16:14:18 ERROR failed to remove object object=nar/dddddddddddddddddddddddddddddddddddddddddddddddddddd.nar.zst error="Access Denied."8952026/11/01 16:14:18 ERROR failed to remove object object=dddddddddddddddddddddddddddddddd.narinfo error="Access Denied."896--- PASS: TestFailedS3DeleteKeepsTombstone (2.71s)897=== CONT TestResolveDBConnectionString898=== RUN TestResolveDBConnectionString/flag_wins899=== PAUSE TestResolveDBConnectionString/flag_wins900--- PASS: TestReadRedirectNar (2.73s)901=== CONT TestConcurrentCommitsSharingObjectsDoNotDeadlock902=== RUN TestResolveDBConnectionString/file_when_flag_empty903=== PAUSE TestResolveDBConnectionString/file_when_flag_empty904=== RUN TestResolveDBConnectionString/missing_file_is_an_error905=== PAUSE TestResolveDBConnectionString/missing_file_is_an_error906=== RUN TestResolveDBConnectionString/PGHOST_allows_empty907=== PAUSE TestResolveDBConnectionString/PGHOST_allows_empty908=== RUN TestResolveDBConnectionString/nothing_configured909=== PAUSE TestResolveDBConnectionString/nothing_configured910=== CONT TestDeleteClosuresRacingPins911--- PASS: TestPushWaitsForSweepHoldingRow (2.88s)912=== CONT TestClientFallsBackToClosures9132026/11/01 16:14:18 INFO Aborted multipart uploads count=0 kept=09142026/11/01 16:14:18 WARN Force mode enabled - objects will be deleted immediately without grace period9152026/11/01 16:14:18 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=09162026/11/01 16:14:18 INFO Vacuumed table table=pending_closures9172026/11/01 16:14:18 INFO Vacuumed table table=pending_objects9182026/11/01 16:14:18 INFO Vacuumed table table=multipart_uploads9192026/11/01 16:14:18 INFO Vacuumed table table=closures9202026/11/01 16:14:18 INFO Vacuumed table table=objects921--- PASS: TestSweepRechecksPendingAfterLocking (3.06s)922=== CONT TestClientPushesUseOnePush923--- PASS: TestReadRedirectKeepsNarinfoProxied (3.18s)924=== CONT TestMultipartUploadAbortedWhenCancelledBeforeRecorded9252026/11/01 16:14:19 INFO Aborted multipart uploads count=0 kept=0926--- PASS: TestGCBugBareHashReferences (3.55s)9272026/11/01 16:14:19 WARN Force mode enabled - objects will be deleted immediately without grace period928=== CONT TestReadProxyOutlastsServerWriteTimeout9292026/11/01 16:14:19 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=09302026/11/01 16:14:19 INFO Vacuumed table table=pending_closures9312026/11/01 16:14:19 INFO Vacuumed table table=pending_objects9322026/11/01 16:14:19 INFO Vacuumed table table=multipart_uploads9332026/11/01 16:14:19 INFO Vacuumed table table=closures9342026/11/01 16:14:19 INFO Vacuumed table table=objects9352026/11/01 16:14:19 INFO Aborted multipart uploads count=0 kept=09362026/11/01 16:14:19 WARN Force mode enabled - objects will be deleted immediately without grace period937--- PASS: TestReadProxyRootRedirectsToIndexHTML (3.70s)938=== CONT TestReadProxyHead9392026/11/01 16:14:19 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=09402026/11/01 16:14:19 INFO Vacuumed table table=pending_closures9412026/11/01 16:14:19 INFO Vacuumed table table=pending_objects9422026/11/01 16:14:19 INFO Vacuumed table table=multipart_uploads9432026/11/01 16:14:19 INFO Vacuumed table table=closures9442026/11/01 16:14:19 INFO Vacuumed table table=objects945--- PASS: TestSweepSkipsRowsLockedByPush (3.80s)946=== CONT TestReadProxyInvalidPath947--- PASS: TestGetExistingObjectsLocksRows (4.13s)948=== CONT TestReadProxy404949=== NAME TestPinProtectsFromGC950 client_integration_test.go:778: Pinned store path: /private/var/tb/3/scratch/4a1a633e2471393e/build/TestPinProtectsFromGC2843779474/001/store/icg1y4ga6afk97zs2a8dkkn6jdfkiv7q-pinned-file.txt951 client_integration_test.go:779: Unpinned store path: /private/var/tb/3/scratch/4a1a633e2471393e/build/TestPinProtectsFromGC2843779474/001/store/584cm29l59503k7bp6db9yc0q4jg947h-unpinned-file.txt952--- PASS: TestReadProxyDisabled (4.26s)953=== CONT TestReadProxyNarStreaming9542026/11/01 16:14:20 INFO Received push request method=POST path=/api/pushes9552026/11/01 16:14:20 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)9562026/11/01 16:14:20 INFO Uploading icg1y4ga6afk97zs2a8dkkn6jdfkiv7q-pinned-file.txt (128B)9572026/11/01 16:14:20 WARN Failed to register uploaded object key=icg1y4ga6afk97zs2a8dkkn6jdfkiv7q.ls error="server returned 404: 404 page not found\n"9582026/11/01 16:14:20 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign9592026/11/01 16:14:20 WARN Failed to register uploaded object key=nar/0qmhsg42pqsz7x6hh02j8gznnac3yi3qpjhrqbwvz88i194jbb5s.nar.zst error="server returned 404: 404 page not found\n"9602026/11/01 16:14:20 INFO Signed narinfos id=1 count=19612026/11/01 16:14:20 INFO Uploading 1 narinfos9622026/11/01 16:14:20 INFO Received complete push request method=POST path=/api/pushes/1/complete9632026/11/01 16:14:20 WARN Failed to register uploaded object key=icg1y4ga6afk97zs2a8dkkn6jdfkiv7q.narinfo error="server returned 404: 404 page not found\n"9642026/11/01 16:14:20 INFO Completed push id=1 objects=3 duration=21.852083ms9652026/11/01 16:14:20 INFO Upload complete. (179ms)9662026/11/01 16:14:20 INFO Received push request method=POST path=/api/pushes9672026/11/01 16:14:20 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)9682026/11/01 16:14:20 INFO Uploading 584cm29l59503k7bp6db9yc0q4jg947h-unpinned-file.txt (128B)9692026/11/01 16:14:20 WARN Failed to register uploaded object key=584cm29l59503k7bp6db9yc0q4jg947h.ls error="server returned 404: 404 page not found\n"9702026/11/01 16:14:20 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign9712026/11/01 16:14:20 WARN Failed to register uploaded object key=nar/0gh0wdnr6gmk4r5sfzzh12isnl14rgmkrwy1ws41hpsrlndclg5h.nar.zst error="server returned 404: 404 page not found\n"9722026/11/01 16:14:20 INFO Signed narinfos id=2 count=19732026/11/01 16:14:20 INFO Uploading 1 narinfos9742026/11/01 16:14:20 INFO Aborted multipart uploads count=0 kept=09752026/11/01 16:14:20 WARN Force mode enabled - objects will be deleted immediately without grace period9762026/11/01 16:14:20 INFO Received complete push request method=POST path=/api/pushes/2/complete9772026/11/01 16:14:20 WARN Failed to register uploaded object key=584cm29l59503k7bp6db9yc0q4jg947h.narinfo error="server returned 404: 404 page not found\n"9782026/11/01 16:14:20 INFO Completed push id=2 objects=3 duration=1.062541ms9792026/11/01 16:14:20 INFO Upload complete. (155ms)9802026/11/01 16:14:20 INFO Aborted multipart uploads count=0 kept=09812026/11/01 16:14:20 INFO Starting cleanup of old closures method=DELETE path=/api/closures9822026/11/01 16:14:20 INFO Garbage collection started9832026/11/01 16:14:20 INFO Aborted multipart uploads count=0 kept=09842026/11/01 16:14:20 WARN Force mode enabled - objects will be deleted immediately without grace period9852026/11/01 16:14:20 WARN Force mode enabled - objects will be deleted immediately without grace period9862026/11/01 16:14:20 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=09872026/11/01 16:14:20 INFO Vacuumed table table=pending_closures9882026/11/01 16:14:20 INFO Vacuumed table table=pending_objects9892026/11/01 16:14:20 INFO Vacuumed table table=multipart_uploads9902026/11/01 16:14:20 INFO Vacuumed table table=closures9912026/11/01 16:14:20 INFO Vacuumed table table=objects992--- PASS: TestGCMetrics (4.91s)993=== CONT TestReadProxyContentNegotiation9942026/11/01 16:14:20 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=09952026/11/01 16:14:20 INFO Vacuumed table table=pending_closures9962026/11/01 16:14:20 INFO Vacuumed table table=pending_objects9972026/11/01 16:14:20 INFO Vacuumed table table=multipart_uploads9982026/11/01 16:14:20 INFO Vacuumed table table=closures9992026/11/01 16:14:20 INFO Vacuumed table table=objects1000--- PASS: TestGCSweepDeliversEachKeyOnce (5.02s)1001=== CONT TestReadProxyNarinfoAlreadyDecompressed1002--- PASS: TestRegisterCompletedObjectNeedsPendingRow (5.15s)1003=== CONT TestReadProxyNarinfo10042026/11/01 16:14:21 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=010052026/11/01 16:14:21 INFO Vacuumed table table=pending_closures10062026/11/01 16:14:21 INFO Vacuumed table table=pending_objects10072026/11/01 16:14:21 INFO Vacuumed table table=multipart_uploads10082026/11/01 16:14:21 INFO Vacuumed table table=closures10092026/11/01 16:14:21 INFO Vacuumed table table=objects10102026/11/01 16:14:21 INFO Received uploads request method=POST path=/api/pending_closures10112026/11/01 16:14:21 INFO Received uploads request method=POST path=/api/pending_closures1012--- PASS: TestCreatePendingClosureVerifyS3FailureReleasesConnection (5.62s)1013=== CONT TestIsValidCachePath1014=== RUN TestIsValidCachePath/narinfo1015=== PAUSE TestIsValidCachePath/narinfo1016=== RUN TestIsValidCachePath/narinfo_all_nix_base32_chars1017=== PAUSE TestIsValidCachePath/narinfo_all_nix_base32_chars1018=== RUN TestIsValidCachePath/nar_zst1019=== PAUSE TestIsValidCachePath/nar_zst1020=== RUN TestIsValidCachePath/nar_xz1021=== PAUSE TestIsValidCachePath/nar_xz1022=== RUN TestIsValidCachePath/nar_bz21023=== PAUSE TestIsValidCachePath/nar_bz21024=== RUN TestIsValidCachePath/nar_uncompressed1025=== PAUSE TestIsValidCachePath/nar_uncompressed1026=== RUN TestIsValidCachePath/ls1027=== PAUSE TestIsValidCachePath/ls1028=== RUN TestIsValidCachePath/log1029=== PAUSE TestIsValidCachePath/log1030=== RUN TestIsValidCachePath/realisation1031=== PAUSE TestIsValidCachePath/realisation1032=== RUN TestIsValidCachePath/nix-cache-info1033=== PAUSE TestIsValidCachePath/nix-cache-info1034=== RUN TestIsValidCachePath/index.html1035=== PAUSE TestIsValidCachePath/index.html1036=== RUN TestIsValidCachePath/traversal_parent1037=== PAUSE TestIsValidCachePath/traversal_parent1038=== RUN TestIsValidCachePath/traversal_in_middle1039=== PAUSE TestIsValidCachePath/traversal_in_middle1040=== RUN TestIsValidCachePath/invalid_char_e1041=== PAUSE TestIsValidCachePath/invalid_char_e1042=== RUN TestIsValidCachePath/invalid_char_u1043=== PAUSE TestIsValidCachePath/invalid_char_u1044=== RUN TestIsValidCachePath/random_path1045=== PAUSE TestIsValidCachePath/random_path1046=== RUN TestIsValidCachePath/empty1047=== PAUSE TestIsValidCachePath/empty1048=== RUN TestIsValidCachePath/leading_slash1049=== PAUSE TestIsValidCachePath/leading_slash1050=== RUN TestIsValidCachePath/wrong_extension1051=== PAUSE TestIsValidCachePath/wrong_extension1052=== RUN TestIsValidCachePath/short_hash1053=== PAUSE TestIsValidCachePath/short_hash1054=== CONT TestParseSingleRange1055=== RUN TestParseSingleRange/none1056=== PAUSE TestParseSingleRange/none1057=== RUN TestParseSingleRange/unknown_unit1058=== PAUSE TestParseSingleRange/unknown_unit1059=== RUN TestParseSingleRange/multi-range_ignored1060=== PAUSE TestParseSingleRange/multi-range_ignored1061=== RUN TestParseSingleRange/malformed_no_dash1062=== PAUSE TestParseSingleRange/malformed_no_dash1063=== RUN TestParseSingleRange/malformed_both_empty1064=== PAUSE TestParseSingleRange/malformed_both_empty1065=== RUN TestParseSingleRange/malformed_end_before_start1066=== PAUSE TestParseSingleRange/malformed_end_before_start1067=== RUN TestParseSingleRange/closed1068=== PAUSE TestParseSingleRange/closed1069=== RUN TestParseSingleRange/open-ended1070=== PAUSE TestParseSingleRange/open-ended1071=== RUN TestParseSingleRange/end_clamped_to_size1072=== PAUSE TestParseSingleRange/end_clamped_to_size1073=== RUN TestParseSingleRange/suffix1074=== PAUSE TestParseSingleRange/suffix1075=== RUN TestParseSingleRange/suffix_exceeds_size1076=== PAUSE TestParseSingleRange/suffix_exceeds_size1077=== RUN TestParseSingleRange/single_byte1078=== PAUSE TestParseSingleRange/single_byte1079=== RUN TestParseSingleRange/start_past_EOF1080=== PAUSE TestParseSingleRange/start_past_EOF1081=== RUN TestParseSingleRange/start_far_past_EOF1082=== PAUSE TestParseSingleRange/start_far_past_EOF1083=== CONT TestPresentNotReportedWhileGCDeletesClosure1084=== RUN TestPresentNotReportedWhileGCDeletesClosure/stale1085=== PAUSE TestPresentNotReportedWhileGCDeletesClosure/stale1086=== RUN TestPresentNotReportedWhileGCDeletesClosure/fresh1087=== PAUSE TestPresentNotReportedWhileGCDeletesClosure/fresh1088=== CONT TestPresentRefreshesOnlyStaleClosures10892026/11/01 16:14:21 INFO Aborted multipart uploads count=0 kept=010902026/11/01 16:14:21 WARN Force mode enabled - objects will be deleted immediately without grace period10912026/11/01 16:14:21 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=010922026/11/01 16:14:21 INFO Vacuumed table table=pending_closures10932026/11/01 16:14:21 INFO Vacuumed table table=pending_objects10942026/11/01 16:14:21 INFO Vacuumed table table=multipart_uploads10952026/11/01 16:14:21 INFO Vacuumed table table=closures10962026/11/01 16:14:21 INFO Vacuumed table table=objects1097--- PASS: TestGCSweepSkipsPendingObjects (5.71s)1098=== CONT TestPresentReportsOnlyClosureRoots10992026/11/01 16:14:21 INFO Received uploads request method=POST path=/api/pending_closures1100--- PASS: TestTombstonedObjectOfferedWithoutWaiting (5.75s)1101=== CONT TestCreatePin_ReservedPins11022026/11/01 16:14:21 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:59041/oidc11032026/11/01 16:14:21 INFO Received uploads request method=POST path=/api/pending_closures1104--- PASS: TestDeduplicatedObjectsRecordedAsPending (5.93s)1105=== CONT TestOrphanedObjectsGCStressTest11062026/11/01 16:14:21 INFO Received uploads request method=POST path=/api/pending_closures11072026/11/01 16:14:22 INFO lead: acquired remote=192.0.2.1:123411082026/11/01 16:14:22 INFO lead: released remote=192.0.2.1:12341109--- PASS: TestLeadIncumbentAnnouncesAtOnce (4.55s)1110=== CONT TestOrphanedObjectsGC11112026/11/01 16:14:22 INFO Aborted multipart uploads count=0 kept=011122026/11/01 16:14:22 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=011132026/11/01 16:14:22 INFO Vacuumed table table=pending_closures11142026/11/01 16:14:22 INFO Vacuumed table table=pending_objects11152026/11/01 16:14:22 INFO Vacuumed table table=multipart_uploads11162026/11/01 16:14:22 INFO Vacuumed table table=closures11172026/11/01 16:14:22 INFO Vacuumed table table=objects11182026/11/01 16:14:22 INFO Aborted multipart uploads count=0 kept=011192026/11/01 16:14:22 WARN Force mode enabled - objects will be deleted immediately without grace period11202026/11/01 16:14:22 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=011212026/11/01 16:14:22 INFO Vacuumed table table=pending_closures11222026/11/01 16:14:22 INFO Vacuumed table table=pending_objects11232026/11/01 16:14:22 INFO Vacuumed table table=multipart_uploads11242026/11/01 16:14:22 INFO Vacuumed table table=closures11252026/11/01 16:14:22 INFO Vacuumed table table=objects1126--- PASS: TestPushDedupSurvivesConcurrentGC (6.43s)1127=== CONT TestObjectStatsUpdatedOncePerCommit11282026/11/01 16:14:22 ERROR failed to check GC advisory lock error="query pg_locks: failed to connect to `user=_tribuchetbld3 database=niks3`: /nonexistent/.s.PGSQL.5432 (/nonexistent): dial error: dial unix /nonexistent/.s.PGSQL.5432: connect: no such file or directory"1129--- PASS: TestGCAdvisoryLockBlocksConcurrentRun (5.64s)1130=== CONT TestObjectStatsTrigger11312026/11/01 16:14:22 INFO lead: acquired remote=192.0.2.1:123411322026/11/01 16:14:22 INFO lead: acquired remote=192.0.2.1:123411332026/11/01 16:14:22 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=011342026/11/01 16:14:22 INFO Received create pin request method=POST path=/api/pins/myapp11352026/11/01 16:14:22 INFO Created/updated pin name=myapp store_path=/private/var/tb/3/scratch/4a1a633e2471393e/build/TestPinProtectsFromGC2843779474/001/store/icg1y4ga6afk97zs2a8dkkn6jdfkiv7q-pinned-file.txt narinfo_key=icg1y4ga6afk97zs2a8dkkn6jdfkiv7q.narinfo11362026/11/01 16:14:22 INFO Starting cleanup of old closures method=DELETE path=/api/closures11372026/11/01 16:14:22 INFO Garbage collection started11382026/11/01 16:14:22 INFO Aborted multipart uploads count=0 kept=011392026/11/01 16:14:22 WARN Force mode enabled - objects will be deleted immediately without grace period11402026/11/01 16:14:22 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=011412026/11/01 16:14:22 INFO Vacuumed table table=pending_closures11422026/11/01 16:14:22 INFO Vacuumed table table=pending_objects11432026/11/01 16:14:22 INFO Vacuumed table table=multipart_uploads11442026/11/01 16:14:22 INFO Vacuumed table table=closures11452026/11/01 16:14:22 INFO Vacuumed table table=objects11462026/11/01 16:14:23 INFO lead: released remote=192.0.2.1:12341147--- PASS: TestLeadEndsOnShutdown (6.35s)1148=== CONT TestPendingCleanupUsesOneCutoff1149--- PASS: TestConcurrentCommitsSharingObjectsDoNotDeadlock (5.10s)1150=== CONT TestService_readinessHandler11512026/11/01 16:14:23 INFO Received uploads request method=POST path=/api/pending_closures11522026/11/01 16:14:23 INFO Received uploads request method=POST path=/api/pending_closures11532026/11/01 16:14:23 INFO Received uploads request method=POST path=/api/pending_closures11542026/11/01 16:14:23 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)11552026/11/01 16:14:23 INFO Uploading l1qvxpxg135d54az9vpvxrg19g5qin36-shared-dep (136B)11562026/11/01 16:14:23 INFO Uploading nsl8lj0q8pf9ylnxjzp7mmwfq6ap8m16-a (256B)1157--- PASS: TestMultipartUploadAbortedWhenCancelledBeforeRecorded (4.76s)1158=== CONT TestMultipartCleanup11592026/11/01 16:14:23 INFO lead: released remote=192.0.2.1:123411602026/11/01 16:14:23 WARN Failed to register uploaded object key=l1qvxpxg135d54az9vpvxrg19g5qin36.ls error="server returned 404: 404 page not found\n"11612026/11/01 16:14:23 WARN Failed to register uploaded object key=nsl8lj0q8pf9ylnxjzp7mmwfq6ap8m16.ls error="server returned 404: 404 page not found\n"11622026/11/01 16:14:23 WARN Failed to register uploaded object key=nar/0vqrj2d3mfmm90xj350b37ks33y9h1h5v0zv4iijs9scig75fmnq.nar.zst error="server returned 404: 404 page not found\n"11632026/11/01 16:14:23 WARN Failed to register uploaded object key=0g53sjqbwqm8lck3wxryxd0cqrnp0d6r.ls error="server returned 404: 404 page not found\n"11642026/11/01 16:14:23 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign11652026/11/01 16:14:23 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"11662026/11/01 16:14:23 INFO Signed narinfos id=1 count=211672026/11/01 16:14:23 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign11682026/11/01 16:14:23 INFO Signed narinfos id=2 count=211692026/11/01 16:14:23 INFO Uploading 4 narinfos11702026/11/01 16:14:23 INFO lead: acquired remote=192.0.2.1:123411712026/11/01 16:14:23 WARN Failed to register uploaded object key=nsl8lj0q8pf9ylnxjzp7mmwfq6ap8m16.narinfo error="server returned 404: 404 page not found\n"11722026/11/01 16:14:23 INFO Received push request method=POST path=/api/pushes11732026/11/01 16:14:23 WARN Failed to register uploaded object key=0g53sjqbwqm8lck3wxryxd0cqrnp0d6r.narinfo error="server returned 404: 404 page not found\n"11742026/11/01 16:14:23 WARN Failed to register uploaded object key=l1qvxpxg135d54az9vpvxrg19g5qin36.narinfo error="server returned 404: 404 page not found\n"11752026/11/01 16:14:23 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)11762026/11/01 16:14:23 INFO Uploading m3w9vq43yg6zgi0hxmy56mwbbvzxli73-shared-dep (136B)11772026/11/01 16:14:23 INFO Uploading a6dnkpqmdsnsskpjkvpk65p887zr6bcn-a (256B)11782026/11/01 16:14:23 WARN Failed to register uploaded object key=3ziwv180nfspfx702am150j38hg8jlf8.ls error="server returned 404: 404 page not found\n"11792026/11/01 16:14:23 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete11802026/11/01 16:14:23 WARN Failed to register uploaded object key=l1qvxpxg135d54az9vpvxrg19g5qin36.narinfo error="server returned 404: 404 page not found\n"11812026/11/01 16:14:23 WARN Failed to register uploaded object key=m3w9vq43yg6zgi0hxmy56mwbbvzxli73.ls error="server returned 404: 404 page not found\n"11822026/11/01 16:14:23 WARN Failed to register uploaded object key=a6dnkpqmdsnsskpjkvpk65p887zr6bcn.ls error="server returned 404: 404 page not found\n"11832026/11/01 16:14:23 INFO Completed upload id=1 objects=6 duration=14.177ms11842026/11/01 16:14:23 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete11852026/11/01 16:14:23 INFO Completed upload id=2 objects=6 duration=362.584µs11862026/11/01 16:14:23 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"11872026/11/01 16:14:23 INFO Upload complete. (382ms)1188=== NAME TestClientFallsBackToClosures1189 client_pushes_test.go:112: Retrieved narinfo from S3:1190 StorePath: /private/var/tb/3/scratch/4a1a633e2471393e/build/TestClientFallsBackToClosures1496177167/001/store/l1qvxpxg135d54az9vpvxrg19g5qin36-shared-dep1191 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1192 Compression: zstd1193 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821194 NarSize: 1361195 References: 1196 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n11972026/11/01 16:14:23 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign11982026/11/01 16:14:23 WARN Failed to register uploaded object key=nar/1c61maxb6y516xdh9isdncmjm170dh28vbyakk63hgdpqhl8nskk.nar.zst error="server returned 404: 404 page not found\n"11992026/11/01 16:14:23 INFO Signed narinfos id=1 count=31200 client_pushes_test.go:112: Retrieved narinfo from S3:1201 StorePath: /private/var/tb/3/scratch/4a1a633e2471393e/build/TestClientFallsBackToClosures1496177167/001/store/nsl8lj0q8pf9ylnxjzp7mmwfq6ap8m16-a1202 URL: nar/0vqrj2d3mfmm90xj350b37ks33y9h1h5v0zv4iijs9scig75fmnq.nar.zst1203 Compression: zstd1204 NarHash: sha256:0vqrj2d3mfmm90xj350b37ks33y9h1h5v0zv4iijs9scig75fmnq1205 NarSize: 2561206 References: /private/var/tb/3/scratch/4a1a633e2471393e/build/TestClientFallsBackToClosures1496177167/001/store/l1qvxpxg135d54az9vpvxrg19g5qin36-shared-dep1207 CA: text:sha256:1g3mr5cbbks9dhym2kjcv0kk8sb34zndlx5qydhpy9wpk4lkfzxs12082026/11/01 16:14:23 INFO Uploading 3 narinfos1209 client_pushes_test.go:112: Retrieved narinfo from S3:1210 StorePath: /private/var/tb/3/scratch/4a1a633e2471393e/build/TestClientFallsBackToClosures1496177167/001/store/0g53sjqbwqm8lck3wxryxd0cqrnp0d6r-b1211 URL: nar/0vqrj2d3mfmm90xj350b37ks33y9h1h5v0zv4iijs9scig75fmnq.nar.zst1212 Compression: zstd1213 NarHash: sha256:0vqrj2d3mfmm90xj350b37ks33y9h1h5v0zv4iijs9scig75fmnq1214 NarSize: 2561215 References: /private/var/tb/3/scratch/4a1a633e2471393e/build/TestClientFallsBackToClosures1496177167/001/store/l1qvxpxg135d54az9vpvxrg19g5qin36-shared-dep1216 CA: text:sha256:1g3mr5cbbks9dhym2kjcv0kk8sb34zndlx5qydhpy9wpk4lkfzxs12172026/11/01 16:14:24 WARN Failed to register uploaded object key=a6dnkpqmdsnsskpjkvpk65p887zr6bcn.narinfo error="server returned 404: 404 page not found\n"12182026/11/01 16:14:24 WARN Failed to register uploaded object key=3ziwv180nfspfx702am150j38hg8jlf8.narinfo error="server returned 404: 404 page not found\n"12192026/11/01 16:14:24 INFO Received complete push request method=POST path=/api/pushes/1/complete12202026/11/01 16:14:24 WARN Failed to register uploaded object key=m3w9vq43yg6zgi0hxmy56mwbbvzxli73.narinfo error="server returned 404: 404 page not found\n"1221--- PASS: TestReadProxyHead (4.52s)1222=== CONT TestServerTLSConfig1223=== RUN TestServerTLSConfig/no_client_CA1224=== PAUSE TestServerTLSConfig/no_client_CA1225=== RUN TestServerTLSConfig/missing_CA_file1226=== PAUSE TestServerTLSConfig/missing_CA_file1227=== RUN TestServerTLSConfig/not_a_PEM_file1228=== PAUSE TestServerTLSConfig/not_a_PEM_file1229=== CONT TestService_NativeMTLS12302026/11/01 16:14:24 INFO Completed push id=1 objects=8 duration=14.8815ms12312026/11/01 16:14:24 INFO Upload complete. (255ms)1232=== NAME TestClientPushesUseOnePush1233 client_pushes_test.go:97: Retrieved narinfo from S3:1234 StorePath: /private/var/tb/3/scratch/4a1a633e2471393e/build/TestClientPushesUseOnePush306052777/001/store/m3w9vq43yg6zgi0hxmy56mwbbvzxli73-shared-dep1235 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1236 Compression: zstd1237 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821238 NarSize: 1361239 References: 1240 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1241 client_pushes_test.go:97: Retrieved narinfo from S3:1242 StorePath: /private/var/tb/3/scratch/4a1a633e2471393e/build/TestClientPushesUseOnePush306052777/001/store/a6dnkpqmdsnsskpjkvpk65p887zr6bcn-a1243 URL: nar/1c61maxb6y516xdh9isdncmjm170dh28vbyakk63hgdpqhl8nskk.nar.zst1244 Compression: zstd1245 NarHash: sha256:1c61maxb6y516xdh9isdncmjm170dh28vbyakk63hgdpqhl8nskk1246 NarSize: 2561247 References: /private/var/tb/3/scratch/4a1a633e2471393e/build/TestClientPushesUseOnePush306052777/001/store/m3w9vq43yg6zgi0hxmy56mwbbvzxli73-shared-dep1248 CA: text:sha256:0fdw6flvkqlbnpbv2djix9al5vf5n8ngllfdflrfbviqnrbj54531249--- PASS: TestClientFallsBackToClosures (5.40s)1250=== CONT TestMetricsCommit1251=== NAME TestClientPushesUseOnePush1252 client_pushes_test.go:97: Retrieved narinfo from S3:1253 StorePath: /private/var/tb/3/scratch/4a1a633e2471393e/build/TestClientPushesUseOnePush306052777/001/store/3ziwv180nfspfx702am150j38hg8jlf8-b1254 URL: nar/1c61maxb6y516xdh9isdncmjm170dh28vbyakk63hgdpqhl8nskk.nar.zst1255 Compression: zstd1256 NarHash: sha256:1c61maxb6y516xdh9isdncmjm170dh28vbyakk63hgdpqhl8nskk1257 NarSize: 2561258 References: /private/var/tb/3/scratch/4a1a633e2471393e/build/TestClientPushesUseOnePush306052777/001/store/m3w9vq43yg6zgi0hxmy56mwbbvzxli73-shared-dep1259 CA: text:sha256:0fdw6flvkqlbnpbv2djix9al5vf5n8ngllfdflrfbviqnrbj54531260--- PASS: TestClientPushesUseOnePush (5.29s)1261=== CONT TestMetricsInventory1262--- PASS: TestConnectWaitsForAPeerMigration (6.22s)1263=== CONT TestNARDeduplicationMetadataUploadBug1264--- PASS: TestReadProxyInvalidPath (4.80s)1265=== CONT TestCreatePendingClosureRejectsOversizedNAR12662026/11/01 16:14:24 INFO Received uploads request method=POST path=/api/pending_closures1267--- PASS: TestCreatePendingClosureRejectsOversizedNAR (0.00s)1268=== CONT TestCacheConfigHandlerMaxNarSize1269--- PASS: TestCacheConfigHandlerMaxNarSize (0.00s)1270=== CONT TestGenerateLandingPage1271--- PASS: TestGenerateLandingPage (0.00s)1272=== CONT TestGCTaskStore_CompletedAllowsNewTask1273--- PASS: TestGCTaskStore_CompletedAllowsNewTask (0.00s)1274=== CONT TestService_healthCheckHandler1275=== NAME TestPinProtectsFromGC1276 client_integration_test.go:887: Pin successfully protected closure from garbage collection1277--- PASS: TestPinProtectsFromGC (8.97s)1278=== CONT TestGracefulShutdownDrainsInflight12792026/11/01 16:14:24 INFO Starting HTTP server address=127.0.0.1:5911212802026/11/01 16:14:24 INFO Shutdown signal received, draining in-flight requests timeout=10s1281--- PASS: TestGracefulShutdownDrainsInflight (0.07s)1282=== CONT TestGCTaskStore_Fail1283--- PASS: TestGCTaskStore_Fail (0.00s)1284=== CONT TestGCTaskStore_PhaseUpdates1285--- PASS: TestGCTaskStore_PhaseUpdates (0.00s)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 TestClientWithDependencies12962026/11/01 16:14:24 INFO lead: released remote=192.0.2.1:12341297--- PASS: TestLeadElectsOneAndHandsOver (7.03s)1298=== CONT TestClientMultipleUploads1299--- PASS: TestReadProxyNarStreaming (4.88s)1300=== CONT TestClientIntegration1301--- PASS: TestReadProxy404 (5.18s)1302=== CONT TestClientErrorHandling1303=== RUN TestClientErrorHandling/InvalidStorePath1304=== PAUSE TestClientErrorHandling/InvalidStorePath1305=== RUN TestClientErrorHandling/InvalidAuthToken1306=== PAUSE TestClientErrorHandling/InvalidAuthToken1307=== RUN TestClientErrorHandling/ServerNotAvailable1308=== PAUSE TestClientErrorHandling/ServerNotAvailable1309=== CONT TestClientCADerivations1310--- PASS: TestReadProxyContentNegotiation (4.69s)1311=== CONT TestCacheStatsHandler1312--- PASS: TestReadProxyNarinfoAlreadyDecompressed (4.75s)1313=== CONT TestParseSize1314--- PASS: TestParseSize (0.00s)1315=== CONT TestCreatePendingClosure_SmallNARUsesSimplePUT13162026/11/01 16:14:25 ERROR Failed to decode narinfo key=3hcdxyjf9yiq7qf3i4548drb6sjmwa1v.narinfo limit=16777216 error=<nil>1317--- PASS: TestReadProxyNarinfo (5.04s)1318=== CONT TestCompleteMultipartUnregistered1319--- PASS: TestPresentRefreshesOnlyStaleClosures (4.78s)1320=== CONT TestService_verifyS3ReuploadsNarinfoOfLostNAR1321=== RUN TestService_verifyS3ReuploadsNarinfoOfLostNAR/lost,_other_NAR1322=== PAUSE TestService_verifyS3ReuploadsNarinfoOfLostNAR/lost,_other_NAR1323=== RUN TestService_verifyS3ReuploadsNarinfoOfLostNAR/intact,_other_NAR1324=== PAUSE TestService_verifyS3ReuploadsNarinfoOfLostNAR/intact,_other_NAR1325=== RUN TestService_verifyS3ReuploadsNarinfoOfLostNAR/named_one_of_two_lost1326=== PAUSE TestService_verifyS3ReuploadsNarinfoOfLostNAR/named_one_of_two_lost1327=== RUN TestService_verifyS3ReuploadsNarinfoOfLostNAR/named_one_of_two_lost,_other_pushed1328=== PAUSE TestService_verifyS3ReuploadsNarinfoOfLostNAR/named_one_of_two_lost,_other_pushed1329=== RUN TestService_verifyS3ReuploadsNarinfoOfLostNAR/lost,_same_NAR_pushed1330=== PAUSE TestService_verifyS3ReuploadsNarinfoOfLostNAR/lost,_same_NAR_pushed1331=== CONT TestService_verifyS3Integrity1332--- PASS: TestDeleteClosuresRacingPins (7.86s)1333=== CONT TestService_createPendingClosureHandler1334--- PASS: TestPresentReportsOnlyClosureRoots (4.97s)1335=== CONT TestService_cleanupPendingClosuresHandler13362026/11/01 16:14:26 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux13372026/11/01 16:14:26 WARN Refused reserved pin name=worker-x86_64-linux13382026/11/01 16:14:26 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux13392026/11/01 16:14:26 INFO Received create pin request method=POST path=/api/pins/my-app13402026/11/01 16:14:26 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux1341--- PASS: TestCreatePin_ReservedPins (5.13s)1342=== CONT TestUploadHandlersRejectOversizedBody1343=== RUN TestUploadHandlersRejectOversizedBody/create_pending_closure1344=== PAUSE TestUploadHandlersRejectOversizedBody/create_pending_closure1345=== RUN TestUploadHandlersRejectOversizedBody/complete_multipart1346=== PAUSE TestUploadHandlersRejectOversizedBody/complete_multipart1347=== RUN TestUploadHandlersRejectOversizedBody/request_more_parts1348=== PAUSE TestUploadHandlersRejectOversizedBody/request_more_parts1349=== CONT TestUploadHandlersRejectInvalidKeys1350=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info1351=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info1352=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal1353=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal1354=== RUN TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key1355=== PAUSE TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key1356=== RUN TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key1357=== PAUSE TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key1358=== CONT TestIsValidUploadKey1359=== RUN TestIsValidUploadKey/narinfo1360=== PAUSE TestIsValidUploadKey/narinfo1361=== RUN TestIsValidUploadKey/nar_zst1362=== PAUSE TestIsValidUploadKey/nar_zst1363=== RUN TestIsValidUploadKey/nar_xz1364=== PAUSE TestIsValidUploadKey/nar_xz1365=== RUN TestIsValidUploadKey/nar_plain1366=== PAUSE TestIsValidUploadKey/nar_plain1367=== RUN TestIsValidUploadKey/listing1368=== PAUSE TestIsValidUploadKey/listing1369=== RUN TestIsValidUploadKey/build_log1370=== PAUSE TestIsValidUploadKey/build_log1371=== RUN TestIsValidUploadKey/build_log_home-manager_file1372=== PAUSE TestIsValidUploadKey/build_log_home-manager_file1373=== RUN TestIsValidUploadKey/build_log_plus_in_name1374=== PAUSE TestIsValidUploadKey/build_log_plus_in_name1375=== RUN TestIsValidUploadKey/build_log_question_mark1376=== PAUSE TestIsValidUploadKey/build_log_question_mark1377=== RUN TestIsValidUploadKey/build_log_equals1378=== PAUSE TestIsValidUploadKey/build_log_equals1379=== RUN TestIsValidUploadKey/realisation1380=== PAUSE TestIsValidUploadKey/realisation1381=== RUN TestIsValidUploadKey/realisation_plus_in_output1382=== PAUSE TestIsValidUploadKey/realisation_plus_in_output1383=== RUN TestIsValidUploadKey/nix-cache-info1384=== PAUSE TestIsValidUploadKey/nix-cache-info1385=== RUN TestIsValidUploadKey/index.html1386=== PAUSE TestIsValidUploadKey/index.html1387=== RUN TestIsValidUploadKey/narinfo_key,_nar_type1388=== PAUSE TestIsValidUploadKey/narinfo_key,_nar_type1389=== RUN TestIsValidUploadKey/nar_key,_narinfo_type1390=== PAUSE TestIsValidUploadKey/nar_key,_narinfo_type1391=== RUN TestIsValidUploadKey/listing_key,_narinfo_type1392=== PAUSE TestIsValidUploadKey/listing_key,_narinfo_type1393=== RUN TestIsValidUploadKey/traversal1394=== PAUSE TestIsValidUploadKey/traversal1395=== RUN TestIsValidUploadKey/traversal_nar1396=== PAUSE TestIsValidUploadKey/traversal_nar1397=== RUN TestIsValidUploadKey/absolute1398=== PAUSE TestIsValidUploadKey/absolute1399=== RUN TestIsValidUploadKey/empty_key1400=== PAUSE TestIsValidUploadKey/empty_key1401=== RUN TestIsValidUploadKey/unknown_type1402=== PAUSE TestIsValidUploadKey/unknown_type1403=== CONT TestPendingClosureWriteTimeout1404=== RUN TestPendingClosureWriteTimeout/empty1405=== PAUSE TestPendingClosureWriteTimeout/empty1406=== RUN TestPendingClosureWriteTimeout/400_objects1407=== PAUSE TestPendingClosureWriteTimeout/400_objects1408=== RUN TestPendingClosureWriteTimeout/670k_objects1409=== PAUSE TestPendingClosureWriteTimeout/670k_objects1410=== RUN TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline1411=== PAUSE TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline1412=== CONT TestProxyWriteTimeout1413=== RUN TestProxyWriteTimeout/narinfo1414=== PAUSE TestProxyWriteTimeout/narinfo1415=== RUN TestProxyWriteTimeout/1_GiB_nar1416=== PAUSE TestProxyWriteTimeout/1_GiB_nar1417=== RUN TestProxyWriteTimeout/10_GiB_nar1418=== PAUSE TestProxyWriteTimeout/10_GiB_nar1419=== RUN TestProxyWriteTimeout/unknown_size1420=== PAUSE TestProxyWriteTimeout/unknown_size1421=== CONT TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle1422--- PASS: TestObjectStatsUpdatedOncePerCommit (5.54s)1423=== CONT TestSkippedUploadsHandler14242026/11/01 16:14:27 INFO Client skipped oversized paths paths=3 nar_bytes=50000000001425--- PASS: TestSkippedUploadsHandler (0.01s)1426=== CONT TestService_AuthMiddleware_MTLSBoundSubjects1427--- PASS: TestObjectStatsTrigger (5.73s)1428=== CONT TestService_ReadAuthMiddleware14292026/11/01 16:14:28 INFO Received uploads request method=POST path=/api/pending_closures14302026/11/01 16:14:28 INFO Received uploads request method=POST path=/api/pending_closures14312026/11/01 16:14:28 INFO Received cleanup request method=DELETE path=/api/pending_closures1432--- PASS: TestReadProxyOutlastsServerWriteTimeout (9.14s)1433=== CONT TestService_ReadScope_PublicByDefault14342026/11/01 16:14:28 WARN readiness check failed error="closed pool"1435--- PASS: TestService_readinessHandler (4.97s)1436=== CONT TestService_AuthMiddleware_MTLSProxyHeader14372026/11/01 16:14:29 INFO Received uploads request method=POST path=/api/pending_closures14382026/11/01 16:14:29 INFO Received cleanup request method=DELETE path=/api/pending_closures14392026/11/01 16:14:29 WARN Failed to abort upload, keeping its closure key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst error="Get \"http://127.0.0.1:1/bucket54/?location=\": dial tcp 127.0.0.1:1: connect: connection refused" code=""14402026/11/01 16:14:29 INFO Aborted multipart uploads count=0 kept=114412026/11/01 16:14:29 INFO Received cleanup request method=DELETE path=/api/pending_closures14422026/11/01 16:14:29 INFO Aborted multipart uploads count=1 kept=01443=== NAME TestOrphanedObjectsGC1444 orphaned_objects_gc_test.go:287: GC Test Summary:1445 orphaned_objects_gc_test.go:288: - Kept: 2 objects from closure A1446 orphaned_objects_gc_test.go:289: - Deleted: 2 objects from closure B1447 orphaned_objects_gc_test.go:290: - Deleted: 6 orphaned chain objects (X1->X2->X3)1448 orphaned_objects_gc_test.go:291: - Deleted: 2 orphaned single objects (Y)1449 orphaned_objects_gc_test.go:292: - Total deleted: 10 objects1450=== CONT TestGCTaskStore_GetEmpty1451=== CONT TestGCTaskStore_GetReturnsLatest1452=== CONT TestPush_RejectsBadRequests1453--- PASS: TestMultipartCleanup (5.71s)1454--- PASS: TestOrphanedObjectsGC (7.43s)1455--- PASS: TestGCTaskStore_GetEmpty (0.00s)1456--- PASS: TestGCTaskStore_GetReturnsLatest (0.00s)1457=== CONT TestService_RequireScope_OIDC14582026/11/01 16:14:29 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:59158/oidc14592026/11/01 16:14:29 INFO Received push request method=POST path=/api/pushes14602026/11/01 16:14:29 INFO Received complete push request method=POST path=/api/pushes/1/complete14612026/11/01 16:14:29 INFO Completed push id=1 objects=4 duration=29.066459ms14622026/11/01 16:14:29 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete14632026/11/01 16:14:29 INFO Completed upload id=2 objects=2 duration=753.417µs1464--- PASS: TestMetricsCommit (5.65s)1465=== CONT TestService_Rustfstest14662026/11/01 16:14:29 WARN mTLS auth: subject not in bound subjects subject="CN=reader"14672026/11/01 16:14:29 WARN mTLS auth: subject not in bound subjects subject="CN=reader"1468--- PASS: TestService_NativeMTLS (5.80s)1469=== CONT TestPresignedUploadRegisteredBeforeCommit1470--- PASS: TestMetricsInventory (6.01s)1471=== CONT TestCompletedNarNotReofferedAcrossClosures1472--- PASS: TestService_healthCheckHandler (6.27s)1473=== CONT TestCompleteMultipartUpload_ErrorButObjectExists1474=== NAME TestNARDeduplicationMetadataUploadBug1475 metadata_upload_test.go:48: First store path: /private/var/tb/3/scratch/4a1a633e2471393e/build/TestNARDeduplicationMetadataUploadBug1709005244/001/store/g4wqklszj6bdf2j0m9k5z583nw9p4a3v-file1.txt14762026/11/01 16:14:30 INFO Received push request method=POST path=/api/pushes14772026/11/01 16:14:30 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)14782026/11/01 16:14:30 INFO Uploading g4wqklszj6bdf2j0m9k5z583nw9p4a3v-file1.txt (160B)14792026/11/01 16:14:30 WARN Failed to register uploaded object key=g4wqklszj6bdf2j0m9k5z583nw9p4a3v.ls error="server returned 404: 404 page not found\n"14802026/11/01 16:14:30 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign14812026/11/01 16:14:30 WARN Failed to register uploaded object key=nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst error="server returned 404: 404 page not found\n"14822026/11/01 16:14:30 INFO Signed narinfos id=1 count=114832026/11/01 16:14:30 INFO Uploading 1 narinfos14842026/11/01 16:14:30 INFO Received complete push request method=POST path=/api/pushes/1/complete14852026/11/01 16:14:30 WARN Failed to register uploaded object key=g4wqklszj6bdf2j0m9k5z583nw9p4a3v.narinfo error="server returned 404: 404 page not found\n"14862026/11/01 16:14:31 INFO Completed push id=1 objects=3 duration=23.972625ms14872026/11/01 16:14:31 INFO Upload complete. (248ms)1488 metadata_upload_test.go:54: Retrieved narinfo from S3:1489 StorePath: /private/var/tb/3/scratch/4a1a633e2471393e/build/TestNARDeduplicationMetadataUploadBug1709005244/001/store/g4wqklszj6bdf2j0m9k5z583nw9p4a3v-file1.txt1490 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1491 Compression: zstd1492 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1493 NarSize: 1601494 References: 1495 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1496 metadata_upload_test.go:55: Retrieved .ls file from S3 (compressed size: 77 bytes)1497 metadata_upload_test.go:55: Decompressed .ls content (64 bytes):1498 {"version":1,"root":{"type":"regular","size":44,"narOffset":96}}1499 metadata_upload_test.go:64: Second store path (same content): /private/var/tb/3/scratch/4a1a633e2471393e/build/TestNARDeduplicationMetadataUploadBug1709005244/001/store/388cdni324m1hgliw0gdsjjls1hqc8b2-file2.txt1500=== NAME TestClientIntegration1501 client_integration_test.go:291: Created store path: /private/var/tb/3/scratch/4a1a633e2471393e/build/TestClientIntegration1365175756/002/store/ybzsghrszvsmsfvxvvdfz855mqy7jzxw-test-file.txt15022026/11/01 16:14:31 INFO Received push request method=POST path=/api/pushes15032026/11/01 16:14:31 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)15042026/11/01 16:14:31 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign15052026/11/01 16:14:31 WARN Failed to register uploaded object key=388cdni324m1hgliw0gdsjjls1hqc8b2.ls error="server returned 404: 404 page not found\n"15062026/11/01 16:14:31 INFO Signed narinfos id=2 count=115072026/11/01 16:14:31 INFO Uploading 1 narinfos15082026/11/01 16:14:31 INFO Received push request method=POST path=/api/pushes15092026/11/01 16:14:31 INFO Received complete push request method=POST path=/api/pushes/2/complete15102026/11/01 16:14:31 WARN Failed to register uploaded object key=388cdni324m1hgliw0gdsjjls1hqc8b2.narinfo error="server returned 404: 404 page not found\n"15112026/11/01 16:14:31 INFO Completed push id=2 objects=3 duration=825.334µs15122026/11/01 16:14:31 INFO Upload complete. (156ms)1513=== NAME TestNARDeduplicationMetadataUploadBug1514 metadata_upload_test.go:76: Retrieved narinfo from S3:1515 StorePath: /private/var/tb/3/scratch/4a1a633e2471393e/build/TestNARDeduplicationMetadataUploadBug1709005244/001/store/388cdni324m1hgliw0gdsjjls1hqc8b2-file2.txt1516 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1517 Compression: zstd1518 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1519 NarSize: 1601520 References: 1521 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf15222026/11/01 16:14:31 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)15232026/11/01 16:14:31 INFO Uploading ybzsghrszvsmsfvxvvdfz855mqy7jzxw-test-file.txt (152B)1524 metadata_upload_test.go:77: Retrieved .ls file from S3 (compressed size: 62 bytes)1525 metadata_upload_test.go:77: Decompressed .ls content (49 bytes):1526 {"version":1,"root":{"type":"regular","size":44}}15272026/11/01 16:14:31 WARN Failed to register uploaded object key=ybzsghrszvsmsfvxvvdfz855mqy7jzxw.ls error="server returned 404: 404 page not found\n"15282026/11/01 16:14:31 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign15292026/11/01 16:14:31 WARN Failed to register uploaded object key=nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst error="server returned 404: 404 page not found\n"15302026/11/01 16:14:31 INFO Signed narinfos id=1 count=115312026/11/01 16:14:31 INFO Uploading 1 narinfos15322026/11/01 16:14:31 INFO Received complete push request method=POST path=/api/pushes/1/complete15332026/11/01 16:14:31 WARN Failed to register uploaded object key=ybzsghrszvsmsfvxvvdfz855mqy7jzxw.narinfo error="server returned 404: 404 page not found\n"1534--- PASS: TestNARDeduplicationMetadataUploadBug (7.09s)1535=== CONT TestRedundantMultipartUpload15362026/11/01 16:14:31 INFO Completed push id=1 objects=3 duration=19.406ms15372026/11/01 16:14:31 INFO Upload complete. (239ms)15382026/11/01 16:14:31 INFO All 1 paths already cached1539=== NAME TestClientIntegration1540 client_integration_test.go:317: Retrieved narinfo from S3:1541 StorePath: /private/var/tb/3/scratch/4a1a633e2471393e/build/TestClientIntegration1365175756/002/store/ybzsghrszvsmsfvxvvdfz855mqy7jzxw-test-file.txt1542 URL: nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst1543 Compression: zstd1544 NarHash: sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11545 NarSize: 1521546 References: 1547 CA: fixed:r:sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11548 client_integration_test.go:318: Retrieved .ls file from S3 (compressed size: 77 bytes)1549 client_integration_test.go:318: Decompressed .ls content (64 bytes):1550 {"version":1,"root":{"type":"regular","size":39,"narOffset":96}}1551=== NAME TestClientWithDependencies1552 client_integration_test.go:660: Built derivation: /private/var/tb/3/scratch/4a1a633e2471393e/build/TestClientWithDependencies1140211963/001/store/cf2svgnps24j4nayhqm5pg11bjvx24xy-test-script1553 client_integration_test.go:662: Found 1 dependencies (including self)1554=== NAME TestClientMultipleUploads1555 client_integration_test.go:405: Created store path 0: /private/var/tb/3/scratch/4a1a633e2471393e/build/TestClientMultipleUploads3069189942/001/store/dlyf15vdknik1d5h24b0jqrvrjc4xarn-test-file-0.txt15562026/11/01 16:14:31 INFO Received push request method=POST path=/api/pushes15572026/11/01 16:14:31 INFO Object in database but missing from S3 key=ybzsghrszvsmsfvxvvdfz855mqy7jzxw.ls15582026/11/01 16:14:31 WARN Found objects in DB but missing from S3, will re-upload count=115592026/11/01 16:14:31 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)1560 client_integration_test.go:405: Created store path 1: /private/var/tb/3/scratch/4a1a633e2471393e/build/TestClientMultipleUploads3069189942/001/store/lhk4mfh9fny3i6wnlysjlm9ng4f6mzpx-test-file-1.txt15612026/11/01 16:14:31 INFO Received push request method=POST path=/api/pushes15622026/11/01 16:14:31 INFO Received complete push request method=POST path=/api/pushes/2/complete15632026/11/01 16:14:31 WARN Failed to register uploaded object key=ybzsghrszvsmsfvxvvdfz855mqy7jzxw.ls error="server returned 404: 404 page not found\n"15642026/11/01 16:14:31 INFO Completed push id=2 objects=3 duration=583.042µs15652026/11/01 16:14:31 INFO Upload complete. (114ms)1566=== NAME TestClientIntegration1567 client_integration_test.go:335: Retrieved .ls file from S3 (compressed size: 62 bytes)1568 client_integration_test.go:335: Decompressed .ls content (49 bytes):15692026/11/01 16:14:31 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)1570 {"version":1,"root":{"type":"regular","size":39}}15712026/11/01 16:14:31 INFO Uploading cf2svgnps24j4nayhqm5pg11bjvx24xy-test-script (136B)1572=== NAME TestClientMultipleUploads1573 client_integration_test.go:405: Created store path 2: /private/var/tb/3/scratch/4a1a633e2471393e/build/TestClientMultipleUploads3069189942/001/store/4rsj7nxn7rn4i8s3k4djpz8l79fh6hfl-test-file-2.txt15742026/11/01 16:14:31 WARN Failed to register uploaded object key=cf2svgnps24j4nayhqm5pg11bjvx24xy.ls error="server returned 404: 404 page not found\n"15752026/11/01 16:14:31 WARN Failed to register uploaded object key=nar/1s7yghixzpinyqm7g59kyn3sav81pmnsdi5v63m6x4r2vacy907j.nar.zst error="server returned 404: 404 page not found\n"15762026/11/01 16:14:31 WARN Failed to register uploaded object key=log/krw8wfqbwvcj56gdz943brj0hpcbsjdw-test-script.drv error="server returned 404: 404 page not found\n"15772026/11/01 16:14:31 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign15782026/11/01 16:14:31 INFO Signed narinfos id=1 count=115792026/11/01 16:14:31 INFO Uploading 1 narinfos15802026/11/01 16:14:32 INFO Received complete push request method=POST path=/api/pushes/1/complete15812026/11/01 16:14:32 WARN Failed to register uploaded object key=cf2svgnps24j4nayhqm5pg11bjvx24xy.narinfo error="server returned 404: 404 page not found\n"15822026/11/01 16:14:32 INFO Received push request method=POST path=/api/pushes15832026/11/01 16:14:32 INFO Completed push id=1 objects=4 duration=39.261042ms15842026/11/01 16:14:32 INFO Upload complete. (305ms)1585=== NAME TestClientWithDependencies1586 client_integration_test.go:664: Skipping nix copy test - isolated store (/private/var/tb/3/scratch/4a1a633e2471393e/build/TestClientWithDependencies1140211963/001/store) requires matching store prefix15872026/11/01 16:14:32 INFO Uploading 3 paths to 127.0.0.1 (0 already cached)15882026/11/01 16:14:32 INFO Uploading dlyf15vdknik1d5h24b0jqrvrjc4xarn-test-file-0.txt (160B)15892026/11/01 16:14:32 INFO Uploading 4rsj7nxn7rn4i8s3k4djpz8l79fh6hfl-test-file-2.txt (160B)15902026/11/01 16:14:32 INFO Uploading lhk4mfh9fny3i6wnlysjlm9ng4f6mzpx-test-file-1.txt (160B)15912026/11/01 16:14:32 WARN Failed to register uploaded object key=nar/0ahq3izw3h0b0c08p3xdfclh758fwxnp85ccvflasb4vnfsv50ri.nar.zst error="server returned 404: 404 page not found\n"15922026/11/01 16:14:32 WARN Failed to register uploaded object key=dlyf15vdknik1d5h24b0jqrvrjc4xarn.ls error="server returned 404: 404 page not found\n"15932026/11/01 16:14:32 WARN Failed to register uploaded object key=nar/13p9pqi0ga6fx2apcwls9hjnv7nmf740ggpn5zvfzdsp5vz2bbg4.nar.zst error="server returned 404: 404 page not found\n"15942026/11/01 16:14:32 WARN Failed to register uploaded object key=lhk4mfh9fny3i6wnlysjlm9ng4f6mzpx.ls error="server returned 404: 404 page not found\n"15952026/11/01 16:14:32 WARN Failed to register uploaded object key=4rsj7nxn7rn4i8s3k4djpz8l79fh6hfl.ls error="server returned 404: 404 page not found\n"15962026/11/01 16:14:32 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign15972026/11/01 16:14:32 WARN Failed to register uploaded object key=nar/1823g6vx4q5zqvr73m7lkq1wpk40fin7bsc792di430yk7sg4lka.nar.zst error="server returned 404: 404 page not found\n"15982026/11/01 16:14:32 INFO Signed narinfos id=1 count=31599--- PASS: TestClientWithDependencies (7.36s)1600=== CONT TestPush_SignsNarinfosOfItsPendingObjects16012026/11/01 16:14:32 INFO Uploading 3 narinfos1602--- PASS: TestCacheStatsHandler (6.82s)1603=== CONT TestGCTaskStore_ConflictDifferentParams1604--- PASS: TestGCTaskStore_ConflictDifferentParams (0.00s)1605=== CONT TestGCTaskStore_DeduplicateSameParams1606--- PASS: TestGCTaskStore_DeduplicateSameParams (0.00s)1607=== CONT TestPush_RepeatedRootCommitsOnce16082026/11/01 16:14:32 WARN Failed to register uploaded object key=4rsj7nxn7rn4i8s3k4djpz8l79fh6hfl.narinfo error="server returned 404: 404 page not found\n"16092026/11/01 16:14:32 WARN Failed to register uploaded object key=lhk4mfh9fny3i6wnlysjlm9ng4f6mzpx.narinfo error="server returned 404: 404 page not found\n"16102026/11/01 16:14:32 INFO Received complete push request method=POST path=/api/pushes/1/complete16112026/11/01 16:14:32 WARN Failed to register uploaded object key=dlyf15vdknik1d5h24b0jqrvrjc4xarn.narinfo error="server returned 404: 404 page not found\n"16122026/11/01 16:14:32 INFO Received push request method=POST path=/api/pushes16132026/11/01 16:14:32 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)16142026/11/01 16:14:32 INFO Completed push id=1 objects=9 duration=31.748625ms16152026/11/01 16:14:32 INFO Received complete push request method=POST path=/api/pushes/3/complete16162026/11/01 16:14:32 INFO Upload complete. (343ms)1617=== NAME TestClientMultipleUploads1618 client_integration_test.go:416: Uploaded 3 paths in 377.884209ms16192026/11/01 16:14:32 WARN Failed to register uploaded object key=ybzsghrszvsmsfvxvvdfz855mqy7jzxw.ls error="server returned 404: 404 page not found\n"16202026/11/01 16:14:32 INFO Completed push id=3 objects=3 duration=720.167µs16212026/11/01 16:14:32 INFO Upload complete. (112ms)1622=== NAME TestClientIntegration1623 client_integration_test.go:352: Retrieved .ls file from S3 (compressed size: 62 bytes)1624 client_integration_test.go:352: Decompressed .ls content (49 bytes):1625 {"version":1,"root":{"type":"regular","size":39}}1626 client_integration_test.go:363: Testing garbage collection...1627--- PASS: TestClientMultipleUploads (7.47s)1628=== CONT TestPush_SkippedKeySurvivesGCBeforeCommit1629=== NAME TestClientCADerivations1630 client_ca_test.go:136: Built CA derivation: /private/var/tb/3/scratch/4a1a633e2471393e/build/TestClientCADerivations2870624254/001/store/fmya01f4lw7r9zzdhxzsji9bfmj3mnck-ca-test16312026/11/01 16:14:32 INFO Starting cleanup of old closures method=DELETE path=/api/closures16322026/11/01 16:14:32 INFO Garbage collection started16332026/11/01 16:14:32 INFO Aborted multipart uploads count=0 kept=016342026/11/01 16:14:32 WARN Force mode enabled - objects will be deleted immediately without grace period1635 client_ca_test.go:139: Found 1 dependencies (including self)16362026/11/01 16:14:32 INFO Received uploads request method=POST path=/api/pending_closures1637--- PASS: TestCreatePendingClosure_SmallNARUsesSimplePUT (6.94s)1638=== CONT TestPush_RootsAreLockedInByteOrder16392026/11/01 16:14:32 INFO Received push request method=POST path=/api/pushes16402026/11/01 16:14:32 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)16412026/11/01 16:14:32 INFO Uploading fmya01f4lw7r9zzdhxzsji9bfmj3mnck-ca-test (144B)16422026/11/01 16:14:32 WARN Failed to register uploaded object key=fmya01f4lw7r9zzdhxzsji9bfmj3mnck.ls error="server returned 404: 404 page not found\n"16432026/11/01 16:14:32 WARN Failed to register uploaded object key=nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst error="server returned 404: 404 page not found\n"16442026/11/01 16:14:32 WARN Failed to register uploaded object key=log/n0kdsrc9ggzlh76ziq4kbsh7lp5nl5kx-ca-test.drv error="server returned 404: 404 page not found\n"16452026/11/01 16:14:32 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign16462026/11/01 16:14:32 INFO Signed narinfos id=1 count=116472026/11/01 16:14:32 INFO Uploading 1 narinfos16482026/11/01 16:14:32 INFO Received complete multipart upload request method=POST path=/api/multipart/complete16492026/11/01 16:14:32 ERROR Failed to get multipart upload error="no rows in result set" upload_id=does-not-exist object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst1650--- PASS: TestCompleteMultipartUnregistered (6.78s)1651=== CONT TestPush_CompleteWaitsForCleanupOfThePush16522026/11/01 16:14:32 INFO Received complete push request method=POST path=/api/pushes/1/complete16532026/11/01 16:14:32 WARN Failed to register uploaded object key=fmya01f4lw7r9zzdhxzsji9bfmj3mnck.narinfo error="server returned 404: 404 page not found\n"16542026/11/01 16:14:32 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=1 objects-marked-for-deletion=3 objects-deleted-after-grace-period=3 objects-failed-to-delete=016552026/11/01 16:14:32 INFO Completed push id=1 objects=4 duration=28.810542ms16562026/11/01 16:14:32 INFO Upload complete. (384ms)1657=== NAME TestClientCADerivations1658 client_ca_test.go:180: Narinfo contains CA field: StorePath: /private/var/tb/3/scratch/4a1a633e2471393e/build/TestClientCADerivations2870624254/001/store/fmya01f4lw7r9zzdhxzsji9bfmj3mnck-ca-test1659 URL: nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst1660 Compression: zstd1661 NarHash: sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1662 NarSize: 1441663 References: 1664 Deriver: /private/var/tb/3/scratch/4a1a633e2471393e/build/TestClientCADerivations2870624254/001/store/n0kdsrc9ggzlh76ziq4kbsh7lp5nl5kx-ca-test.drv1665 CA: fixed:r:sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1666 client_ca_test.go:185: Checking for realisation files in S3...1667 client_ca_test.go:207: No realisation files uploaded - this is expected for locally built CA derivations1668 client_ca_test.go:208: Locally built CA derivations don't have DrvOutput IDs until they're substituted from a cache16692026/11/01 16:14:32 INFO Vacuumed table table=pending_closures16702026/11/01 16:14:32 INFO Vacuumed table table=pending_objects16712026/11/01 16:14:32 INFO Vacuumed table table=multipart_uploads16722026/11/01 16:14:32 INFO Vacuumed table table=closures16732026/11/01 16:14:32 INFO Vacuumed table table=objects1674 client_ca_test.go:258: nix copy output: error: binary cache 's3://bucket63?endpoint=http://localhost:58887®ion=eu-west-1' is for Nix stores with prefix '/nix/store', not '/private/var/tb/3/scratch/4a1a633e2471393e/build/TestClientCADerivations2870624254/001/store'1675 client_ca_test.go:259: nix copy failed (might be expected with isolated stores): exit status 116762026/11/01 16:14:33 INFO Received uploads request method=POST path=/api/pending_closures1677--- PASS: TestClientCADerivations (7.89s)1678=== CONT TestPush_OverlappingRootsStoreOneRowPerKey16792026/11/01 16:14:33 INFO Received uploads request method=POST path=/api/pending_closures16802026/11/01 16:14:33 INFO Received uploads request method=POST path=/api/pending_closures16812026/11/01 16:14:33 INFO Received uploads request method=POST path=/api/pending_closures16822026/11/01 16:14:33 INFO Received cleanup request method=DELETE path=/api/pending_closures16832026/11/01 16:14:33 INFO Aborted multipart uploads count=0 kept=016842026/11/01 16:14:33 INFO Received uploads request method=POST path=/api/pending_closures16852026/11/01 16:14:33 INFO Received cleanup request method=DELETE path=/api/pending_closures16862026/11/01 16:14:33 INFO Aborted multipart uploads count=1 kept=016872026/11/01 16:14:33 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete16882026-11-01 16:14:33.736 UTC [95163] ERROR: Closure does not exist: id=116892026-11-01 16:14:33.736 UTC [95163] CONTEXT: PL/pgSQL function commit_pending_closure(bigint) line 13 at RAISE16902026-11-01 16:14:33.736 UTC [95163] STATEMENT: -- name: CommitPendingClosure :one1691 SELECT commit_pending_closure($1::bigint)::bigint1692 1693--- PASS: TestService_cleanupPendingClosuresHandler (7.26s)1694=== CONT TestPush_CompleteCommitsEveryRoot16952026/11/01 16:14:33 INFO Received uploads request method=POST path=/api/pending_closures16962026/11/01 16:14:34 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted,O=Other"16972026/11/01 16:14:34 WARN mTLS auth: bound subjects configured but subject DN unavailable16982026/11/01 16:14:34 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted"1699--- PASS: TestService_AuthMiddleware_MTLSBoundSubjects (6.51s)1700=== CONT TestReadRedirectUsesPublicS3URL17012026/11/01 16:14:34 INFO Received complete multipart upload request method=POST path=/api/multipart/complete17022026/11/01 16:14:34 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=01703=== NAME TestClientIntegration1704 client_integration_test.go:370: Objects in database after GC:1705 client_integration_test.go:370: Successfully deleted all objects with GC --force17062026/11/01 16:14:34 INFO Aborted multipart uploads count=1 kept=01707--- PASS: TestClientIntegration (9.53s)1708=== CONT TestService_AuthMiddleware_OIDC17092026/11/01 16:14:34 INFO Received cleanup request method=DELETE path=/api/pending_closures17102026/11/01 16:14:34 INFO Aborted multipart uploads count=1 kept=01711--- PASS: TestPendingCleanupUsesOneCutoff (11.09s)1712=== CONT TestForceGCDuringPushOffersSweptObject/before_pending_rows17132026/11/01 16:14:34 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:59275/oidc17142026/11/01 16:14:34 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1715--- PASS: TestService_ReadAuthMiddleware (6.66s)1716=== CONT TestGCEndsOnShutdown/before_the_run17172026/11/01 16:14:34 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst upload_id=MWZlZGYxYzQtMWFiYy00MTg1LThlNzctYjc2ODFiODQyMzJjLjI1MDgyNzliLTEzNDgtNDZlZi1iZWU0LWI1ZmI1MzU4YmUwOHgxNzkzNTQ5NjczMDUyMjUzMDAw parts=1017182026/11/01 16:14:34 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete17192026/11/01 16:14:34 INFO Completed upload id=1 objects=2 duration=25.5125ms17202026/11/01 16:14:34 INFO Received uploads request method=POST path=/api/pending_closures17212026/11/01 16:14:34 INFO Received uploads request method=POST path=/api/pending_closures17222026/11/01 16:14:34 INFO Object in database but missing from S3 key=dadb44fdadb44fdadb44fdadb44f0000.narinfo17232026/11/01 16:14:34 WARN Found objects in DB but missing from S3, will re-upload count=11724--- PASS: TestService_verifyS3Integrity (8.59s)1725=== CONT TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark1726--- PASS: TestService_AuthMiddleware_MTLSProxyHeader (6.44s)1727=== CONT TestForceGCDuringPushOffersSweptObject/after_presence_check17282026/11/01 16:14:35 INFO Received complete multipart upload request method=POST path=/api/multipart/complete17292026/11/01 16:14:35 INFO Completed multipart upload object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst upload_id=MWZlZGYxYzQtMWFiYy00MTg1LThlNzctYjc2ODFiODQyMzJjLmUyMjRiZTNlLTMxNTMtNGYwZC05NThiLWQyZGU1YjQ2YTAwNngxNzkzNTQ5NjczMjg5MjEzMDAw parts=1017302026/11/01 16:14:35 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete17312026/11/01 16:14:35 INFO Completed upload id=1 objects=2 duration=83.049583ms17322026/11/01 16:14:35 INFO Received get closure request method=GET path=/api/closures/0000000000000000000000000000000017332026/11/01 16:14:35 INFO Received uploads request method=POST path=/api/pending_closures17342026/11/01 16:14:35 INFO Starting cleanup of old closures method=DELETE path=/api/closures1735--- PASS: TestService_ReadScope_PublicByDefault (6.94s)1736=== CONT TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete17372026/11/01 16:14:35 INFO Aborted multipart uploads count=0 kept=017382026/11/01 16:14:35 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=017392026/11/01 16:14:35 INFO Vacuumed table table=pending_closures17402026/11/01 16:14:35 INFO Vacuumed table table=pending_objects17412026/11/01 16:14:35 INFO Vacuumed table table=multipart_uploads17422026/11/01 16:14:35 INFO Vacuumed table table=closures17432026/11/01 16:14:35 INFO Vacuumed table table=objects17442026/11/01 16:14:35 INFO Received get closure request method=GET path=/api/closures/000000000000000000000000000000001745--- PASS: TestService_createPendingClosureHandler (9.18s)1746=== CONT TestResolveDBConnectionString/flag_wins1747=== CONT TestResolveDBConnectionString/PGHOST_allows_empty1748=== CONT TestResolveDBConnectionString/nothing_configured1749=== CONT TestResolveDBConnectionString/missing_file_is_an_error1750=== CONT TestResolveDBConnectionString/file_when_flag_empty1751=== CONT TestIsValidCachePath/narinfo1752=== CONT TestIsValidCachePath/index.html1753=== CONT TestIsValidCachePath/short_hash1754=== CONT TestIsValidCachePath/wrong_extension1755=== CONT TestIsValidCachePath/leading_slash1756=== CONT TestIsValidCachePath/empty1757=== CONT TestIsValidCachePath/random_path1758=== CONT TestIsValidCachePath/invalid_char_u1759=== CONT TestIsValidCachePath/invalid_char_e1760=== CONT TestIsValidCachePath/traversal_in_middle1761=== CONT TestIsValidCachePath/traversal_parent1762=== CONT TestIsValidCachePath/nar_uncompressed1763=== CONT TestIsValidCachePath/nix-cache-info1764=== CONT TestIsValidCachePath/realisation1765--- PASS: TestResolveDBConnectionString (0.03s)1766 --- PASS: TestResolveDBConnectionString/flag_wins (0.00s)1767 --- PASS: TestResolveDBConnectionString/PGHOST_allows_empty (0.00s)1768 --- PASS: TestResolveDBConnectionString/nothing_configured (0.00s)1769 --- PASS: TestResolveDBConnectionString/missing_file_is_an_error (0.00s)1770 --- PASS: TestResolveDBConnectionString/file_when_flag_empty (0.00s)1771=== CONT TestIsValidCachePath/log1772=== CONT TestIsValidCachePath/ls1773=== CONT TestIsValidCachePath/nar_xz1774=== CONT TestIsValidCachePath/nar_bz21775=== CONT TestIsValidCachePath/nar_zst1776=== CONT TestIsValidCachePath/narinfo_all_nix_base32_chars1777--- PASS: TestIsValidCachePath (0.00s)1778 --- PASS: TestIsValidCachePath/narinfo (0.00s)1779 --- PASS: TestIsValidCachePath/index.html (0.00s)1780 --- PASS: TestIsValidCachePath/short_hash (0.00s)1781 --- PASS: TestIsValidCachePath/wrong_extension (0.00s)1782 --- PASS: TestIsValidCachePath/leading_slash (0.00s)1783 --- PASS: TestIsValidCachePath/empty (0.00s)1784 --- PASS: TestIsValidCachePath/random_path (0.00s)1785 --- PASS: TestIsValidCachePath/invalid_char_u (0.00s)1786 --- PASS: TestIsValidCachePath/invalid_char_e (0.00s)1787 --- PASS: TestIsValidCachePath/traversal_in_middle (0.00s)1788 --- PASS: TestIsValidCachePath/traversal_parent (0.00s)1789 --- PASS: TestIsValidCachePath/nar_uncompressed (0.00s)1790 --- PASS: TestIsValidCachePath/nix-cache-info (0.00s)1791 --- PASS: TestIsValidCachePath/realisation (0.00s)1792 --- PASS: TestIsValidCachePath/log (0.00s)1793 --- PASS: TestIsValidCachePath/ls (0.00s)1794 --- PASS: TestIsValidCachePath/nar_xz (0.00s)1795 --- PASS: TestIsValidCachePath/nar_bz2 (0.00s)1796 --- PASS: TestIsValidCachePath/nar_zst (0.00s)1797 --- PASS: TestIsValidCachePath/narinfo_all_nix_base32_chars (0.00s)1798=== CONT TestParseSingleRange/none1799=== CONT TestParseSingleRange/open-ended1800=== CONT TestParseSingleRange/start_far_past_EOF1801=== CONT TestParseSingleRange/start_past_EOF1802=== CONT TestParseSingleRange/single_byte1803=== CONT TestParseSingleRange/suffix_exceeds_size1804=== CONT TestParseSingleRange/suffix1805=== CONT TestParseSingleRange/end_clamped_to_size1806=== CONT TestParseSingleRange/malformed_both_empty1807=== CONT TestParseSingleRange/closed1808=== CONT TestParseSingleRange/malformed_end_before_start1809=== CONT TestParseSingleRange/multi-range_ignored1810=== CONT TestParseSingleRange/malformed_no_dash1811=== CONT TestParseSingleRange/unknown_unit1812--- PASS: TestParseSingleRange (0.00s)1813 --- PASS: TestParseSingleRange/none (0.00s)1814 --- PASS: TestParseSingleRange/open-ended (0.00s)1815 --- PASS: TestParseSingleRange/start_far_past_EOF (0.00s)1816 --- PASS: TestParseSingleRange/start_past_EOF (0.00s)1817 --- PASS: TestParseSingleRange/single_byte (0.00s)1818 --- PASS: TestParseSingleRange/suffix_exceeds_size (0.00s)1819 --- PASS: TestParseSingleRange/suffix (0.00s)1820 --- PASS: TestParseSingleRange/end_clamped_to_size (0.00s)1821 --- PASS: TestParseSingleRange/malformed_both_empty (0.00s)1822 --- PASS: TestParseSingleRange/closed (0.00s)1823 --- PASS: TestParseSingleRange/malformed_end_before_start (0.00s)1824 --- PASS: TestParseSingleRange/multi-range_ignored (0.00s)1825 --- PASS: TestParseSingleRange/malformed_no_dash (0.00s)1826 --- PASS: TestParseSingleRange/unknown_unit (0.00s)1827=== CONT TestPresentNotReportedWhileGCDeletesClosure/stale1828=== RUN TestPush_RejectsBadRequests/no_objects1829=== PAUSE TestPush_RejectsBadRequests/no_objects1830=== RUN TestPush_RejectsBadRequests/bad_root1831=== PAUSE TestPush_RejectsBadRequests/bad_root1832=== RUN TestPush_RejectsBadRequests/root_not_in_objects1833=== PAUSE TestPush_RejectsBadRequests/root_not_in_objects1834=== RUN TestPush_RejectsBadRequests/no_roots1835=== PAUSE TestPush_RejectsBadRequests/no_roots1836=== CONT TestPresentNotReportedWhileGCDeletesClosure/fresh1837--- PASS: TestService_Rustfstest (6.24s)1838=== CONT TestServerTLSConfig/no_client_CA1839=== CONT TestServerTLSConfig/not_a_PEM_file1840=== CONT TestServerTLSConfig/missing_CA_file1841--- PASS: TestServerTLSConfig (0.00s)1842 --- PASS: TestServerTLSConfig/no_client_CA (0.00s)1843 --- PASS: TestServerTLSConfig/not_a_PEM_file (0.00s)1844 --- PASS: TestServerTLSConfig/missing_CA_file (0.00s)1845=== CONT TestCacheConfigHandler/full_config,_no_issuer1846=== CONT TestCacheConfigHandler/no_signing_keys1847=== CONT TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1848=== CONT TestCacheConfigHandler/no_cache_url_configured1849--- PASS: TestCacheConfigHandler (0.00s)1850 --- PASS: TestCacheConfigHandler/full_config,_no_issuer (0.00s)1851 --- PASS: TestCacheConfigHandler/no_signing_keys (0.00s)1852 --- PASS: TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator (0.00s)1853 --- PASS: TestCacheConfigHandler/no_cache_url_configured (0.00s)1854=== CONT TestClientErrorHandling/InvalidStorePath1855=== RUN TestService_RequireScope_OIDC/builder_may_write1856=== PAUSE TestService_RequireScope_OIDC/builder_may_write1857=== RUN TestService_RequireScope_OIDC/builder_may_not_admin1858=== PAUSE TestService_RequireScope_OIDC/builder_may_not_admin1859=== RUN TestService_RequireScope_OIDC/ops_may_admin1860=== PAUSE TestService_RequireScope_OIDC/ops_may_admin1861=== RUN TestService_RequireScope_OIDC/ops_may_not_write1862=== PAUSE TestService_RequireScope_OIDC/ops_may_not_write1863=== RUN TestService_RequireScope_OIDC/reader_may_not_write1864=== PAUSE TestService_RequireScope_OIDC/reader_may_not_write1865=== RUN TestService_RequireScope_OIDC/static_token_may_admin1866=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin1867=== RUN TestService_RequireScope_OIDC/static_token_may_write1868=== PAUSE TestService_RequireScope_OIDC/static_token_may_write1869=== RUN TestService_RequireScope_OIDC/reader_may_read1870=== PAUSE TestService_RequireScope_OIDC/reader_may_read1871=== RUN TestService_RequireScope_OIDC/writer_implies_read1872=== PAUSE TestService_RequireScope_OIDC/writer_implies_read1873=== RUN TestService_RequireScope_OIDC/anonymous_may_not_read1874=== PAUSE TestService_RequireScope_OIDC/anonymous_may_not_read1875=== RUN TestService_RequireScope_OIDC/reader_may_read_with_netrc1876=== PAUSE TestService_RequireScope_OIDC/reader_may_read_with_netrc1877=== RUN TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1878=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1879=== RUN TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read1880=== PAUSE TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read1881=== RUN TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1882=== PAUSE TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1883=== CONT TestClientErrorHandling/ServerNotAvailable18842026/11/01 16:14:36 INFO Received uploads request method=POST path=/api/pending_closures18852026/11/01 16:14:36 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/present18862026/11/01 16:14:36 INFO Registered completed upload object_key=nar/jjjjjjjjjjjjjjjjjjjjjjjjjjjjjj0100000000000000000000.nar.zst18872026/11/01 16:14:36 INFO Received uploads request method=POST path=/api/pending_closures1888--- PASS: TestPresignedUploadRegisteredBeforeCommit (6.89s)1889=== CONT TestClientErrorHandling/InvalidAuthToken18902026/11/01 16:14:36 WARN Request failed, retrying attempt=2 backoff=209.0098ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present18912026/11/01 16:14:36 INFO Received uploads request method=POST path=/api/pending_closures18922026/11/01 16:14:37 WARN Request failed, retrying attempt=3 backoff=419.357479ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present18932026/11/01 16:14:37 INFO Received uploads request method=POST path=/api/pending_closures18942026/11/01 16:14:37 WARN Request failed, retrying attempt=4 backoff=846.32262ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present18952026/11/01 16:14:37 INFO Received complete multipart upload request method=POST path=/api/multipart/complete18962026/11/01 16:14:37 INFO Received uploads request method=POST path=/api/pending_closures18972026/11/01 16:14:37 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified key does not exist." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=MWZlZGYxYzQtMWFiYy00MTg1LThlNzctYjc2ODFiODQyMzJjLmUwNTlkMmI1LTVhY2UtNDgxYS04ZjIyLWY1NDllZmUzZmQxNHgxNzkzNTQ5Njc3MjcyMDMyMDAw18982026/11/01 16:14:37 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=MWZlZGYxYzQtMWFiYy00MTg1LThlNzctYjc2ODFiODQyMzJjLmUwNTlkMmI1LTVhY2UtNDgxYS04ZjIyLWY1NDllZmUzZmQxNHgxNzkzNTQ5Njc3MjcyMDMyMDAw parts=11899--- PASS: TestCompleteMultipartUpload_ErrorButObjectExists (7.03s)1900=== CONT TestService_verifyS3ReuploadsNarinfoOfLostNAR/lost,_other_NAR19012026/11/01 16:14:37 INFO Received uploads request method=POST path=/api/pending_closures19022026/11/01 16:14:37 INFO Received push request method=POST path=/api/pushes19032026/11/01 16:14:38 INFO Received complete push request method=POST path=/api/pushes/1/complete19042026/11/01 16:14:38 INFO Completed push id=1 objects=4 duration=69.96325ms1905--- PASS: TestPush_RepeatedRootCommitsOnce (5.99s)1906=== CONT TestService_verifyS3ReuploadsNarinfoOfLostNAR/named_one_of_two_lost,_other_pushed19072026/11/01 16:14:38 WARN Rate limiter enabled after throttle name=s3-test rate=519082026/11/01 16:14:38 WARN S3 rate limit hit operation="complete multipart upload" error="Please reduce your request rate."1909=== NAME TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle1910 throttle_test.go:213: Proxy stats: total=13, throttled=10, completeMultipart=101911 throttle_test.go:215: Rate limiter: enabled=true, rate=5.001912--- PASS: TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle (11.51s)1913=== CONT TestService_verifyS3ReuploadsNarinfoOfLostNAR/lost,_same_NAR_pushed19142026/11/01 16:14:38 WARN Request failed, retrying attempt=5 backoff=1.510302773s error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present19152026/11/01 16:14:38 INFO Received push request method=POST path=/api/pushes19162026/11/01 16:14:38 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign19172026/11/01 16:14:38 INFO Signed narinfos id=1 count=119182026/11/01 16:14:38 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign19192026/11/01 16:14:38 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign19202026/11/01 16:14:38 ERROR Failed to sign narinfos signer="index 1" error="signing key cannot be nil"19212026/11/01 16:14:38 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign19222026/11/01 16:14:38 ERROR Failed to sign narinfos signer=niks3-test-1 error="signer failed"19232026/11/01 16:14:38 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign19242026/11/01 16:14:38 ERROR Signer returned unexpected signature count signer=niks3-test-1 got=0 want=119252026/11/01 16:14:38 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign19262026/11/01 16:14:38 ERROR Signer returned unexpected object key signer=niks3-test-1 object_key=unexpected.narinfo1927--- PASS: TestPush_SignsNarinfosOfItsPendingObjects (6.45s)1928=== CONT TestService_verifyS3ReuploadsNarinfoOfLostNAR/named_one_of_two_lost19292026/11/01 16:14:38 INFO Received push request method=POST path=/api/pushes19302026/11/01 16:14:39 INFO Received complete push request method=POST path=/api/pushes/1/complete19312026/11/01 16:14:39 INFO Completed push id=1 objects=4 duration=52.767833ms19322026/11/01 16:14:39 INFO Received push request method=POST path=/api/pushes19332026/11/01 16:14:39 INFO Received complete multipart upload request method=POST path=/api/multipart/complete19342026/11/01 16:14:39 INFO Aborted multipart uploads count=0 kept=019352026/11/01 16:14:39 INFO Completed multipart upload object_key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhh0100000000000000000000.nar.zst upload_id=MWZlZGYxYzQtMWFiYy00MTg1LThlNzctYjc2ODFiODQyMzJjLjBlYjFhOTYwLWNmOTUtNGRhNC04NWJhLTFmZDVkZTUxMDgyNngxNzkzNTQ5Njc2OTEyNjIxMDAw parts=1219362026/11/01 16:14:39 INFO Received push request method=POST path=/api/pushes19372026/11/01 16:14:39 INFO Received uploads request method=POST path=/api/pending_closures19382026/11/01 16:14:39 WARN Force mode enabled - objects will be deleted immediately without grace period1939--- PASS: TestCompletedNarNotReofferedAcrossClosures (9.13s)1940=== CONT TestService_verifyS3ReuploadsNarinfoOfLostNAR/intact,_other_NAR19412026/11/01 16:14:39 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=019422026/11/01 16:14:39 INFO Vacuumed table table=pending_closures19432026/11/01 16:14:39 INFO Vacuumed table table=pending_objects19442026/11/01 16:14:39 INFO Vacuumed table table=multipart_uploads19452026/11/01 16:14:39 INFO Vacuumed table table=closures1946=== NAME TestOrphanedObjectsGCStressTest19472026-11-01 16:14:39.532 UTC [95295] ERROR: could not obtain lock on row in relation "closures"19482026-11-01 16:14:39.532 UTC [95295] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT1949 orphaned_objects_gc_test.go:422: Created 10 active closures, 5 to-delete closures, 20 orphaned chains19502026-11-01 16:14:39.541 UTC [95295] ERROR: could not obtain lock on row in relation "closures"19512026-11-01 16:14:39.541 UTC [95295] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT19522026-11-01 16:14:39.546 UTC [95295] ERROR: could not obtain lock on row in relation "closures"19532026-11-01 16:14:39.546 UTC [95295] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT19542026-11-01 16:14:39.553 UTC [95295] ERROR: could not obtain lock on row in relation "closures"19552026-11-01 16:14:39.553 UTC [95295] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT19562026-11-01 16:14:39.561 UTC [95295] ERROR: could not obtain lock on row in relation "closures"19572026-11-01 16:14:39.561 UTC [95295] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT19582026/11/01 16:14:39 INFO Vacuumed table table=objects19592026/11/01 16:14:39 INFO Received complete push request method=POST path=/api/pushes/2/complete19602026/11/01 16:14:39 INFO Completed push id=2 objects=4 duration=8.193166ms1961--- PASS: TestPush_SkippedKeySurvivesGCBeforeCommit (7.24s)1962--- PASS: TestPush_RootsAreLockedInByteOrder (7.06s)1963=== CONT TestUploadHandlersRejectOversizedBody/request_more_parts19642026/11/01 16:14:39 INFO Received request for more parts method=POST path=/1965=== CONT TestUploadHandlersRejectOversizedBody/create_pending_closure19662026/11/01 16:14:39 INFO Received uploads request method=POST path=/1967=== CONT TestUploadHandlersRejectOversizedBody/complete_multipart19682026/11/01 16:14:39 INFO Received complete multipart upload request method=POST path=/1969=== NAME TestOrphanedObjectsGCStressTest1970 orphaned_objects_gc_test.go:440: Marked 210 objects for deletion1971=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info19722026/11/01 16:14:39 INFO Received uploads request method=POST path=/1973=== CONT TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key19742026/11/01 16:14:39 INFO Received complete multipart upload request method=POST path=/1975=== CONT TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key19762026/11/01 16:14:39 INFO Received request for more parts method=POST path=/1977=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal19782026/11/01 16:14:39 INFO Received uploads request method=POST path=/1979--- PASS: TestUploadHandlersRejectInvalidKeys (0.00s)1980 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info (0.00s)1981 --- PASS: TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key (0.00s)1982 --- PASS: TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key (0.00s)1983 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal (0.00s)1984=== CONT TestIsValidUploadKey/narinfo1985=== CONT TestIsValidUploadKey/realisation_plus_in_output1986=== CONT TestIsValidUploadKey/unknown_type1987=== CONT TestIsValidUploadKey/empty_key1988=== CONT TestIsValidUploadKey/absolute1989=== CONT TestIsValidUploadKey/traversal_nar1990=== CONT TestIsValidUploadKey/traversal1991=== CONT TestIsValidUploadKey/listing_key,_narinfo_type1992=== CONT TestIsValidUploadKey/nar_key,_narinfo_type1993=== CONT TestIsValidUploadKey/narinfo_key,_nar_type1994=== CONT TestIsValidUploadKey/index.html1995=== CONT TestIsValidUploadKey/nix-cache-info1996=== CONT TestIsValidUploadKey/build_log_home-manager_file1997=== CONT TestIsValidUploadKey/realisation1998=== CONT TestIsValidUploadKey/build_log_equals1999=== CONT TestIsValidUploadKey/build_log_question_mark2000=== CONT TestIsValidUploadKey/build_log_plus_in_name2001=== CONT TestIsValidUploadKey/nar_plain2002=== CONT TestIsValidUploadKey/build_log2003=== CONT TestIsValidUploadKey/listing2004=== CONT TestIsValidUploadKey/nar_xz2005=== CONT TestIsValidUploadKey/nar_zst2006--- PASS: TestIsValidUploadKey (0.00s)2007 --- PASS: TestIsValidUploadKey/narinfo (0.00s)2008 --- PASS: TestIsValidUploadKey/realisation_plus_in_output (0.00s)2009 --- PASS: TestIsValidUploadKey/unknown_type (0.00s)2010 --- PASS: TestIsValidUploadKey/empty_key (0.00s)2011 --- PASS: TestIsValidUploadKey/absolute (0.00s)2012 --- PASS: TestIsValidUploadKey/traversal_nar (0.00s)2013 --- PASS: TestIsValidUploadKey/traversal (0.00s)2014 --- PASS: TestIsValidUploadKey/listing_key,_narinfo_type (0.00s)2015 --- PASS: TestIsValidUploadKey/nar_key,_narinfo_type (0.00s)2016 --- PASS: TestIsValidUploadKey/narinfo_key,_nar_type (0.00s)2017 --- PASS: TestIsValidUploadKey/index.html (0.00s)2018 --- PASS: TestIsValidUploadKey/nix-cache-info (0.00s)2019 --- PASS: TestIsValidUploadKey/build_log_home-manager_file (0.00s)2020 --- PASS: TestIsValidUploadKey/realisation (0.00s)2021 --- PASS: TestIsValidUploadKey/build_log_equals (0.00s)2022 --- PASS: TestIsValidUploadKey/build_log_question_mark (0.00s)2023 --- PASS: TestIsValidUploadKey/build_log_plus_in_name (0.00s)2024 --- PASS: TestIsValidUploadKey/nar_plain (0.00s)2025 --- PASS: TestIsValidUploadKey/build_log (0.00s)2026 --- PASS: TestIsValidUploadKey/listing (0.00s)2027 --- PASS: TestIsValidUploadKey/nar_xz (0.00s)2028 --- PASS: TestIsValidUploadKey/nar_zst (0.00s)2029=== CONT TestPendingClosureWriteTimeout/empty2030=== CONT TestPendingClosureWriteTimeout/670k_objects2031=== CONT TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline20322026/11/01 16:14:39 INFO Received push request method=POST path=/api/pushes20332026/11/01 16:14:39 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-config20342026/11/01 16:14:39 WARN Request failed, retrying attempt=2 backoff=208.839457ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config20352026/11/01 16:14:40 INFO Received push request method=POST path=/api/pushes2036--- PASS: TestUploadHandlersRejectOversizedBody (0.06s)2037 --- PASS: TestUploadHandlersRejectOversizedBody/request_more_parts (0.04s)2038 --- PASS: TestUploadHandlersRejectOversizedBody/complete_multipart (0.03s)2039 --- PASS: TestUploadHandlersRejectOversizedBody/create_pending_closure (0.41s)2040=== CONT TestPendingClosureWriteTimeout/400_objects2041=== CONT TestProxyWriteTimeout/narinfo2042=== CONT TestProxyWriteTimeout/10_GiB_nar2043=== CONT TestProxyWriteTimeout/unknown_size2044=== CONT TestProxyWriteTimeout/1_GiB_nar2045--- PASS: TestProxyWriteTimeout (0.00s)2046 --- PASS: TestProxyWriteTimeout/narinfo (0.00s)2047 --- PASS: TestProxyWriteTimeout/10_GiB_nar (0.00s)2048 --- PASS: TestProxyWriteTimeout/unknown_size (0.00s)2049 --- PASS: TestProxyWriteTimeout/1_GiB_nar (0.00s)2050=== CONT TestPush_RejectsBadRequests/no_objects20512026/11/01 16:14:40 INFO Received push request method=POST path=/api/pushes2052=== CONT TestPush_RejectsBadRequests/root_not_in_objects20532026/11/01 16:14:40 INFO Received push request method=POST path=/api/pushes2054=== CONT TestPush_RejectsBadRequests/no_roots20552026/11/01 16:14:40 INFO Received push request method=POST path=/api/pushes2056=== CONT TestPush_RejectsBadRequests/bad_root20572026/11/01 16:14:40 INFO Received push request method=POST path=/api/pushes2058=== CONT TestService_RequireScope_OIDC/builder_may_write2059--- PASS: TestPush_RejectsBadRequests (6.23s)2060 --- PASS: TestPush_RejectsBadRequests/no_objects (0.00s)2061 --- PASS: TestPush_RejectsBadRequests/root_not_in_objects (0.00s)2062 --- PASS: TestPush_RejectsBadRequests/no_roots (0.00s)2063 --- PASS: TestPush_RejectsBadRequests/bad_root (0.00s)2064=== CONT TestService_RequireScope_OIDC/reader_may_read2065=== CONT TestService_RequireScope_OIDC/empty_netrc_password_may_not_read2066=== CONT TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read20672026/11/01 16:14:40 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]2068=== CONT TestService_RequireScope_OIDC/static_token_may_admin_with_netrc2069=== CONT TestService_RequireScope_OIDC/reader_may_read_with_netrc2070=== CONT TestService_RequireScope_OIDC/anonymous_may_not_read2071=== CONT TestService_RequireScope_OIDC/writer_implies_read2072=== CONT TestService_RequireScope_OIDC/reader_may_not_write2073=== CONT TestService_RequireScope_OIDC/static_token_may_write2074=== CONT TestService_RequireScope_OIDC/static_token_may_admin2075=== CONT TestService_RequireScope_OIDC/ops_may_admin20762026/11/01 16:14:40 INFO Received complete multipart upload request method=POST path=/api/multipart/complete2077=== CONT TestService_RequireScope_OIDC/ops_may_not_write2078=== CONT TestService_RequireScope_OIDC/builder_may_not_admin2079--- PASS: TestService_RequireScope_OIDC (6.88s)2080 --- PASS: TestService_RequireScope_OIDC/builder_may_write (0.00s)2081 --- PASS: TestService_RequireScope_OIDC/reader_may_read (0.00s)2082 --- PASS: TestService_RequireScope_OIDC/empty_netrc_password_may_not_read (0.00s)2083 --- PASS: TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read (0.00s)2084 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin_with_netrc (0.00s)2085 --- PASS: TestService_RequireScope_OIDC/reader_may_read_with_netrc (0.00s)2086 --- PASS: TestService_RequireScope_OIDC/anonymous_may_not_read (0.00s)2087 --- PASS: TestService_RequireScope_OIDC/writer_implies_read (0.00s)2088 --- PASS: TestService_RequireScope_OIDC/reader_may_not_write (0.00s)2089 --- PASS: TestService_RequireScope_OIDC/static_token_may_write (0.00s)2090 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin (0.00s)2091 --- PASS: TestService_RequireScope_OIDC/ops_may_admin (0.00s)2092 --- PASS: TestService_RequireScope_OIDC/ops_may_not_write (0.00s)2093 --- PASS: TestService_RequireScope_OIDC/builder_may_not_admin (0.00s)20942026-11-01 16:14:40.142 UTC [95300] ERROR: Push does not exist: id=120952026-11-01 16:14:40.142 UTC [95300] CONTEXT: PL/pgSQL function commit_push(bigint) line 11 at RAISE20962026-11-01 16:14:40.142 UTC [95300] STATEMENT: SELECT commit_push($1)2097--- PASS: TestPush_CompleteWaitsForCleanupOfThePush (7.37s)2098--- PASS: TestPush_OverlappingRootsStoreOneRowPerKey (7.18s)20992026/11/01 16:14:40 WARN Request failed, retrying attempt=3 backoff=392.79228ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21002026/11/01 16:14:40 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=MWZlZGYxYzQtMWFiYy00MTg1LThlNzctYjc2ODFiODQyMzJjLmJjZThiMGUxLWUyYWItNDQyYS05NzFjLTc0Yzc1ODFkZTNkY3gxNzkzNTQ5Njc3NzEyOTY2MDAw parts=1221012026/11/01 16:14:40 INFO Received uploads request method=POST path=/api/pending_closures21022026/11/01 16:14:40 INFO Received uploads request method=POST path=/api/pending_closures21032026/11/01 16:14:40 INFO Received push request method=POST path=/api/pushes21042026/11/01 16:14:40 INFO Received complete push request method=POST path=/api/pushes/1/complete21052026/11/01 16:14:40 WARN Request failed, retrying attempt=4 backoff=727.039512ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21062026/11/01 16:14:40 INFO Completed push id=1 objects=6 duration=37.269708ms2107--- PASS: TestPush_CompleteCommitsEveryRoot (6.88s)2108--- PASS: TestReadRedirectUsesPublicS3URL (6.60s)2109=== RUN TestService_AuthMiddleware_OIDC/valid_OIDC_token2110=== PAUSE TestService_AuthMiddleware_OIDC/valid_OIDC_token2111=== RUN TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected2112=== PAUSE TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected2113=== RUN TestService_AuthMiddleware_OIDC/malformed_token_rejected2114=== PAUSE TestService_AuthMiddleware_OIDC/malformed_token_rejected2115=== RUN TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2116=== PAUSE TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2117=== CONT TestService_AuthMiddleware_OIDC/valid_OIDC_token2118=== CONT TestService_AuthMiddleware_OIDC/malformed_token_rejected21192026/11/01 16:14:41 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]2120=== CONT TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2121=== CONT TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected21222026/11/01 16:14:41 WARN Authentication failed token_preview=eyJhbGciOi...LBh1KdzE6Q token_length=701 oidc_error="no rule matched: claim \"repository_owner\" value [otherorg] not in allowed patterns [myorg]" oidc_provider=test tried_providers=[test]2123--- PASS: TestService_AuthMiddleware_OIDC (6.77s)2124 --- PASS: TestService_AuthMiddleware_OIDC/malformed_token_rejected (0.00s)2125 --- PASS: TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured (0.00s)2126 --- PASS: TestService_AuthMiddleware_OIDC/valid_OIDC_token (0.00s)2127 --- PASS: TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected (0.01s)21282026/11/01 16:14:41 WARN Request failed, retrying attempt=5 backoff=1.62588096s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21292026/11/01 16:14:41 INFO Received uploads request method=POST path=/api/pending_closures21302026/11/01 16:14:41 INFO Aborted multipart uploads count=0 kept=021312026/11/01 16:14:41 WARN Force mode enabled - objects will be deleted immediately without grace period21322026/11/01 16:14:42 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=021332026/11/01 16:14:42 INFO Vacuumed table table=pending_closures21342026/11/01 16:14:42 INFO Vacuumed table table=pending_objects21352026/11/01 16:14:42 INFO Vacuumed table table=multipart_uploads21362026/11/01 16:14:42 INFO Vacuumed table table=closures21372026/11/01 16:14:42 INFO Vacuumed table table=objects21382026/11/01 16:14:44 INFO Aborted multipart uploads count=0 kept=021392026/11/01 16:14:44 WARN Force mode enabled - objects will be deleted immediately without grace period21402026/11/01 16:14:44 INFO Received complete multipart upload request method=POST path=/api/multipart/complete21412026/11/01 16:14:44 WARN Failed to abort redundant multipart upload, keeping its row object_key=nar/gggggggggggggggggggggggggggggg0200000000000000000000.nar.zst upload_id=MWZlZGYxYzQtMWFiYy00MTg1LThlNzctYjc2ODFiODQyMzJjLjA2NzdiOTk2LWRhMGQtNDkwZC05ZDRlLTc3ZDljYTZkZjc4M3gxNzkzNTQ5NjgwMzI1NjMzMDAw error="Get \"http://127.0.0.1:1/bucket81/?location=\": dial tcp 127.0.0.1:1: connect: connection refused"21422026/11/01 16:14:44 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0200000000000000000000.nar.zst upload_id=MWZlZGYxYzQtMWFiYy00MTg1LThlNzctYjc2ODFiODQyMzJjLmY2YzAzODk0LTViOWYtNGZiOC05MzAwLWQ5NGUwMDNmNzk4OXgxNzkzNTQ5NjgwMjc0MDA2MDAw parts=1221432026/11/01 16:14:44 INFO Received cleanup request method=DELETE path=/api/pending_closures21442026/11/01 16:14:44 INFO Aborted multipart uploads count=1 kept=02145--- PASS: TestRedundantMultipartUpload (11.38s)21462026/11/01 16:14:44 INFO Received uploads request method=POST path=/api/pending_closures21472026/11/01 16:14:44 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"21482026/11/01 16:14:44 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-config21492026/11/01 16:14:44 INFO Aborted multipart uploads count=0 kept=021502026/11/01 16:14:44 WARN Force mode enabled - objects will be deleted immediately without grace period21512026/11/01 16:14:45 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=021522026/11/01 16:14:45 INFO Vacuumed table table=pending_closures21532026/11/01 16:14:45 INFO Vacuumed table table=pending_objects21542026/11/01 16:14:45 INFO Vacuumed table table=multipart_uploads21552026/11/01 16:14:45 INFO Vacuumed table table=closures21562026/11/01 16:14:45 INFO Vacuumed table table=objects21572026/11/01 16:14:45 WARN Request failed, retrying attempt=2 backoff=182.066104ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config2158--- PASS: TestForceGCDuringPushOffersSweptObject (0.00s)2159 --- PASS: TestForceGCDuringPushOffersSweptObject/before_pending_rows (7.88s)2160 --- PASS: TestForceGCDuringPushOffersSweptObject/after_presence_check (8.06s)21612026/11/01 16:14:45 INFO Aborted multipart uploads count=0 kept=021622026/11/01 16:14:45 WARN Force mode enabled - objects will be deleted immediately without grace period21632026/11/01 16:14:45 ERROR failed to remove object object=nar/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa.nar.zst error="Post \"http://localhost:58887/bucket95/?delete=\": context canceled"2164--- PASS: TestGCEndsOnShutdown (0.00s)2165 --- PASS: TestGCEndsOnShutdown/before_the_run (7.51s)2166 --- PASS: TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark (7.82s)2167 --- PASS: TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete (7.79s)21682026/11/01 16:14:45 WARN Request failed, retrying attempt=3 backoff=377.118077ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21692026/11/01 16:14:45 WARN Request failed, retrying attempt=4 backoff=774.658131ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config2170--- PASS: TestPresentNotReportedWhileGCDeletesClosure (0.01s)2171 --- PASS: TestPresentNotReportedWhileGCDeletesClosure/stale (8.31s)2172 --- PASS: TestPresentNotReportedWhileGCDeletesClosure/fresh (8.46s)21732026/11/01 16:14:46 INFO Received uploads request method=POST path=/api/pending_closures21742026/11/01 16:14:46 WARN Request failed, retrying attempt=5 backoff=1.712422975s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21752026/11/01 16:14:46 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"21762026/11/01 16:14:46 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"21772026/11/01 16:14:46 INFO Received uploads request method=POST path=/api/pending_closures21782026/11/01 16:14:46 INFO Received uploads request method=POST path=/api/pending_closures21792026/11/01 16:14:47 INFO Received uploads request method=POST path=/api/pending_closures21802026/11/01 16:14:47 INFO Received uploads request method=POST path=/api/pending_closures21812026/11/01 16:14:47 INFO Received complete multipart upload request method=POST path=/api/multipart/complete21822026/11/01 16:14:47 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000100000000000000000000.nar.zst upload_id=MWZlZGYxYzQtMWFiYy00MTg1LThlNzctYjc2ODFiODQyMzJjLjZiOWNmNjQ1LTk0OTMtNDM4My1hNTM4LWMzNDRmMzIxNGIyNXgxNzkzNTQ5Njg2NDE0ODAzMDAw parts=1021832026/11/01 16:14:47 INFO Received uploads request method=POST path=/api/pending_closures21842026/11/01 16:14:47 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete21852026/11/01 16:14:48 INFO Completed upload id=1 objects=3 duration=13.17475ms21862026/11/01 16:14:48 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_closures21872026/11/01 16:14:48 WARN Request failed, retrying attempt=2 backoff=199.582514ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures21882026/11/01 16:14:48 INFO Received complete multipart upload request method=POST path=/api/multipart/complete21892026/11/01 16:14:48 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000500000000000000000000.nar.zst upload_id=MWZlZGYxYzQtMWFiYy00MTg1LThlNzctYjc2ODFiODQyMzJjLjY4MDM2MjM3LWRkNjItNGUxYy05MDAzLTZhNDc0MmEyODJmNHgxNzkzNTQ5Njg2NjUzODEwMDAw parts=102190--- PASS: TestPendingClosureWriteTimeout (0.00s)2191 --- PASS: TestPendingClosureWriteTimeout/empty (0.00s)2192 --- PASS: TestPendingClosureWriteTimeout/670k_objects (0.00s)2193 --- PASS: TestPendingClosureWriteTimeout/400_objects (0.00s)2194 --- PASS: TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline (6.71s)21952026/11/01 16:14:48 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete21962026/11/01 16:14:48 INFO Completed upload id=1 objects=3 duration=11.165083ms21972026/11/01 16:14:48 WARN Request failed, retrying attempt=3 backoff=429.141717ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures21982026/11/01 16:14:48 INFO Received uploads request method=POST path=/api/pending_closures21992026/11/01 16:14:48 INFO Object in database but missing from S3 key=nar/dadb44fdadb44fdadb44fdadb44f000100000000000000000000.nar.zst22002026/11/01 16:14:48 INFO Received complete multipart upload request method=POST path=/api/multipart/complete22012026/11/01 16:14:48 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000400000000000000000000.nar.zst upload_id=MWZlZGYxYzQtMWFiYy00MTg1LThlNzctYjc2ODFiODQyMzJjLjZjZTRhNmU5LTc5NWEtNDk5MS1hODgyLTdhNmI3ZjI3N2RmN3gxNzkzNTQ5Njg2OTMxNDg2MDAw parts=1022022026/11/01 16:14:48 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete22032026/11/01 16:14:48 INFO Completed upload id=1 objects=3 duration=3.757875ms22042026/11/01 16:14:48 INFO Received uploads request method=POST path=/api/pending_closures22052026/11/01 16:14:48 INFO Received uploads request method=POST path=/api/pending_closures22062026/11/01 16:14:48 INFO Object in database but missing from S3 key=nar/dadb44fdadb44fdadb44fdadb44f000500000000000000000000.nar.zst22072026/11/01 16:14:48 WARN Found objects in DB but missing from S3, will re-upload count=122082026/11/01 16:14:48 WARN Request failed, retrying attempt=4 backoff=720.170867ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures22092026/11/01 16:14:48 INFO Received complete multipart upload request method=POST path=/api/multipart/complete22102026/11/01 16:14:48 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000300000000000000000000.nar.zst upload_id=MWZlZGYxYzQtMWFiYy00MTg1LThlNzctYjc2ODFiODQyMzJjLmExZTgxMjhmLTU0NDktNDRjNC1hYzliLTA2YzAyNjdlMjExYXgxNzkzNTQ5Njg3MjY1ODg4MDAw parts=1022112026/11/01 16:14:49 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete22122026/11/01 16:14:49 INFO Completed upload id=1 objects=3 duration=9.62275ms22132026/11/01 16:14:49 INFO Received uploads request method=POST path=/api/pending_closures22142026/11/01 16:14:49 INFO Received complete multipart upload request method=POST path=/api/multipart/complete22152026/11/01 16:14:49 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000200000000000000000000.nar.zst upload_id=MWZlZGYxYzQtMWFiYy00MTg1LThlNzctYjc2ODFiODQyMzJjLjU4NWVlODlhLTA3YWItNDg1ZS05NGE4LTE4MzhjZDkxMGFjOXgxNzkzNTQ5Njg3OTQ4NDMwMDAw parts=1022162026/11/01 16:14:49 WARN Request failed, retrying attempt=5 backoff=1.745945451s error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures22172026/11/01 16:14:49 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete22182026/11/01 16:14:49 INFO Completed upload id=1 objects=3 duration=10.808542ms22192026/11/01 16:14:49 INFO Received uploads request method=POST path=/api/pending_closures22202026/11/01 16:14:49 INFO Received complete multipart upload request method=POST path=/api/multipart/complete22212026/11/01 16:14:50 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f100400000000000000000000.nar.zst upload_id=MWZlZGYxYzQtMWFiYy00MTg1LThlNzctYjc2ODFiODQyMzJjLjIyNTU1YzE2LTQ0ZDctNDY3My1iY2JhLTViM2E1OWMyMWRiYXgxNzkzNTQ5Njg4NjcwOTgzMDAw parts=1022222026/11/01 16:14:50 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete22232026/11/01 16:14:50 INFO Completed upload id=2 objects=3 duration=948.334µs22242026/11/01 16:14:50 INFO Received complete multipart upload request method=POST path=/api/multipart/complete22252026/11/01 16:14:50 INFO Received uploads request method=POST path=/api/pending_closures22262026/11/01 16:14:50 INFO Object in database but missing from S3 key=nar/dadb44fdadb44fdadb44fdadb44f000400000000000000000000.nar.zst22272026/11/01 16:14:50 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f100300000000000000000000.nar.zst upload_id=MWZlZGYxYzQtMWFiYy00MTg1LThlNzctYjc2ODFiODQyMzJjLjFkODI0NjM1LTJlMGEtNDg0Ni1hMjE1LTRiOGQxYTAxNDc0ZngxNzkzNTQ5Njg5MDg1NTczMDAw parts=1022282026/11/01 16:14:50 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete22292026/11/01 16:14:50 INFO Completed upload id=2 objects=3 duration=919.875µs22302026/11/01 16:14:50 INFO Received uploads request method=POST path=/api/pending_closures22312026/11/01 16:14:50 INFO Object in database but missing from S3 key=nar/dadb44fdadb44fdadb44fdadb44f000300000000000000000000.nar.zst2232--- PASS: TestService_verifyS3ReuploadsNarinfoOfLostNAR (0.01s)2233 --- PASS: TestService_verifyS3ReuploadsNarinfoOfLostNAR/lost,_other_NAR (8.83s)2234 --- PASS: TestService_verifyS3ReuploadsNarinfoOfLostNAR/lost,_same_NAR_pushed (8.58s)2235 --- PASS: TestService_verifyS3ReuploadsNarinfoOfLostNAR/intact,_other_NAR (8.40s)2236 --- PASS: TestService_verifyS3ReuploadsNarinfoOfLostNAR/named_one_of_two_lost,_other_pushed (10.13s)2237 --- PASS: TestService_verifyS3ReuploadsNarinfoOfLostNAR/named_one_of_two_lost (9.97s)2238--- PASS: TestClientErrorHandling (0.00s)2239 --- PASS: TestClientErrorHandling/InvalidStorePath (8.04s)2240 --- PASS: TestClientErrorHandling/InvalidAuthToken (7.83s)2241 --- PASS: TestClientErrorHandling/ServerNotAvailable (13.06s)2242=== NAME TestOrphanedObjectsGCStressTest2243 orphaned_objects_gc_test.go:503: Stress test completed successfully:2244 orphaned_objects_gc_test.go:504: - Active objects preserved: 202245 orphaned_objects_gc_test.go:505: - Objects deleted: 2102246 orphaned_objects_gc_test.go:506: - Total GC'd: 2102247--- PASS: TestOrphanedObjectsGCStressTest (32.47s)2248PASS2249{"timestamp":"2026-11-01T16:14:56.205499Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:59443","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(9)"}2250{"timestamp":"2026-11-01T16:14:56.207368Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:59205","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)"}2251{"timestamp":"2026-11-01T16:14:56.207506Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:59280","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(9)"}22522026-11-01 16:14:56.332 UTC [94831] LOG: received smart shutdown request22532026-11-01 16:14:56.333 UTC [94831] LOG: background worker "logical replication launcher" (PID 94841) exited with exit code 122542026-11-01 16:14:56.338 UTC [94836] LOG: shutting down22552026-11-01 16:14:56.338 UTC [94836] LOG: checkpoint starting: shutdown immediate22562026-11-01 16:14:57.951 UTC [94836] LOG: checkpoint complete: wrote 11560 buffers (70.6%), wrote 5 SLRU buffers; 0 WAL file(s) added, 0 removed, 32 recycled; write=0.845 s, sync=0.737 s, total=1.614 s; sync files=35725, longest=0.009 s, average=0.001 s; distance=525349 kB, estimate=525349 kB; lsn=0/21896470, redo lsn=0/2189647022572026-11-01 16:14:57.960 UTC [94831] LOG: database system is shut down2258Running OIDC tests...2259=== RUN TestAudienceForIssuer2260=== PAUSE TestAudienceForIssuer2261=== RUN TestGlobMatch2262=== PAUSE TestGlobMatch2263=== RUN TestValidateToken_ValidToken2264=== PAUSE TestValidateToken_ValidToken2265=== RUN TestValidateToken_WrongAudience2266=== PAUSE TestValidateToken_WrongAudience2267=== RUN TestValidateToken_Expired2268=== PAUSE TestValidateToken_Expired2269=== RUN TestValidateToken_BoundClaimsMismatch2270=== PAUSE TestValidateToken_BoundClaimsMismatch2271=== RUN TestValidateToken_BoundSubjectMismatch2272=== PAUSE TestValidateToken_BoundSubjectMismatch2273=== RUN TestValidateToken_MultipleProviders2274=== PAUSE TestValidateToken_MultipleProviders2275=== RUN TestValidateToken_NoMatchingProvider2276=== PAUSE TestValidateToken_NoMatchingProvider2277=== RUN TestValidateToken_KubernetesServiceAccount2278=== PAUSE TestValidateToken_KubernetesServiceAccount2279=== RUN TestNewValidator_KubernetesRequiresCA2280=== PAUSE TestNewValidator_KubernetesRequiresCA2281=== RUN TestValidateToken_KubernetesIssuerFromOwnToken2282=== PAUSE TestValidateToken_KubernetesIssuerFromOwnToken2283=== RUN TestPins_ReservedForMatchingRule2284=== PAUSE TestPins_ReservedForMatchingRule2285=== RUN TestPins_TopLevelShorthand2286=== PAUSE TestPins_TopLevelShorthand2287=== RUN TestPins_ConfigValidation2288=== PAUSE TestPins_ConfigValidation2289=== RUN TestScopes_LegacyProviderDefaultsToWrite2290=== PAUSE TestScopes_LegacyProviderDefaultsToWrite2291=== RUN TestScopes_Rules2292=== PAUSE TestScopes_Rules2293=== RUN TestScopes_ConfigValidation2294=== PAUSE TestScopes_ConfigValidation2295=== CONT TestAudienceForIssuer2296--- PASS: TestAudienceForIssuer (0.00s)2297=== CONT TestValidateToken_NoMatchingProvider2298=== CONT TestPins_ConfigValidation2299=== CONT TestValidateToken_KubernetesServiceAccount2300=== CONT TestScopes_Rules2301=== CONT TestScopes_ConfigValidation2302=== CONT TestScopes_LegacyProviderDefaultsToWrite2303=== CONT TestPins_ReservedForMatchingRule2304=== CONT TestValidateToken_KubernetesIssuerFromOwnToken2305=== CONT TestValidateToken_Expired2306--- PASS: TestPins_ConfigValidation (0.01s)2307--- PASS: TestScopes_ConfigValidation (0.01s)2308=== CONT TestPins_TopLevelShorthand2309=== CONT TestValidateToken_ValidToken2310=== CONT TestNewValidator_KubernetesRequiresCA2311=== CONT TestGlobMatch2312=== RUN TestGlobMatch/foo_foo2313=== PAUSE TestGlobMatch/foo_foo2314=== RUN TestGlobMatch/foo_bar2315=== PAUSE TestGlobMatch/foo_bar2316=== RUN TestGlobMatch/*_2317=== PAUSE TestGlobMatch/*_2318=== RUN TestGlobMatch/*_anything2319=== PAUSE TestGlobMatch/*_anything2320=== RUN TestGlobMatch/foo*_foo2321=== PAUSE TestGlobMatch/foo*_foo2322=== RUN TestGlobMatch/foo*_foobar2323=== PAUSE TestGlobMatch/foo*_foobar2324=== RUN TestGlobMatch/foo*_bar2325=== PAUSE TestGlobMatch/foo*_bar2326=== RUN TestGlobMatch/*bar_bar2327=== PAUSE TestGlobMatch/*bar_bar2328=== RUN TestGlobMatch/*bar_foobar2329=== PAUSE TestGlobMatch/*bar_foobar2330=== RUN TestGlobMatch/*bar_foo2331=== PAUSE TestGlobMatch/*bar_foo2332=== RUN TestGlobMatch/foo*bar_foobar2333=== PAUSE TestGlobMatch/foo*bar_foobar2334=== RUN TestGlobMatch/foo*bar_foo123bar2335=== PAUSE TestGlobMatch/foo*bar_foo123bar2336=== RUN TestGlobMatch/foo*bar_foobarbaz2337=== PAUSE TestGlobMatch/foo*bar_foobarbaz2338=== RUN TestGlobMatch/*/*_foo/bar2339=== PAUSE TestGlobMatch/*/*_foo/bar2340=== RUN TestGlobMatch/*/*_foo2341=== PAUSE TestGlobMatch/*/*_foo2342=== RUN TestGlobMatch/refs/heads/*_refs/heads/main2343=== PAUSE TestGlobMatch/refs/heads/*_refs/heads/main2344=== RUN TestGlobMatch/refs/heads/*_refs/tags/v1.02345=== PAUSE TestGlobMatch/refs/heads/*_refs/tags/v1.02346=== RUN TestGlobMatch/refs/*/main_refs/heads/main2347=== PAUSE TestGlobMatch/refs/*/main_refs/heads/main2348=== RUN TestGlobMatch/fo?_foo2349=== PAUSE TestGlobMatch/fo?_foo2350=== RUN TestGlobMatch/fo?_fo2351=== PAUSE TestGlobMatch/fo?_fo2352=== RUN TestGlobMatch/fo?_fooo2353=== PAUSE TestGlobMatch/fo?_fooo2354=== RUN TestGlobMatch/?oo_foo2355=== PAUSE TestGlobMatch/?oo_foo2356=== RUN TestGlobMatch/?oo_boo2357=== PAUSE TestGlobMatch/?oo_boo2358=== RUN TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2359=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2360=== RUN TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2361=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2362=== CONT TestGlobMatch/foo_foo2363=== CONT TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2364=== CONT TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2365=== CONT TestGlobMatch/?oo_boo2366=== CONT TestGlobMatch/?oo_foo2367=== CONT TestGlobMatch/fo?_fooo2368=== CONT TestGlobMatch/fo?_fo2369=== CONT TestGlobMatch/fo?_foo2370=== CONT TestGlobMatch/refs/*/main_refs/heads/main2371=== CONT TestGlobMatch/refs/heads/*_refs/tags/v1.02372=== CONT TestGlobMatch/refs/heads/*_refs/heads/main2373=== CONT TestGlobMatch/*/*_foo2374=== CONT TestGlobMatch/*/*_foo/bar2375=== CONT TestGlobMatch/foo*bar_foobarbaz2376=== CONT TestGlobMatch/foo*bar_foo123bar2377=== CONT TestGlobMatch/foo*bar_foobar2378=== CONT TestGlobMatch/*bar_foo2379=== CONT TestGlobMatch/*bar_foobar2380=== CONT TestGlobMatch/*bar_bar2381=== CONT TestGlobMatch/foo*_bar2382=== CONT TestGlobMatch/foo*_foobar2383=== CONT TestGlobMatch/foo*_foo2384=== CONT TestGlobMatch/*_anything2385=== CONT TestGlobMatch/*_2386=== CONT TestGlobMatch/foo_bar2387--- PASS: TestGlobMatch (0.00s)2388 --- PASS: TestGlobMatch/foo_foo (0.00s)2389 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main (0.00s)2390 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main (0.00s)2391 --- PASS: TestGlobMatch/?oo_boo (0.00s)2392 --- PASS: TestGlobMatch/?oo_foo (0.00s)2393 --- PASS: TestGlobMatch/fo?_fooo (0.00s)2394 --- PASS: TestGlobMatch/fo?_fo (0.00s)2395 --- PASS: TestGlobMatch/fo?_foo (0.00s)2396 --- PASS: TestGlobMatch/refs/*/main_refs/heads/main (0.00s)2397 --- PASS: TestGlobMatch/refs/heads/*_refs/tags/v1.0 (0.00s)2398 --- PASS: TestGlobMatch/refs/heads/*_refs/heads/main (0.00s)2399 --- PASS: TestGlobMatch/*/*_foo (0.00s)2400 --- PASS: TestGlobMatch/*/*_foo/bar (0.00s)2401 --- PASS: TestGlobMatch/foo*bar_foobarbaz (0.00s)2402 --- PASS: TestGlobMatch/foo*bar_foo123bar (0.00s)2403 --- PASS: TestGlobMatch/foo*bar_foobar (0.00s)2404 --- PASS: TestGlobMatch/*bar_foo (0.00s)2405 --- PASS: TestGlobMatch/*bar_foobar (0.00s)2406 --- PASS: TestGlobMatch/*bar_bar (0.00s)2407 --- PASS: TestGlobMatch/foo*_bar (0.00s)2408 --- PASS: TestGlobMatch/foo*_foobar (0.00s)2409 --- PASS: TestGlobMatch/foo*_foo (0.00s)2410 --- PASS: TestGlobMatch/*_anything (0.00s)2411 --- PASS: TestGlobMatch/*_ (0.00s)2412 --- PASS: TestGlobMatch/foo_bar (0.00s)2413=== CONT TestValidateToken_WrongAudience2414=== CONT TestValidateToken_BoundSubjectMismatch2415=== CONT TestValidateToken_BoundClaimsMismatch2416=== CONT TestValidateToken_MultipleProviders24172026/11/01 16:14:59 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:59464/oidc24182026/11/01 16:14:59 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:59459/oidc24192026/11/01 16:14:59 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:59460/oidc24202026/11/01 16:14:59 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:59467/oidc2421--- PASS: TestPins_TopLevelShorthand (0.06s)24222026/11/01 16:14:59 INFO OIDC provider initialized name=kubernetes issuer=https://127.0.0.1:5946224232026/11/01 16:14:59 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:59469/oidc2424--- PASS: TestValidateToken_ValidToken (0.06s)2425--- PASS: TestValidateToken_WrongAudience (0.06s)2426--- PASS: TestScopes_Rules (0.08s)2427--- PASS: TestScopes_LegacyProviderDefaultsToWrite (0.08s)2428--- PASS: TestValidateToken_KubernetesServiceAccount (0.08s)24292026/11/01 16:14:59 http: TLS handshake error from 127.0.0.1:59472: read tcp 127.0.0.1:59471->127.0.0.1:59472: use of closed network connection2430--- PASS: TestNewValidator_KubernetesRequiresCA (0.07s)24312026/11/01 16:14:59 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:59473/oidc2432--- PASS: TestValidateToken_Expired (0.08s)24332026/11/01 16:14:59 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:59475/oidc2434--- PASS: TestPins_ReservedForMatchingRule (0.10s)24352026/11/01 16:14:59 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:59477/oidc2436--- PASS: TestValidateToken_BoundClaimsMismatch (0.09s)24372026/11/01 16:14:59 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:59480/oidc2438--- PASS: TestValidateToken_BoundSubjectMismatch (0.09s)24392026/11/01 16:14:59 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:59479/oidc2440--- PASS: TestValidateToken_NoMatchingProvider (0.14s)24412026/11/01 16:14:59 INFO OIDC provider initialized name=kubernetes issuer=https://oidc.eks.invalid/id/ABC1232442--- PASS: TestValidateToken_KubernetesIssuerFromOwnToken (0.16s)24432026/11/01 16:14:59 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:59482/oidc24442026/11/01 16:14:59 INFO OIDC provider initialized name=provider2 issuer=http://127.0.0.1:59487/oidc2445--- PASS: TestValidateToken_MultipleProviders (0.15s)2446PASS2447Running hook tests...2448=== RUN TestSendPathsEmpty2449=== PAUSE TestSendPathsEmpty2450=== RUN TestQueueEnqueueAndFetch2451=== PAUSE TestQueueEnqueueAndFetch2452=== RUN TestQueueDeduplication2453=== PAUSE TestQueueDeduplication2454=== RUN TestQueueRemove2455=== PAUSE TestQueueRemove2456=== RUN TestQueueFetchBatchLimit2457=== PAUSE TestQueueFetchBatchLimit2458=== RUN TestQueueRetryMovesToBack2459=== PAUSE TestQueueRetryMovesToBack2460=== RUN TestQueueFetchRemoveLifecycle2461=== PAUSE TestQueueFetchRemoveLifecycle2462=== RUN TestQueueConcurrentWriters2463=== PAUSE TestQueueConcurrentWriters2464=== RUN TestQueueRemoveLargeClosure2465=== PAUSE TestQueueRemoveLargeClosure2466=== RUN TestServerClientIntegration2467--- PASS: TestServerClientIntegration (0.00s)2468=== RUN TestServerQueueError24692026/11/01 16:15:00 ERROR Failed to queue paths error="permission denied" count=12470--- PASS: TestServerQueueError (0.00s)2471=== RUN TestGetListenerSocketActivation2472 server_test.go:145: systemd socket activation does not exist on darwin2473--- SKIP: TestGetListenerSocketActivation (0.00s)2474=== RUN TestServerStalledClientDoesNotBlockShutdown2475=== PAUSE TestServerStalledClientDoesNotBlockShutdown2476=== RUN TestServerBacksOffOnAcceptErrors2477=== PAUSE TestServerBacksOffOnAcceptErrors2478=== RUN TestDrainIsolatesPoisonPath2479=== PAUSE TestDrainIsolatesPoisonPath2480=== RUN TestRunNotBlockedByPoisonHead2481=== PAUSE TestRunNotBlockedByPoisonHead2482=== RUN TestDrainGivesUpWhenServerDown2483=== PAUSE TestDrainGivesUpWhenServerDown2484=== RUN TestFailedPathPrunedByLaterClosure2485=== PAUSE TestFailedPathPrunedByLaterClosure2486=== RUN TestWorkerUploadsAndRemoves2487=== PAUSE TestWorkerUploadsAndRemoves2488=== RUN TestWorkerSkipsGCdPaths2489=== PAUSE TestWorkerSkipsGCdPaths2490=== RUN TestWorkerPrunesClosureDeps2491=== PAUSE TestWorkerPrunesClosureDeps2492=== RUN TestDrainTimeout2493=== PAUSE TestDrainTimeout2494=== RUN TestWorkerRemoveFailureIsNotProgress2495=== PAUSE TestWorkerRemoveFailureIsNotProgress2496=== RUN TestWorkerKeepsPathItCannotStat2497=== PAUSE TestWorkerKeepsPathItCannotStat2498=== CONT TestSendPathsEmpty2499=== CONT TestWorkerKeepsPathItCannotStat2500--- PASS: TestSendPathsEmpty (0.00s)2501=== CONT TestDrainIsolatesPoisonPath2502=== CONT TestQueueRetryMovesToBack2503=== CONT TestQueueFetchBatchLimit2504=== CONT TestQueueRemove2505=== CONT TestQueueFetchRemoveLifecycle2506=== CONT TestServerBacksOffOnAcceptErrors2507=== CONT TestQueueDeduplication25082026/11/01 16:15:00 ERROR Accept failed error="too many open files"2509=== CONT TestServerStalledClientDoesNotBlockShutdown2510=== CONT TestQueueRemoveLargeClosure2511=== CONT TestQueueEnqueueAndFetch2512=== CONT TestWorkerSkipsGCdPaths2513=== CONT TestQueueConcurrentWriters2514=== CONT TestWorkerRemoveFailureIsNotProgress2515=== CONT TestFailedPathPrunedByLaterClosure2516=== CONT TestDrainTimeout2517=== CONT TestWorkerUploadsAndRemoves2518=== CONT TestWorkerPrunesClosureDeps2519=== CONT TestDrainGivesUpWhenServerDown2520=== CONT TestRunNotBlockedByPoisonHead25212026/11/01 16:15:00 ERROR Accept failed error="too many open files"25222026/11/01 16:15:00 INFO Upload queue status pending=225232026/11/01 16:15:00 INFO Uploading batch count=125242026/11/01 16:15:00 INFO Upload queue status pending=225252026/11/01 16:15:00 INFO Upload queue status pending=225262026/11/01 16:15:00 INFO Uploading batch count=225272026/11/01 16:15:00 INFO Uploading batch count=425282026/11/01 16:15:00 ERROR Upload failed error="upload failed" count=425292026/11/01 16:15:00 INFO Uploading batch count=125302026/11/01 16:15:00 ERROR Upload failed error="upload failed" count=125312026/11/01 16:15:00 WARN Cannot stat store path, will retry later path=/private/var/tb/3/scratch/4a1a633e2471393e/build/TestWorkerKeepsPathItCannotStat2502571233/002/locked/aaa error="stat /private/var/tb/3/scratch/4a1a633e2471393e/build/TestWorkerKeepsPathItCannotStat2502571233/002/locked/aaa: permission denied"25322026/11/01 16:15:00 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/3/scratch/4a1a633e2471393e/build/TestDrainIsolatesPoisonPath1396901769/002/bbb2533--- PASS: TestQueueDeduplication (0.01s)25342026/11/01 16:15:00 INFO Uploading batch count=225352026/11/01 16:15:00 ERROR Upload failed error="upload failed" count=225362026/11/01 16:15:00 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/3/scratch/4a1a633e2471393e/build/TestDrainGivesUpWhenServerDown3767370614/002/a2537--- PASS: TestQueueFetchBatchLimit (0.01s)25382026/11/01 16:15:00 INFO Uploading batch count=125392026/11/01 16:15:00 WARN Store path no longer exists (garbage collected?), removing from queue path=/private/var/tb/3/scratch/4a1a633e2471393e/build/TestWorkerSkipsGCdPaths3625046856/002/nonexistent25402026/11/01 16:15:00 INFO Uploading batch count=225412026/11/01 16:15:00 INFO Uploading batch count=125422026/11/01 16:15:00 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/3/scratch/4a1a633e2471393e/build/TestDrainGivesUpWhenServerDown3767370614/002/b25432026/11/01 16:15:00 WARN Cannot stat store path, will retry later path=/private/var/tb/3/scratch/4a1a633e2471393e/build/TestWorkerKeepsPathItCannotStat2502571233/002/locked/aaa error="stat /private/var/tb/3/scratch/4a1a633e2471393e/build/TestWorkerKeepsPathItCannotStat2502571233/002/locked/aaa: permission denied"2544--- PASS: TestQueueRetryMovesToBack (0.01s)25452026/11/01 16:15:00 INFO Upload queue status pending=325462026/11/01 16:15:00 WARN Cannot stat store path, will retry later path=/private/var/tb/3/scratch/4a1a633e2471393e/build/TestWorkerKeepsPathItCannotStat2502571233/002/locked/aaa error="stat /private/var/tb/3/scratch/4a1a633e2471393e/build/TestWorkerKeepsPathItCannotStat2502571233/002/locked/aaa: permission denied"25472026/11/01 16:15:00 INFO Uploading batch count=125482026/11/01 16:15:00 ERROR Upload failed error="upload failed" count=125492026/11/01 16:15:00 INFO Uploading batch count=125502026/11/01 16:15:00 ERROR Drain finished with paths left in queue remaining=125512026/11/01 16:15:00 INFO Uploading batch count=125522026/11/01 16:15:00 ERROR Upload failed error="upload failed" count=12553--- PASS: TestQueueFetchRemoveLifecycle (0.01s)25542026/11/01 16:15:00 INFO Uploading batch count=125552026/11/01 16:15:00 ERROR Upload failed error="upload failed" count=125562026/11/01 16:15:00 INFO Uploading batch count=225572026/11/01 16:15:00 ERROR Upload failed error="upload failed" count=225582026/11/01 16:15:00 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/3/scratch/4a1a633e2471393e/build/TestDrainGivesUpWhenServerDown3767370614/002/c25592026/11/01 16:15:00 WARN Store path no longer exists (garbage collected?), removing from queue path=/private/var/tb/3/scratch/4a1a633e2471393e/build/TestWorkerRemoveFailureIsNotProgress4143841809/002/nonexistent25602026/11/01 16:15:00 INFO Uploading batch count=125612026/11/01 16:15:00 ERROR Upload failed error="upload failed" count=125622026/11/01 16:15:00 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=12563--- PASS: TestQueueRemove (0.01s)25642026/11/01 16:15:00 WARN Store path no longer exists (garbage collected?), removing from queue path=/private/var/tb/3/scratch/4a1a633e2471393e/build/TestWorkerRemoveFailureIsNotProgress4143841809/002/nonexistent25652026/11/01 16:15:00 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=125662026/11/01 16:15:00 WARN Store path no longer exists (garbage collected?), removing from queue path=/private/var/tb/3/scratch/4a1a633e2471393e/build/TestWorkerRemoveFailureIsNotProgress4143841809/002/nonexistent25672026/11/01 16:15:00 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=125682026/11/01 16:15:00 ERROR Drain finished with paths left in queue remaining=125692026/11/01 16:15:00 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/3/scratch/4a1a633e2471393e/build/TestDrainGivesUpWhenServerDown3767370614/002/d25702026/11/01 16:15:00 ERROR Drain finished with paths left in queue remaining=12571--- PASS: TestWorkerKeepsPathItCannotStat (0.02s)25722026/11/01 16:15:00 INFO Uploading batch count=225732026/11/01 16:15:00 ERROR Upload failed error="upload failed" count=225742026/11/01 16:15:00 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/3/scratch/4a1a633e2471393e/build/TestDrainGivesUpWhenServerDown3767370614/002/e25752026/11/01 16:15:00 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/3/scratch/4a1a633e2471393e/build/TestDrainGivesUpWhenServerDown3767370614/002/f2576--- PASS: TestWorkerRemoveFailureIsNotProgress (0.02s)25772026/11/01 16:15:00 ERROR Drain finished with paths left in queue remaining=102578--- PASS: TestFailedPathPrunedByLaterClosure (0.02s)25792026/11/01 16:15:00 ERROR Accept failed error="too many open files"2580--- PASS: TestQueueEnqueueAndFetch (0.02s)2581--- PASS: TestDrainIsolatesPoisonPath (0.02s)2582--- PASS: TestDrainGivesUpWhenServerDown (0.02s)2583--- PASS: TestWorkerPrunesClosureDeps (0.03s)2584--- PASS: TestWorkerSkipsGCdPaths (0.03s)2585--- PASS: TestWorkerUploadsAndRemoves (0.03s)25862026/11/01 16:15:00 ERROR Accept failed error="too many open files"2587--- PASS: TestQueueRemoveLargeClosure (0.04s)2588--- PASS: TestQueueConcurrentWriters (0.04s)25892026/11/01 16:15:00 ERROR Accept failed error="too many open files"25902026/11/01 16:15:00 ERROR Accept failed error="too many open files"25912026/11/01 16:15:00 ERROR Failed to decode request error="read unix /private/var/tb/3/scratch/4a1a633e2471393e/build/hook1207803271/test.sock->: i/o timeout"25922026/11/01 16:15:00 ERROR Failed to write response error="write unix /private/var/tb/3/scratch/4a1a633e2471393e/build/hook1207803271/test.sock->: i/o timeout"2593--- PASS: TestServerStalledClientDoesNotBlockShutdown (0.20s)25942026/11/01 16:15:00 ERROR Upload failed error="context deadline exceeded" count=225952026/11/01 16:15:00 ERROR Drain finished with paths left in queue remaining=42596--- PASS: TestDrainTimeout (0.21s)25972026/11/01 16:15:00 ERROR Accept failed error="too many open files"25982026/11/01 16:15:00 ERROR Accept failed error="too many open files"2599--- PASS: TestServerBacksOffOnAcceptErrors (0.64s)26002026/11/01 16:15:01 INFO Uploading batch count=126012026/11/01 16:15:01 INFO Uploading batch count=126022026/11/01 16:15:01 INFO Uploading batch count=126032026/11/01 16:15:01 ERROR Upload failed error="upload failed" count=126042026/11/01 16:15:01 INFO Uploading batch count=126052026/11/01 16:15:01 ERROR Upload failed error="upload failed" count=126062026/11/01 16:15:01 INFO Uploading batch count=126072026/11/01 16:15:01 ERROR Upload failed error="upload failed" count=126082026/11/01 16:15:01 INFO Uploading batch count=126092026/11/01 16:15:01 ERROR Upload failed error="upload failed" count=126102026/11/01 16:15:01 ERROR Drain finished with paths left in queue remaining=12611--- PASS: TestRunNotBlockedByPoisonHead (1.04s)2612PASS2613Running signing tests...2614=== RUN TestExternalSigner2615=== PAUSE TestExternalSigner2616=== RUN TestExternalSignerWrongPublicKey2617=== PAUSE TestExternalSignerWrongPublicKey2618=== RUN TestExternalSignerErrors2619=== PAUSE TestExternalSignerErrors2620=== RUN TestExternalSignerRestartsAfterCrash2621=== PAUSE TestExternalSignerRestartsAfterCrash2622=== RUN TestExternalSignerProgramErrorKeepsProcess2623=== PAUSE TestExternalSignerProgramErrorKeepsProcess2624=== RUN TestExternalSignerClose2625=== PAUSE TestExternalSignerClose2626=== RUN TestExternalSignerRejectsInvalidPublicKey2627=== PAUSE TestExternalSignerRejectsInvalidPublicKey2628=== RUN TestExternalSignerCancellation2629=== PAUSE TestExternalSignerCancellation2630=== RUN TestGenerateFingerprint2631=== PAUSE TestGenerateFingerprint2632=== RUN TestParseSigningKey2633=== PAUSE TestParseSigningKey2634=== RUN TestSign2635=== PAUSE TestSign2636=== RUN TestSignBatch2637=== PAUSE TestSignBatch2638=== RUN TestNilKeyPublicKey2639=== PAUSE TestNilKeyPublicKey2640=== RUN TestSignErrors2641=== PAUSE TestSignErrors2642=== CONT TestExternalSigner2643=== CONT TestExternalSignerCancellation2644=== CONT TestSignBatch2645=== CONT TestSignErrors2646=== CONT TestSign2647=== CONT TestNilKeyPublicKey2648=== CONT TestParseSigningKey2649=== CONT TestExternalSignerRestartsAfterCrash2650=== RUN TestParseSigningKey/valid_32-byte_key2651=== PAUSE TestParseSigningKey/valid_32-byte_key2652=== RUN TestParseSigningKey/valid_32-byte_key_with_different_name2653=== PAUSE TestParseSigningKey/valid_32-byte_key_with_different_name2654=== RUN TestParseSigningKey/no_colon2655=== PAUSE TestParseSigningKey/no_colon2656=== RUN TestParseSigningKey/empty_name2657=== PAUSE TestParseSigningKey/empty_name2658=== CONT TestExternalSignerWrongPublicKey2659--- PASS: TestNilKeyPublicKey (0.00s)2660=== RUN TestParseSigningKey/invalid_base642661=== PAUSE TestParseSigningKey/invalid_base642662=== CONT TestGenerateFingerprint2663=== RUN TestParseSigningKey/wrong_length2664=== RUN TestGenerateFingerprint/basic_with_references2665=== CONT TestExternalSignerProgramErrorKeepsProcess2666=== PAUSE TestParseSigningKey/wrong_length2667=== CONT TestParseSigningKey/valid_32-byte_key2668=== CONT TestExternalSignerClose2669=== CONT TestExternalSignerErrors2670=== RUN TestExternalSignerErrors/exit_on_request2671=== PAUSE TestExternalSignerErrors/exit_on_request2672=== RUN TestExternalSignerErrors/wrong_signature_length2673=== CONT TestExternalSignerRejectsInvalidPublicKey2674=== PAUSE TestGenerateFingerprint/basic_with_references2675=== CONT TestParseSigningKey/empty_name2676=== PAUSE TestExternalSignerErrors/wrong_signature_length2677=== CONT TestParseSigningKey/wrong_length2678=== CONT TestParseSigningKey/invalid_base642679=== RUN TestGenerateFingerprint/no_references2680=== CONT TestParseSigningKey/no_colon2681=== PAUSE TestGenerateFingerprint/no_references2682=== CONT TestParseSigningKey/valid_32-byte_key_with_different_name2683=== RUN TestExternalSignerErrors/exit_at_startup2684=== RUN TestGenerateFingerprint/unsorted_references_get_sorted2685=== RUN TestExternalSignerRejectsInvalidPublicKey/#002686=== PAUSE TestExternalSignerRejectsInvalidPublicKey/#002687=== RUN TestExternalSignerRejectsInvalidPublicKey/no-colon2688=== PAUSE TestExternalSignerRejectsInvalidPublicKey/no-colon2689=== PAUSE TestGenerateFingerprint/unsorted_references_get_sorted2690=== PAUSE TestExternalSignerErrors/exit_at_startup2691=== RUN TestGenerateFingerprint/invalid_nar_hash_prefix2692=== PAUSE TestGenerateFingerprint/invalid_nar_hash_prefix2693=== RUN TestGenerateFingerprint/invalid_nar_hash_length2694=== PAUSE TestGenerateFingerprint/invalid_nar_hash_length2695=== RUN TestGenerateFingerprint/invalid_store_path_prefix2696=== PAUSE TestGenerateFingerprint/invalid_store_path_prefix2697=== RUN TestGenerateFingerprint/invalid_reference_prefix2698=== PAUSE TestGenerateFingerprint/invalid_reference_prefix2699=== CONT TestGenerateFingerprint/basic_with_references2700=== RUN TestExternalSignerErrors/wrong_shape2701=== PAUSE TestExternalSignerErrors/wrong_shape2702=== RUN TestExternalSignerErrors/wrong_id2703=== PAUSE TestExternalSignerErrors/wrong_id2704=== RUN TestExternalSignerErrors/wrong_signature_name2705=== PAUSE TestExternalSignerErrors/wrong_signature_name2706=== RUN TestExternalSignerErrors/invalid_JSON2707=== CONT TestGenerateFingerprint/invalid_nar_hash_prefix2708=== PAUSE TestExternalSignerErrors/invalid_JSON2709=== RUN TestExternalSignerErrors/null_signatures2710=== PAUSE TestExternalSignerErrors/null_signatures2711=== RUN TestExternalSignerErrors/program_error2712=== PAUSE TestExternalSignerErrors/program_error2713=== RUN TestExternalSignerErrors/null2714=== PAUSE TestExternalSignerErrors/null2715=== RUN TestExternalSignerErrors/missing_signatures2716=== PAUSE TestExternalSignerErrors/missing_signatures2717=== RUN TestExternalSignerErrors/wrong_signatures_shape2718=== PAUSE TestExternalSignerErrors/wrong_signatures_shape2719=== RUN TestExternalSignerErrors/too_few_signatures2720=== PAUSE TestExternalSignerErrors/too_few_signatures2721=== CONT TestGenerateFingerprint/invalid_reference_prefix2722=== RUN TestSignErrors/nil_key2723=== CONT TestGenerateFingerprint/invalid_store_path_prefix2724=== PAUSE TestSignErrors/nil_key2725=== RUN TestSignErrors/nil_narinfo2726=== PAUSE TestSignErrors/nil_narinfo2727=== RUN TestSignErrors/invalid_narinfo2728=== PAUSE TestSignErrors/invalid_narinfo2729=== RUN TestSignErrors/canceled2730=== PAUSE TestSignErrors/canceled2731=== CONT TestSignErrors/nil_key2732=== CONT TestGenerateFingerprint/no_references2733=== CONT TestSignErrors/canceled2734=== CONT TestSignErrors/invalid_narinfo2735--- PASS: TestSign (0.00s)2736=== CONT TestSignErrors/nil_narinfo2737--- PASS: TestSignErrors (0.00s)2738 --- PASS: TestSignErrors/nil_key (0.00s)2739 --- PASS: TestSignErrors/canceled (0.00s)2740 --- PASS: TestSignErrors/invalid_narinfo (0.00s)2741 --- PASS: TestSignErrors/nil_narinfo (0.00s)2742=== RUN TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2743=== PAUSE TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2744=== CONT TestGenerateFingerprint/invalid_nar_hash_length2745=== CONT TestGenerateFingerprint/unsorted_references_get_sorted2746=== RUN TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2747--- PASS: TestParseSigningKey (0.00s)2748 --- PASS: TestParseSigningKey/empty_name (0.00s)2749 --- PASS: TestParseSigningKey/wrong_length (0.00s)2750 --- PASS: TestParseSigningKey/invalid_base64 (0.00s)2751 --- PASS: TestParseSigningKey/no_colon (0.00s)2752 --- PASS: TestParseSigningKey/valid_32-byte_key (0.00s)2753 --- PASS: TestParseSigningKey/valid_32-byte_key_with_different_name (0.00s)2754=== PAUSE TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2755--- PASS: TestSignBatch (0.00s)2756=== RUN TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2757=== PAUSE TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2758=== CONT TestExternalSignerRejectsInvalidPublicKey/#002759=== CONT TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2760=== CONT TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2761--- PASS: TestGenerateFingerprint (0.00s)2762 --- PASS: TestGenerateFingerprint/basic_with_references (0.00s)2763 --- PASS: TestGenerateFingerprint/invalid_nar_hash_prefix (0.00s)2764 --- PASS: TestGenerateFingerprint/invalid_reference_prefix (0.00s)2765 --- PASS: TestGenerateFingerprint/invalid_store_path_prefix (0.00s)2766 --- PASS: TestGenerateFingerprint/no_references (0.00s)2767 --- PASS: TestGenerateFingerprint/invalid_nar_hash_length (0.00s)2768 --- PASS: TestGenerateFingerprint/unsorted_references_get_sorted (0.00s)2769=== RUN TestExternalSignerErrors/unrequested_key2770=== CONT TestExternalSignerRejectsInvalidPublicKey/no-colon2771=== CONT TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2772=== PAUSE TestExternalSignerErrors/unrequested_key2773--- PASS: TestExternalSignerRejectsInvalidPublicKey (0.00s)2774 --- PASS: TestExternalSignerRejectsInvalidPublicKey/#00 (0.00s)2775 --- PASS: TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA= (0.00s)2776 --- PASS: TestExternalSignerRejectsInvalidPublicKey/test-key:invalid! (0.00s)2777 --- PASS: TestExternalSignerRejectsInvalidPublicKey/no-colon (0.00s)2778 --- PASS: TestExternalSignerRejectsInvalidPublicKey/test-key:YQ== (0.00s)2779=== RUN TestExternalSignerErrors/missing_signature_name2780=== PAUSE TestExternalSignerErrors/missing_signature_name2781=== RUN TestExternalSignerErrors/invalid_signature_base642782=== PAUSE TestExternalSignerErrors/invalid_signature_base642783=== CONT TestExternalSignerErrors/exit_on_request2784=== CONT TestExternalSignerErrors/program_error2785=== CONT TestExternalSignerErrors/too_few_signatures2786=== CONT TestExternalSignerErrors/wrong_signatures_shape2787=== CONT TestExternalSignerErrors/wrong_signature_length2788=== CONT TestExternalSignerErrors/exit_at_startup2789=== CONT TestExternalSignerErrors/invalid_signature_base642790=== CONT TestExternalSignerErrors/missing_signature_name2791=== CONT TestExternalSignerErrors/unrequested_key2792=== CONT TestExternalSignerErrors/invalid_JSON2793=== CONT TestExternalSignerErrors/wrong_signature_name2794=== CONT TestExternalSignerErrors/wrong_id2795=== CONT TestExternalSignerErrors/wrong_shape2796=== CONT TestExternalSignerErrors/missing_signatures2797=== CONT TestExternalSignerErrors/null2798=== CONT TestExternalSignerErrors/null_signatures2799--- PASS: TestExternalSignerWrongPublicKey (0.22s)2800--- PASS: TestExternalSigner (0.42s)2801--- PASS: TestExternalSignerCancellation (0.62s)2802--- PASS: TestExternalSignerRestartsAfterCrash (0.81s)2803/private/var/tb/3/scratch/4a1a633e2471393e/build/TestExternalSignerRestartsAfterCrash1232108755/001/sign program: line 7: /private/var/tb/3/scratch/4a1a633e2471393e/build/TestExternalSignerRestartsAfterCrash1232108755/001/sign program.starts: No such file or directory2804--- PASS: TestExternalSignerClose (2.89s)2805--- PASS: TestExternalSignerProgramErrorKeepsProcess (3.08s)2806--- PASS: TestExternalSignerErrors (0.00s)2807 --- PASS: TestExternalSignerErrors/missing_signature_name (0.97s)2808 --- PASS: TestExternalSignerErrors/wrong_signatures_shape (1.17s)2809 --- PASS: TestExternalSignerErrors/exit_on_request (1.35s)2810 --- PASS: TestExternalSignerErrors/wrong_signature_length (1.55s)2811 --- PASS: TestExternalSignerErrors/program_error (1.74s)2812 --- PASS: TestExternalSignerErrors/unrequested_key (1.93s)2813 --- PASS: TestExternalSignerErrors/wrong_shape (2.12s)2814 --- PASS: TestExternalSignerErrors/invalid_signature_base64 (2.31s)2815 --- PASS: TestExternalSignerErrors/invalid_JSON (2.50s)2816 --- PASS: TestExternalSignerErrors/exit_at_startup (2.70s)2817 --- PASS: TestExternalSignerErrors/null_signatures (3.26s)2818 --- PASS: TestExternalSignerErrors/too_few_signatures (3.45s)2819 --- PASS: TestExternalSignerErrors/null (3.64s)2820 --- PASS: TestExternalSignerErrors/wrong_signature_name (3.83s)2821 --- PASS: TestExternalSignerErrors/missing_signatures (4.02s)2822 --- PASS: TestExternalSignerErrors/wrong_id (4.21s)2823PASS2824Running OpenBao signer tests...2825=== RUN TestSign2826=== PAUSE TestSign2827=== RUN TestSignErrors2828=== PAUSE TestSignErrors2829=== RUN TestServe2830=== PAUSE TestServe2831=== RUN TestServeRejectsGarbage2832=== PAUSE TestServeRejectsGarbage2833=== CONT TestSign2834=== CONT TestServe2835=== CONT TestSignErrors2836=== RUN TestSignErrors/http_error2837=== CONT TestServeRejectsGarbage2838=== PAUSE TestSignErrors/http_error2839--- PASS: TestServeRejectsGarbage (0.00s)2840=== RUN TestSignErrors/invalid_json2841=== PAUSE TestSignErrors/invalid_json2842=== RUN TestSignErrors/no_prefix2843=== PAUSE TestSignErrors/no_prefix2844=== RUN TestSignErrors/invalid_base642845=== PAUSE TestSignErrors/invalid_base642846=== CONT TestSignErrors/http_error2847=== CONT TestSignErrors/no_prefix2848=== CONT TestSignErrors/invalid_base642849--- PASS: TestServe (0.00s)2850=== CONT TestSignErrors/invalid_json2851--- PASS: TestSign (0.00s)2852--- PASS: TestSignErrors (0.00s)2853 --- PASS: TestSignErrors/no_prefix (0.00s)2854 --- PASS: TestSignErrors/invalid_json (0.00s)2855 --- PASS: TestSignErrors/invalid_base64 (0.00s)2856 --- PASS: TestSignErrors/http_error (0.00s)2857PASS