niks3-go-unit-tests
checks.aarch64-darwin.go-unit-tests
· build #430
· 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.05s)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 TestScriptTokenEmptyCommand117=== CONT TestDoWithRetry_BodyReplayedViaGetBody118=== CONT TestClientSignaturesByStorePath119=== CONT TestSetClientTLSErrors120=== CONT TestStreamPushStopsWhenCanceled121=== CONT TestStreamPushReportsSkippedPaths122=== CONT TestSetClientTLS123=== CONT TestStreamPushReportsSignatures124=== CONT TestScriptTokenScriptFails125=== CONT TestStreamPushRequestLine126=== CONT TestScriptTokenBadJSON127=== CONT TestStreamPushGivesUpOnDeadServer128=== CONT TestScriptTokenEmptyToken129=== CONT TestSetClientTLSDoesNotMutateDefaultTransport130=== CONT TestStreamPushIsolatesFailures131=== CONT TestScriptTokenCachesUntilRefresh132=== CONT TestStreamPushBatchesUnderLoad133=== CONT TestScriptTokenNoExpiryRerunsEveryCall134=== CONT TestStreamPushReportsEveryPath135=== CONT TestFileTokenEmpty1362026/10/25 17:18:53 ERROR Upload failed error=boom count=1137=== CONT TestDumpPathWriterError1382026/10/25 17:18:53 ERROR Upload failed error="connection refused" count=201392026/10/25 17:18:53 ERROR Server seems unavailable, giving up on batch untried=17140=== CONT TestShellSplitErrors141=== CONT TestParsePathInfoJSONMultiplePaths142=== CONT TestFileTokenMissing143=== CONT TestShellSplit144=== CONT TestParsePathInfoJSON145=== CONT TestFileTokenReadsAndCaches146=== CONT TestResolveStorePath1472026/10/25 17:18:53 WARN Rate limiter enabled after throttle name=server-test rate=51482026/10/25 17:18:53 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:523601492026/10/25 17:18:53 ERROR Upload failed error="bad path" count=31502026/10/25 17:18:53 ERROR Upload failed error=boom count=1151=== CONT TestDoWithRetry_FinalResponseBodyReadable152=== CONT TestRateLimiterFeedback153=== RUN TestRateLimiterFeedback/429_enables_limiter154=== PAUSE TestRateLimiterFeedback/429_enables_limiter155=== RUN TestRateLimiterFeedback/503_enables_limiter156=== PAUSE TestRateLimiterFeedback/503_enables_limiter157=== RUN TestRateLimiterFeedback/200_does_not_enable_limiter158=== PAUSE TestRateLimiterFeedback/200_does_not_enable_limiter159=== RUN TestRateLimiterFeedback/400_does_not_enable_limiter160=== PAUSE TestRateLimiterFeedback/400_does_not_enable_limiter161=== CONT TestEncodeNixBase32WithRealHash162=== CONT TestPathInfoCACompatibility163=== RUN TestPathInfoCACompatibility/null_ca_field164=== PAUSE TestPathInfoCACompatibility/null_ca_field165=== RUN TestPathInfoCACompatibility/old_string_format_-_text166=== PAUSE TestPathInfoCACompatibility/old_string_format_-_text167=== RUN TestPathInfoCACompatibility/old_string_format_-_fixed_recursive168=== PAUSE TestPathInfoCACompatibility/old_string_format_-_fixed_recursive169=== RUN TestPathInfoCACompatibility/new_structured_format_-_text170=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_text171=== RUN TestPathInfoCACompatibility/new_structured_format_-_nar_method172=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_nar_method173=== CONT TestEncodeNixBase32174=== RUN TestEncodeNixBase32/test_string_hash175=== CONT TestStaticToken176--- PASS: TestScriptTokenEmptyCommand (0.00s)177=== CONT TestRetryTimeoutOutlastsMaxRetries178=== RUN TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths179=== RUN TestSetClientTLS/rejects_connection_without_client_cert180=== CONT TestGetStorePathHash181=== RUN TestParsePathInfoJSON/Nix_format182=== RUN TestSetClientTLSErrors/missing_cert_file183=== CONT TestRateLimiterFeedback_400DoesNotCountAsSuccess184=== CONT TestConvertHashToNix32185=== RUN TestConvertHashToNix32/SRI_format_to_Nix32186=== PAUSE TestConvertHashToNix32/SRI_format_to_Nix32187=== RUN TestConvertHashToNix32/already_Nix32_format188=== PAUSE TestConvertHashToNix32/already_Nix32_format189=== RUN TestConvertHashToNix32/invalid_format190=== PAUSE TestEncodeNixBase32/test_string_hash191=== RUN TestEncodeNixBase32/empty_input192=== PAUSE TestSetClientTLSErrors/missing_cert_file193=== RUN TestSetClientTLSErrors/missing_key_file194=== PAUSE TestSetClientTLSErrors/missing_key_file195=== RUN TestSetClientTLSErrors/missing_ca_file196=== PAUSE TestSetClientTLSErrors/missing_ca_file197=== RUN TestSetClientTLSErrors/invalid_ca_file198=== PAUSE TestSetClientTLS/rejects_connection_without_client_cert199=== CONT TestUploadMultipart_PartsInParallel200=== RUN TestSetClientTLS/succeeds_with_client_cert_and_CA201=== PAUSE TestSetClientTLS/succeeds_with_client_cert_and_CA202=== RUN TestSetClientTLS/preserves_debug_logging_transport203=== PAUSE TestSetClientTLS/preserves_debug_logging_transport204=== CONT TestDumpPathMatchesNix2052026/10/25 17:18:53 WARN Rate limiter backed off name=server-test rate=52062026/10/25 17:18:53 WARN Request returned retryable status, retrying attempt=2 backoff=0s status=503 url=http://127.0.0.1:52360207=== CONT TestSupersededNARStillUploadsListing208=== RUN TestSupersededNARStillUploadsListing/small_NAR209=== PAUSE TestSupersededNARStillUploadsListing/small_NAR210=== RUN TestSupersededNARStillUploadsListing/dump_cut_short211--- PASS: TestClientSignaturesByStorePath (0.00s)212--- PASS: TestStreamPushStopsWhenCanceled (0.00s)213--- PASS: TestStreamPushReportsSkippedPaths (0.00s)214--- PASS: TestStreamPushReportsSignatures (0.00s)215--- PASS: TestShellSplitErrors (0.00s)216--- PASS: TestShellSplit (0.00s)217--- PASS: TestFileTokenMissing (0.00s)218=== PAUSE TestSetClientTLSErrors/invalid_ca_file219=== PAUSE TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths220=== PAUSE TestConvertHashToNix32/invalid_format221=== PAUSE TestEncodeNixBase32/empty_input222=== CONT TestCaseHackSuffix223=== CONT TestRegisterUploadedObject_BoundedAgainstSilentServer224=== RUN TestGetStorePathHash/valid_store_path225=== PAUSE TestParsePathInfoJSON/Nix_format226=== CONT TestDumpPathSingleFile2272026/10/25 17:18:53 WARN Rate limiter enabled after throttle name=server-test rate=5228=== CONT TestPathInfoHashCompatibility229--- PASS: TestFileTokenReadsAndCaches (0.00s)230--- PASS: TestSetClientTLSDoesNotMutateDefaultTransport (0.00s)231--- PASS: TestStreamPushIsolatesFailures (0.00s)232--- PASS: TestStreamPushReportsEveryPath (0.00s)233--- PASS: TestResolveStorePath (0.00s)234--- PASS: TestStreamPushGivesUpOnDeadServer (0.01s)235--- PASS: TestEncodeNixBase32WithRealHash (0.00s)236--- PASS: TestStaticToken (0.00s)237--- PASS: TestScriptTokenScriptFails (0.01s)238=== PAUSE TestSupersededNARStillUploadsListing/dump_cut_short239=== CONT TestRunGarbageCollection_NotFoundAfterLocalRun240--- PASS: TestDoServerRequestAttachesToken (0.01s)241=== CONT TestFilterOversizedClosures242=== RUN TestFilterOversizedClosures/no_limit_keeps_everything243=== PAUSE TestFilterOversizedClosures/no_limit_keeps_everything244=== CONT TestRegisterUploadedObjectReusesConnections245=== RUN TestSupersededNARStillUploadsListing/listing_upload_fails246--- PASS: TestFileTokenEmpty (0.01s)247=== RUN TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped248=== PAUSE TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped249=== RUN TestFilterOversizedClosures/all_closures_skipped250=== PAUSE TestSupersededNARStillUploadsListing/listing_upload_fails251=== PAUSE TestFilterOversizedClosures/all_closures_skipped252=== RUN TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)253=== PAUSE TestGetStorePathHash/valid_store_path254=== RUN TestParsePathInfoJSON/Lix_format255=== CONT TestRunGarbageCollection_FinishedOnAnotherReplica256=== CONT TestUploadBuildLog_FileBodyReplayedOnRetry2572026/10/25 17:18:53 WARN Request returned retryable status, retrying attempt=1 backoff=1ms status=502 url=http://127.0.0.1:523662582026/10/25 17:18:53 WARN Rate limiter enabled after throttle name=server-test rate=52592026/10/25 17:18:53 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:52364260=== RUN TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths261=== PAUSE TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths262--- PASS: TestDoWithRetry_BodyReplayedViaGetBody (0.02s)263=== CONT TestPartSizeForNAR264=== RUN TestPartSizeForNAR/zero_stays_at_minimum265=== CONT TestUploadMultipart_SupersededByPeer266=== RUN TestUploadMultipart_SupersededByPeer/exists267=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)268=== RUN TestPathInfoHashCompatibility/old_string_format_with_colon2692026/10/25 17:18:53 WARN Request returned retryable status, retrying attempt=2 backoff=1ms status=502 url=http://127.0.0.1:52366270--- PASS: TestScriptTokenEmptyToken (0.02s)271=== CONT TestUploadMultipart_FailedPartBufferNotReused2722026/10/25 17:18:53 INFO Garbage collection started273=== RUN TestGetStorePathHash/basename_without_hyphen_should_error274=== PAUSE TestGetStorePathHash/basename_without_hyphen_should_error275=== RUN TestGetStorePathHash/hash_with_invalid_characters_should_error276=== PAUSE TestGetStorePathHash/hash_with_invalid_characters_should_error277=== RUN TestGetStorePathHash/hash_with_wrong_length_should_error278=== PAUSE TestGetStorePathHash/hash_with_wrong_length_should_error279=== CONT TestRateLimiterFeedback/429_enables_limiter280=== PAUSE TestParsePathInfoJSON/Lix_format281=== RUN TestParsePathInfoJSON/empty_input282=== PAUSE TestParsePathInfoJSON/empty_input283=== RUN TestParsePathInfoJSON/whitespace_only284=== PAUSE TestParsePathInfoJSON/whitespace_only285=== RUN TestParsePathInfoJSON/invalid_JSON286=== PAUSE TestParsePathInfoJSON/invalid_JSON287=== CONT TestPathInfoCACompatibility/null_ca_field288=== CONT TestRateLimiterFeedback/400_does_not_enable_limiter289=== PAUSE TestPartSizeForNAR/zero_stays_at_minimum290=== RUN TestPartSizeForNAR/small_stays_at_minimum291=== PAUSE TestPartSizeForNAR/small_stays_at_minimum292=== RUN TestPartSizeForNAR/80_GiB_fits_at_minimum293=== PAUSE TestUploadMultipart_SupersededByPeer/exists294=== PAUSE TestPartSizeForNAR/80_GiB_fits_at_minimum295=== RUN TestPartSizeForNAR/115_GiB_needs_larger_parts296=== PAUSE TestPartSizeForNAR/115_GiB_needs_larger_parts297=== RUN TestPartSizeForNAR/1_TiB298=== PAUSE TestPartSizeForNAR/1_TiB299=== RUN TestPartSizeForNAR/5_TiB_S3_max_object300=== PAUSE TestPartSizeForNAR/5_TiB_S3_max_object301=== RUN TestPartSizeForNAR/capped_at_5_GiB302=== PAUSE TestPartSizeForNAR/capped_at_5_GiB303=== RUN TestUploadMultipart_SupersededByPeer/missing304=== PAUSE TestUploadMultipart_SupersededByPeer/missing305=== CONT TestRateLimiterFeedback/200_does_not_enable_limiter306=== CONT TestRateLimiterFeedback/503_enables_limiter3072026/10/25 17:18:53 WARN Rate limiter backed off name=server-test rate=5308=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_colon309--- PASS: TestDoWithRetry_FinalResponseBodyReadable (0.03s)310=== CONT TestPathInfoCACompatibility/new_structured_format_-_nar_method311=== CONT TestPathInfoCACompatibility/new_structured_format_-_text312=== CONT TestPathInfoCACompatibility/old_string_format_-_fixed_recursive313=== CONT TestPathInfoCACompatibility/old_string_format_-_text314--- PASS: TestPathInfoCACompatibility (0.00s)315 --- PASS: TestPathInfoCACompatibility/null_ca_field (0.00s)316 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_nar_method (0.00s)317 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_text (0.00s)318 --- PASS: TestPathInfoCACompatibility/old_string_format_-_fixed_recursive (0.00s)319 --- PASS: TestPathInfoCACompatibility/old_string_format_-_text (0.00s)320=== RUN TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI321=== PAUSE TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI322=== RUN TestPathInfoHashCompatibility/new_structured_format_with_sha512323=== PAUSE TestPathInfoHashCompatibility/new_structured_format_with_sha512324=== CONT TestSetClientTLS/rejects_connection_without_client_cert325=== CONT TestSetClientTLS/succeeds_with_client_cert_and_CA326--- PASS: TestScriptTokenBadJSON (0.04s)327=== CONT TestSetClientTLS/preserves_debug_logging_transport3282026/10/25 17:18:53 WARN Rate limiter enabled after throttle name=s3-test rate=53292026/10/25 17:18:53 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:524553302026/10/25 17:18:53 WARN Request returned retryable status, retrying attempt=1 backoff=1ms status=502 url=http://127.0.0.1:523663312026/10/25 17:18:53 WARN Rate limiter enabled after throttle name=server-test rate=53322026/10/25 17:18:53 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:524503332026/10/25 17:18:53 WARN Rate limiter backed off name=server-test rate=5334=== CONT TestSetClientTLSErrors/missing_cert_file335=== CONT TestSetClientTLSErrors/invalid_ca_file3362026/10/25 17:18:53 INFO Garbage collection started337--- PASS: TestStreamPushRequestLine (0.06s)338=== CONT TestConvertHashToNix32/SRI_format_to_Nix32339=== CONT TestEncodeNixBase32/test_string_hash340=== CONT TestEncodeNixBase32/empty_input341--- PASS: TestEncodeNixBase32 (0.00s)342 --- PASS: TestEncodeNixBase32/test_string_hash (0.00s)343 --- PASS: TestEncodeNixBase32/empty_input (0.00s)344=== CONT TestConvertHashToNix32/invalid_format345=== CONT TestConvertHashToNix32/already_Nix32_format346--- PASS: TestConvertHashToNix32 (0.00s)347 --- PASS: TestConvertHashToNix32/SRI_format_to_Nix32 (0.00s)348 --- PASS: TestConvertHashToNix32/invalid_format (0.00s)349 --- PASS: TestConvertHashToNix32/already_Nix32_format (0.00s)350=== CONT TestSupersededNARStillUploadsListing/small_NAR351--- PASS: TestRunGarbageCollection_NotFoundAfterLocalRun (0.04s)352=== CONT TestFilterOversizedClosures/no_limit_keeps_everything353=== CONT TestSupersededNARStillUploadsListing/listing_upload_fails354=== CONT TestSetClientTLSErrors/missing_ca_file355=== CONT TestSetClientTLSErrors/missing_key_file356--- PASS: TestUploadBuildLog_FileBodyReplayedOnRetry (0.03s)357=== CONT TestSupersededNARStillUploadsListing/dump_cut_short358=== CONT TestFilterOversizedClosures/all_closures_skipped359=== CONT TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped3602026/10/25 17:18:53 WARN Request returned retryable status, retrying attempt=2 backoff=1ms status=502 url=http://127.0.0.1:523663612026/10/25 17:18:53 WARN Rate limiter enabled after throttle name=server-test rate=53622026/10/25 17:18:53 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=503632026/10/25 17:18:53 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=20003642026/10/25 17:18:53 INFO Uploading abc-hello (1.0GB)3652026/10/25 17:18:53 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=429 url=http://127.0.0.1:52443366=== CONT TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths3672026/10/25 17:18:53 INFO Uploading abc-hello (1.0GB)368=== CONT TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths369--- PASS: TestParsePathInfoJSONMultiplePaths (0.01s)370 --- PASS: TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths (0.00s)371 --- PASS: TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths (0.00s)372=== CONT TestGetStorePathHash/valid_store_path373=== CONT TestGetStorePathHash/hash_with_wrong_length_should_error374=== CONT TestGetStorePathHash/hash_with_invalid_characters_should_error375=== CONT TestGetStorePathHash/basename_without_hyphen_should_error376=== CONT TestParsePathInfoJSON/Nix_format377--- PASS: TestGetStorePathHash (0.02s)378 --- PASS: TestGetStorePathHash/valid_store_path (0.00s)379 --- PASS: TestGetStorePathHash/hash_with_wrong_length_should_error (0.00s)380 --- PASS: TestGetStorePathHash/hash_with_invalid_characters_should_error (0.00s)381 --- PASS: TestGetStorePathHash/basename_without_hyphen_should_error (0.00s)382=== CONT TestParsePathInfoJSON/invalid_JSON383=== CONT TestParsePathInfoJSON/whitespace_only384=== CONT TestParsePathInfoJSON/empty_input385=== CONT TestParsePathInfoJSON/Lix_format386--- PASS: TestParsePathInfoJSON (0.02s)387 --- PASS: TestParsePathInfoJSON/Nix_format (0.00s)388 --- PASS: TestParsePathInfoJSON/invalid_JSON (0.00s)389 --- PASS: TestParsePathInfoJSON/whitespace_only (0.00s)390 --- PASS: TestParsePathInfoJSON/empty_input (0.00s)391 --- PASS: TestParsePathInfoJSON/Lix_format (0.00s)392=== CONT TestPartSizeForNAR/zero_stays_at_minimum393=== CONT TestUploadMultipart_SupersededByPeer/exists3942026/10/25 17:18:53 WARN Rate limiter backed off name=server-test rate=5395=== CONT TestPartSizeForNAR/capped_at_5_GiB396=== CONT TestPartSizeForNAR/5_TiB_S3_max_object397=== CONT TestPartSizeForNAR/1_TiB398=== CONT TestPartSizeForNAR/115_GiB_needs_larger_parts399=== CONT TestPartSizeForNAR/80_GiB_fits_at_minimum400=== CONT TestPartSizeForNAR/small_stays_at_minimum401--- PASS: TestPartSizeForNAR (0.01s)402 --- PASS: TestPartSizeForNAR/zero_stays_at_minimum (0.00s)403 --- PASS: TestPartSizeForNAR/capped_at_5_GiB (0.00s)404 --- PASS: TestPartSizeForNAR/5_TiB_S3_max_object (0.00s)405 --- PASS: TestPartSizeForNAR/1_TiB (0.00s)406 --- PASS: TestPartSizeForNAR/115_GiB_needs_larger_parts (0.00s)407 --- PASS: TestPartSizeForNAR/80_GiB_fits_at_minimum (0.00s)408 --- PASS: TestPartSizeForNAR/small_stays_at_minimum (0.00s)409=== CONT TestUploadMultipart_SupersededByPeer/missing4102026/10/25 17:18:53 WARN Request returned retryable status, retrying attempt=3 backoff=1ms status=502 url=http://127.0.0.1:523664112026/10/25 17:18:53 http: TLS handshake error from 127.0.0.1:52454: remote error: tls: bad certificate412=== CONT TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)413=== CONT TestPathInfoHashCompatibility/new_structured_format_with_sha512414=== CONT TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI415=== CONT TestPathInfoHashCompatibility/old_string_format_with_colon416--- PASS: TestPathInfoHashCompatibility (0.02s)417 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) (0.00s)418 --- PASS: TestPathInfoHashCompatibility/new_structured_format_with_sha512 (0.00s)419 --- PASS: TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI (0.00s)420 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_colon (0.00s)4212026/10/25 17:18:53 WARN Request returned retryable status, retrying attempt=4 backoff=1ms status=502 url=http://127.0.0.1:523664222026/10/25 17:18:53 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=0423--- PASS: TestUploadMultipart_SupersededByPeer (0.01s)424 --- PASS: TestUploadMultipart_SupersededByPeer/exists (0.00s)425 --- PASS: TestUploadMultipart_SupersededByPeer/missing (0.00s)426--- PASS: TestSetClientTLSErrors (0.01s)427 --- PASS: TestSetClientTLSErrors/missing_cert_file (0.00s)428 --- PASS: TestSetClientTLSErrors/missing_key_file (0.00s)429 --- PASS: TestSetClientTLSErrors/missing_ca_file (0.00s)430 --- PASS: TestSetClientTLSErrors/invalid_ca_file (0.01s)431--- PASS: TestSetClientTLS (0.01s)432 --- PASS: TestSetClientTLS/succeeds_with_client_cert_and_CA (0.02s)433 --- PASS: TestSetClientTLS/rejects_connection_without_client_cert (0.03s)434 --- PASS: TestSetClientTLS/preserves_debug_logging_transport (0.03s)4352026/10/25 17:18:53 WARN Garbage collection finished on another replica. Its statistics are not available here436--- PASS: TestRunGarbageCollection_FinishedOnAnotherReplica (0.06s)4372026/10/25 17:18:53 WARN Request returned retryable status, retrying attempt=5 backoff=1ms status=502 url=http://127.0.0.1:52366438--- PASS: TestFilterOversizedClosures (0.00s)439 --- PASS: TestFilterOversizedClosures/no_limit_keeps_everything (0.00s)440 --- PASS: TestFilterOversizedClosures/all_closures_skipped (0.01s)441 --- PASS: TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped (0.01s)4422026/10/25 17:18:53 WARN Request returned retryable status, retrying attempt=6 backoff=1ms status=502 url=http://127.0.0.1:52366443--- PASS: TestRateLimiterFeedback (0.00s)444 --- PASS: TestRateLimiterFeedback/200_does_not_enable_limiter (0.02s)445 --- PASS: TestRateLimiterFeedback/503_enables_limiter (0.03s)446 --- PASS: TestRateLimiterFeedback/429_enables_limiter (0.04s)447 --- PASS: TestRateLimiterFeedback/400_does_not_enable_limiter (0.05s)4482026/10/25 17:18:53 WARN Request returned retryable status, retrying attempt=7 backoff=1ms status=502 url=http://127.0.0.1:523664492026/10/25 17:18:53 WARN Rate limiter enabled after throttle name=s3-test rate=54502026/10/25 17:18:53 WARN Request returned retryable status, retrying attempt=8 backoff=1ms status=502 url=http://127.0.0.1:52366451--- PASS: TestScriptTokenCachesUntilRefresh (0.08s)4522026/10/25 17:18:53 WARN Request returned retryable status, retrying attempt=9 backoff=1ms status=502 url=http://127.0.0.1:523664532026/10/25 17:18:53 WARN Request returned retryable status, retrying attempt=10 backoff=1ms status=502 url=http://127.0.0.1:523664542026/10/25 17:18:53 WARN Request returned retryable status, retrying attempt=11 backoff=1ms status=502 url=http://127.0.0.1:523664552026/10/25 17:18:53 WARN Request returned retryable status, retrying attempt=12 backoff=1ms status=502 url=http://127.0.0.1:52366456--- PASS: TestDumpPathWriterError (0.09s)4572026/10/25 17:18:53 WARN Request returned retryable status, retrying attempt=13 backoff=1ms status=502 url=http://127.0.0.1:523664582026/10/25 17:18:53 WARN Request returned retryable status, retrying attempt=14 backoff=1ms status=502 url=http://127.0.0.1:52366459--- PASS: TestScriptTokenNoExpiryRerunsEveryCall (0.09s)4602026/10/25 17:18:53 WARN Request returned retryable status, retrying attempt=15 backoff=1ms status=502 url=http://127.0.0.1:52366461--- PASS: TestRegisterUploadedObjectReusesConnections (0.09s)4622026/10/25 17:18:53 WARN Request returned retryable status, retrying attempt=16 backoff=1ms status=502 url=http://127.0.0.1:523664632026/10/25 17:18:53 WARN Request returned retryable status, retrying attempt=17 backoff=1ms status=502 url=http://127.0.0.1:52366464--- PASS: TestRetryTimeoutOutlastsMaxRetries (0.09s)465--- PASS: TestStreamPushBatchesUnderLoad (0.10s)466--- PASS: TestCaseHackSuffix (0.16s)4672026/10/25 17:18:54 INFO Uploading abc-hello (1.0GB)468--- PASS: TestDumpPathSingleFile (0.16s)4692026/10/25 17:18:54 WARN Request failed, retrying attempt=1 backoff=100ms error="Put \"http://127.0.0.1:52464/part/2\": uploading part 1: server returned 404: no such upload\n" url=http://127.0.0.1:52464/part/24702026/10/25 17:18:54 WARN Request failed, retrying attempt=1 backoff=100ms error="Put \"http://127.0.0.1:52464/part/3\": uploading part 1: server returned 404: no such upload\n" url=http://127.0.0.1:52464/part/34712026/10/25 17:18:54 ERROR Failed to close zstd encoder error="io: read/write on closed pipe"472--- PASS: TestDumpPathMatchesNix (0.19s)473--- PASS: TestUploadMultipart_FailedPartBufferNotReused (0.61s)474--- PASS: TestUploadMultipart_PartsInParallel (0.62s)475--- PASS: TestSupersededNARStillUploadsListing (0.00s)476 --- PASS: TestSupersededNARStillUploadsListing/small_NAR (0.01s)477 --- PASS: TestSupersededNARStillUploadsListing/listing_upload_fails (0.01s)478 --- PASS: TestSupersededNARStillUploadsListing/dump_cut_short (0.61s)479--- PASS: TestRateLimiterFeedback_400DoesNotCountAsSuccess (1.00s)4802026/10/25 17:18:54 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:52370/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:52370/api/uploads/complete4812026/10/25 17:18:54 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"4822026/10/25 17:18:54 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:52370/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:52370/api/uploads/complete4832026/10/25 17:18:54 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"4842026/10/25 17:18:54 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:52370/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:52370/api/uploads/complete4852026/10/25 17:18:54 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"486--- PASS: TestRegisterUploadedObject_BoundedAgainstSilentServer (1.01s)487PASS488Running server tests...489The files belonging to this database system will be owned by user "_tribuchetbld1".490This user must also own the server process.491492The database cluster will be initialized with locale "C".493The default database encoding has accordingly been set to "SQL_ASCII".494The default text search configuration will be set to "english".495496Data page checksums are enabled.497498creating directory /private/var/tb/1/scratch/9b0bff5f52e90cd9/build/postgres3380639979/data ... ok499creating subdirectories ... ok500selecting dynamic shared memory implementation ... posix501selecting default "max_connections" ... 100502selecting default "shared_buffers" ... 128MB503selecting default time zone ... UTC504creating configuration files ... ok505running bootstrap script ... ok506performing post-bootstrap initialization ... ok507syncing data to disk ... ok508509initdb: warning: enabling "trust" authentication for local connections510initdb: 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.511512Success. You can now start the database server using:513514 pg_ctl -D /private/var/tb/1/scratch/9b0bff5f52e90cd9/build/postgres3380639979/data -l logfile start515516/private/var/tb/1/scratch/9b0bff5f52e90cd9/build/postgres3380639979:5432 - no response5172026-10-25 17:18:55.962 UTC [47310] LOG: starting PostgreSQL 18.6 on aarch64-apple-darwin25.6.0, compiled by clang version 21.1.8, 64-bit5182026-10-25 17:18:55.962 UTC [47310] LOG: listening on Unix socket "/private/var/tb/1/scratch/9b0bff5f52e90cd9/build/postgres3380639979/.s.PGSQL.5432"5192026-10-25 17:18:55.977 UTC [47317] LOG: database system was shut down at 2026-10-25 17:18:55 UTC5202026-10-25 17:18:55.979 UTC [47310] LOG: database system is ready to accept connections521/private/var/tb/1/scratch/9b0bff5f52e90cd9/build/postgres3380639979:5432 - accepting connections522{"timestamp":"2026-10-25T17:18:56.188955Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"2388c8d6-f614-424b-b5ed-b6662a7597a6","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(5)"}523=== RUN TestService_AuthMiddleware524=== PAUSE TestService_AuthMiddleware525=== RUN TestService_AuthMiddleware_MTLSProxyHeader526=== PAUSE TestService_AuthMiddleware_MTLSProxyHeader527=== RUN TestService_AuthMiddleware_MTLSBoundSubjects528=== PAUSE TestService_AuthMiddleware_MTLSBoundSubjects529=== RUN TestService_ReadAuthMiddleware530=== PAUSE TestService_ReadAuthMiddleware531=== RUN TestService_AuthMiddleware_OIDC532=== PAUSE TestService_AuthMiddleware_OIDC533=== RUN TestService_RequireScope_OIDC534=== PAUSE TestService_RequireScope_OIDC535=== RUN TestService_ReadScope_PublicByDefault536=== PAUSE TestService_ReadScope_PublicByDefault537=== RUN TestCacheConfigHandler538=== PAUSE TestCacheConfigHandler539=== RUN TestCacheStatsHandler540=== PAUSE TestCacheStatsHandler541=== RUN TestClientCADerivations542=== PAUSE TestClientCADerivations543=== RUN TestClientErrorHandling544=== PAUSE TestClientErrorHandling545=== RUN TestClientIntegration546=== PAUSE TestClientIntegration547=== RUN TestClientMultipleUploads548=== PAUSE TestClientMultipleUploads549=== RUN TestClientWithDependencies550=== PAUSE TestClientWithDependencies551=== RUN TestClientSharedPathCommittedMidPush552=== PAUSE TestClientSharedPathCommittedMidPush553=== RUN TestPinProtectsFromGC554=== PAUSE TestPinProtectsFromGC555=== RUN TestClientPushesUseOnePush556=== PAUSE TestClientPushesUseOnePush557=== RUN TestClientFallsBackToClosures558=== PAUSE TestClientFallsBackToClosures559=== RUN TestDeleteClosuresRacingPins560=== PAUSE TestDeleteClosuresRacingPins561=== RUN TestConcurrentCommitsSharingObjectsDoNotDeadlock562=== PAUSE TestConcurrentCommitsSharingObjectsDoNotDeadlock563=== RUN TestResolveDBConnectionString564=== PAUSE TestResolveDBConnectionString565=== RUN TestConnectWaitsForAPeerMigration566=== PAUSE TestConnectWaitsForAPeerMigration567=== RUN TestLeadElectsOneAndHandsOver568=== PAUSE TestLeadElectsOneAndHandsOver569=== RUN TestLeadIncumbentWinsAfterRestart5702026/10/25 17:18:56 INFO lead: acquired remote=192.0.2.1:12345712026/10/25 17:18:57 INFO lead: released remote=192.0.2.1:12345722026/10/25 17:18:57 INFO lead: acquired remote=192.0.2.1:12345732026/10/25 17:18:58 INFO lead: released remote=192.0.2.1:1234574--- PASS: TestLeadIncumbentWinsAfterRestart (2.02s)575=== RUN TestLeadIncumbentAnnouncesAtOnce576=== PAUSE TestLeadIncumbentAnnouncesAtOnce577=== RUN TestLeadEndsOnShutdown578=== PAUSE TestLeadEndsOnShutdown579=== RUN TestLeadEndsWhenItsConnectionHangs5802026/10/25 17:18:58 INFO lead: acquired remote=192.0.2.1:12345812026-10-25 17:18:59.899 UTC [47368] FATAL: terminating connection due to administrator command5822026/10/25 17:19:00 INFO lead: acquired remote=192.0.2.1:12345832026/10/25 17:19:01 WARN lead: lock connection lost error="timeout: context deadline exceeded"5842026/10/25 17:19:01 INFO lead: released remote=192.0.2.1:12345852026/10/25 17:19:01 INFO lead: released remote=192.0.2.1:1234586--- PASS: TestLeadEndsWhenItsConnectionHangs (2.98s)587=== RUN TestGCAdvisoryLockBlocksConcurrentRun588=== PAUSE TestGCAdvisoryLockBlocksConcurrentRun589=== RUN TestGCBugBareHashReferences590=== PAUSE TestGCBugBareHashReferences591=== RUN TestGCMetrics592=== PAUSE TestGCMetrics593=== RUN TestPushDedupSurvivesConcurrentGC594=== PAUSE TestPushDedupSurvivesConcurrentGC595=== RUN TestDeduplicatedObjectsRecordedAsPending596=== PAUSE TestDeduplicatedObjectsRecordedAsPending597=== RUN TestGCSweepSkipsPendingObjects598=== PAUSE TestGCSweepSkipsPendingObjects599=== RUN TestTombstonedObjectOfferedWithoutWaiting600=== PAUSE TestTombstonedObjectOfferedWithoutWaiting601=== RUN TestGCSweepDeliversEachKeyOnce602=== PAUSE TestGCSweepDeliversEachKeyOnce603=== RUN TestCreatePendingClosureVerifyS3FailureReleasesConnection604=== PAUSE TestCreatePendingClosureVerifyS3FailureReleasesConnection605=== RUN TestForceGCDuringPushOffersSweptObject606=== PAUSE TestForceGCDuringPushOffersSweptObject607=== RUN TestFailedS3DeleteKeepsTombstone608=== PAUSE TestFailedS3DeleteKeepsTombstone609=== RUN TestSweepSkipsRowsLockedByPush610=== PAUSE TestSweepSkipsRowsLockedByPush611=== RUN TestRegisterCompletedObjectNeedsPendingRow612=== PAUSE TestRegisterCompletedObjectNeedsPendingRow613=== RUN TestGetExistingObjectsLocksRows614=== PAUSE TestGetExistingObjectsLocksRows615=== RUN TestSweepRechecksPendingAfterLocking616=== PAUSE TestSweepRechecksPendingAfterLocking617=== RUN TestPushWaitsForSweepHoldingRow618=== PAUSE TestPushWaitsForSweepHoldingRow619=== RUN TestCommitRacingPendingCleanupKeepsObjects620=== PAUSE TestCommitRacingPendingCleanupKeepsObjects621=== RUN TestGCEndsOnShutdown622=== PAUSE TestGCEndsOnShutdown623=== RUN TestGCTaskStore_StartNew624=== PAUSE TestGCTaskStore_StartNew625=== RUN TestGCTaskStore_DeduplicateSameParams626=== PAUSE TestGCTaskStore_DeduplicateSameParams627=== RUN TestGCTaskStore_ConflictDifferentParams628=== PAUSE TestGCTaskStore_ConflictDifferentParams629=== RUN TestGCTaskStore_GetEmpty630=== PAUSE TestGCTaskStore_GetEmpty631=== RUN TestGCTaskStore_GetReturnsLatest632=== PAUSE TestGCTaskStore_GetReturnsLatest633=== RUN TestGCTaskStore_CompletedAllowsNewTask634=== PAUSE TestGCTaskStore_CompletedAllowsNewTask635=== RUN TestGCTaskStore_PhaseUpdates636=== PAUSE TestGCTaskStore_PhaseUpdates637=== RUN TestGCTaskStore_Fail638=== PAUSE TestGCTaskStore_Fail639=== RUN TestGracefulShutdownDrainsInflight640=== PAUSE TestGracefulShutdownDrainsInflight641=== RUN TestService_healthCheckHandler642=== PAUSE TestService_healthCheckHandler643=== RUN TestService_readinessHandler644=== PAUSE TestService_readinessHandler645=== RUN TestGenerateLandingPage646=== PAUSE TestGenerateLandingPage647=== RUN TestCacheConfigHandlerMaxNarSize648=== PAUSE TestCacheConfigHandlerMaxNarSize649=== RUN TestCreatePendingClosureRejectsOversizedNAR650=== PAUSE TestCreatePendingClosureRejectsOversizedNAR651=== RUN TestNARDeduplicationMetadataUploadBug652=== PAUSE TestNARDeduplicationMetadataUploadBug653=== RUN TestMetricsInventory654=== PAUSE TestMetricsInventory655=== RUN TestMetricsCommit656=== PAUSE TestMetricsCommit657=== RUN TestService_NativeMTLS658=== PAUSE TestService_NativeMTLS659=== RUN TestServerTLSConfig660=== PAUSE TestServerTLSConfig661=== RUN TestMultipartCleanup662=== PAUSE TestMultipartCleanup663=== RUN TestMultipartUploadAbortedWhenCancelledBeforeRecorded664=== PAUSE TestMultipartUploadAbortedWhenCancelledBeforeRecorded665=== RUN TestPendingCleanupUsesOneCutoff666=== PAUSE TestPendingCleanupUsesOneCutoff667=== RUN TestObjectStatsTrigger668=== PAUSE TestObjectStatsTrigger669=== RUN TestObjectStatsUpdatedOncePerCommit670=== PAUSE TestObjectStatsUpdatedOncePerCommit671=== RUN TestOrphanedObjectsGC672=== PAUSE TestOrphanedObjectsGC673=== RUN TestOrphanedObjectsGCStressTest674=== PAUSE TestOrphanedObjectsGCStressTest675=== RUN TestCreatePin_ReservedPins676=== PAUSE TestCreatePin_ReservedPins677=== RUN TestPresentReportsOnlyClosureRoots678=== PAUSE TestPresentReportsOnlyClosureRoots679=== RUN TestPresentRefreshesOnlyStaleClosures680=== PAUSE TestPresentRefreshesOnlyStaleClosures681=== RUN TestPresentNotReportedWhileGCDeletesClosure682=== PAUSE TestPresentNotReportedWhileGCDeletesClosure683=== RUN TestParseSingleRange684=== PAUSE TestParseSingleRange685=== RUN TestProxyHeadersOnlyTrustedOnSocket6862026/10/25 17:19:01 INFO Starting HTTP server address=proxy.sock6872026/10/25 17:19:01 INFO Starting HTTP server address=127.0.0.1:525006882026/10/25 17:19:01 WARN mTLS auth: subject not in bound subjects subject="CN=someone"6892026/10/25 17:19:01 INFO Shutdown signal received, draining in-flight requests timeout=10s690--- PASS: TestProxyHeadersOnlyTrustedOnSocket (0.19s)691=== RUN TestIsValidCachePath692=== PAUSE TestIsValidCachePath693=== RUN TestReadProxyNarinfo694=== PAUSE TestReadProxyNarinfo695=== RUN TestReadProxyNarinfoAlreadyDecompressed696=== PAUSE TestReadProxyNarinfoAlreadyDecompressed697=== RUN TestReadProxyContentNegotiation698=== PAUSE TestReadProxyContentNegotiation699=== RUN TestReadProxyNarStreaming700=== PAUSE TestReadProxyNarStreaming701=== RUN TestReadProxy404702=== PAUSE TestReadProxy404703=== RUN TestReadProxyInvalidPath704=== PAUSE TestReadProxyInvalidPath705=== RUN TestReadProxyHead706=== PAUSE TestReadProxyHead707=== RUN TestReadProxyOutlastsServerWriteTimeout708=== PAUSE TestReadProxyOutlastsServerWriteTimeout709=== RUN TestReadProxyConditionalGet710=== PAUSE TestReadProxyConditionalGet711=== RUN TestReadProxyRootRedirectsToIndexHTML712=== PAUSE TestReadProxyRootRedirectsToIndexHTML713=== RUN TestReadProxyDisabled714=== PAUSE TestReadProxyDisabled715=== RUN TestReadRedirectNar716=== PAUSE TestReadRedirectNar717=== RUN TestReadRedirectKeepsNarinfoProxied718=== PAUSE TestReadRedirectKeepsNarinfoProxied719=== RUN TestReadProxyRangeRequest720=== PAUSE TestReadProxyRangeRequest721=== RUN TestReadRedirectUsesPublicS3URL722=== PAUSE TestReadRedirectUsesPublicS3URL723=== RUN TestPush_OverlappingRootsStoreOneRowPerKey724=== PAUSE TestPush_OverlappingRootsStoreOneRowPerKey725=== RUN TestPush_CompleteCommitsEveryRoot726=== PAUSE TestPush_CompleteCommitsEveryRoot727=== RUN TestPush_RepeatedRootCommitsOnce728=== PAUSE TestPush_RepeatedRootCommitsOnce729=== RUN TestPush_CompleteWaitsForCleanupOfThePush730=== PAUSE TestPush_CompleteWaitsForCleanupOfThePush731=== RUN TestPush_RootsAreLockedInByteOrder732=== PAUSE TestPush_RootsAreLockedInByteOrder733=== RUN TestPush_SkippedKeySurvivesGCBeforeCommit734=== PAUSE TestPush_SkippedKeySurvivesGCBeforeCommit735=== RUN TestPush_RejectsBadRequests736=== PAUSE TestPush_RejectsBadRequests737=== RUN TestPush_SignsNarinfosOfItsPendingObjects738=== PAUSE TestPush_SignsNarinfosOfItsPendingObjects739=== RUN TestRedundantMultipartUpload740=== PAUSE TestRedundantMultipartUpload741=== RUN TestCompleteMultipartUpload_ErrorButObjectExists742=== PAUSE TestCompleteMultipartUpload_ErrorButObjectExists743=== RUN TestCompletedNarNotReofferedAcrossClosures744=== PAUSE TestCompletedNarNotReofferedAcrossClosures745=== RUN TestPresignedUploadRegisteredBeforeCommit746=== PAUSE TestPresignedUploadRegisteredBeforeCommit747=== RUN TestService_Rustfstest748=== PAUSE TestService_Rustfstest749=== RUN TestParseSize750=== PAUSE TestParseSize751=== RUN TestSkippedUploadsHandler752=== PAUSE TestSkippedUploadsHandler753=== RUN TestSystemdListenerNotActivated754--- PASS: TestSystemdListenerNotActivated (0.00s)755=== RUN TestWatchdogBeatsWhenHealthy756--- PASS: TestWatchdogBeatsWhenHealthy (0.03s)757=== RUN TestWatchdogSkipsWhenUnhealthy7582026/10/25 17:19:01 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7592026/10/25 17:19:01 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7602026/10/25 17:19:01 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7612026/10/25 17:19:01 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7622026/10/25 17:19:01 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7632026/10/25 17:19:01 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7642026/10/25 17:19:01 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7652026/10/25 17:19:01 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7662026/10/25 17:19:01 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7672026/10/25 17:19:01 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"768--- PASS: TestWatchdogSkipsWhenUnhealthy (0.20s)769=== RUN TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle770=== PAUSE TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle771=== RUN TestProxyWriteTimeout772=== PAUSE TestProxyWriteTimeout773=== RUN TestPendingClosureWriteTimeout774=== PAUSE TestPendingClosureWriteTimeout775=== RUN TestIsValidUploadKey776=== PAUSE TestIsValidUploadKey777=== RUN TestUploadHandlersRejectInvalidKeys778=== PAUSE TestUploadHandlersRejectInvalidKeys779=== RUN TestUploadHandlersRejectOversizedBody780=== PAUSE TestUploadHandlersRejectOversizedBody781=== RUN TestService_cleanupPendingClosuresHandler782=== PAUSE TestService_cleanupPendingClosuresHandler783=== RUN TestService_createPendingClosureHandler784=== PAUSE TestService_createPendingClosureHandler785=== RUN TestService_verifyS3Integrity786=== PAUSE TestService_verifyS3Integrity787=== RUN TestCompleteMultipartUnregistered788=== PAUSE TestCompleteMultipartUnregistered789=== RUN TestCreatePendingClosure_SmallNARUsesSimplePUT790=== PAUSE TestCreatePendingClosure_SmallNARUsesSimplePUT791=== CONT TestService_AuthMiddleware792=== CONT TestObjectStatsTrigger793=== CONT TestMultipartCleanup794=== CONT TestCreatePendingClosureVerifyS3FailureReleasesConnection795=== CONT TestCommitRacingPendingCleanupKeepsObjects796=== CONT TestGCTaskStore_CompletedAllowsNewTask797--- PASS: TestGCTaskStore_CompletedAllowsNewTask (0.00s)798=== CONT TestCacheConfigHandlerMaxNarSize799=== CONT TestGCTaskStore_GetReturnsLatest800--- PASS: TestGCTaskStore_GetReturnsLatest (0.00s)801=== CONT TestMetricsInventory802=== CONT TestGCTaskStore_PhaseUpdates803--- PASS: TestGCTaskStore_PhaseUpdates (0.00s)804=== CONT TestNARDeduplicationMetadataUploadBug805=== CONT TestPendingCleanupUsesOneCutoff806=== CONT TestGCTaskStore_GetEmpty807--- PASS: TestGCTaskStore_GetEmpty (0.00s)808=== CONT TestMultipartUploadAbortedWhenCancelledBeforeRecorded809=== CONT TestGCTaskStore_ConflictDifferentParams810=== CONT TestGCTaskStore_DeduplicateSameParams811=== CONT TestCompleteMultipartUnregistered812=== CONT TestGCTaskStore_StartNew813=== CONT TestService_verifyS3Integrity814=== CONT TestGCEndsOnShutdown815=== RUN TestGCEndsOnShutdown/before_the_run816=== CONT TestPushWaitsForSweepHoldingRow817=== CONT TestSweepRechecksPendingAfterLocking818=== CONT TestGetExistingObjectsLocksRows819=== CONT TestRegisterCompletedObjectNeedsPendingRow820=== CONT TestSweepSkipsRowsLockedByPush821=== CONT TestFailedS3DeleteKeepsTombstone822=== CONT TestForceGCDuringPushOffersSweptObject823=== RUN TestForceGCDuringPushOffersSweptObject/before_pending_rows824=== CONT TestService_readinessHandler825=== PAUSE TestForceGCDuringPushOffersSweptObject/before_pending_rows826=== RUN TestForceGCDuringPushOffersSweptObject/after_presence_check827=== CONT TestCreatePendingClosureRejectsOversizedNAR828=== PAUSE TestForceGCDuringPushOffersSweptObject/after_presence_check829=== CONT TestServerTLSConfig830=== RUN TestServerTLSConfig/no_client_CA831=== CONT TestPush_CompleteCommitsEveryRoot832=== PAUSE TestServerTLSConfig/no_client_CA833=== RUN TestServerTLSConfig/missing_CA_file834=== CONT TestCreatePendingClosure_SmallNARUsesSimplePUT835=== CONT TestMetricsCommit836=== PAUSE TestGCEndsOnShutdown/before_the_run837--- PASS: TestCacheConfigHandlerMaxNarSize (0.00s)838=== PAUSE TestServerTLSConfig/missing_CA_file8392026/10/25 17:19:01 INFO Received uploads request method=POST path=/api/pending_closures840=== RUN TestServerTLSConfig/not_a_PEM_file841--- PASS: TestGCTaskStore_ConflictDifferentParams (0.00s)842--- PASS: TestGCTaskStore_DeduplicateSameParams (0.00s)843=== PAUSE TestServerTLSConfig/not_a_PEM_file844=== RUN TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete845--- PASS: TestGCTaskStore_StartNew (0.00s)846=== CONT TestService_createPendingClosureHandler847--- PASS: TestCreatePendingClosureRejectsOversizedNAR (0.00s)848=== CONT TestService_cleanupPendingClosuresHandler849=== PAUSE TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete850=== RUN TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark851=== PAUSE TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark852=== CONT TestService_NativeMTLS8532026/10/25 17:19:02 INFO Received complete multipart upload request method=POST path=/api/multipart/complete8542026/10/25 17:19:02 ERROR Failed to get multipart upload error="no rows in result set" upload_id=does-not-exist object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst855--- PASS: TestCompleteMultipartUnregistered (0.89s)856=== CONT TestUploadHandlersRejectOversizedBody857=== RUN TestUploadHandlersRejectOversizedBody/create_pending_closure858=== PAUSE TestUploadHandlersRejectOversizedBody/create_pending_closure859=== RUN TestUploadHandlersRejectOversizedBody/complete_multipart860=== PAUSE TestUploadHandlersRejectOversizedBody/complete_multipart861=== RUN TestUploadHandlersRejectOversizedBody/request_more_parts862=== PAUSE TestUploadHandlersRejectOversizedBody/request_more_parts863=== CONT TestUploadHandlersRejectInvalidKeys864=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info865=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info866=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal867=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal868=== RUN TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key869=== PAUSE TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key870=== RUN TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key871=== PAUSE TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key872=== CONT TestIsValidUploadKey873=== RUN TestIsValidUploadKey/narinfo874=== PAUSE TestIsValidUploadKey/narinfo875=== RUN TestIsValidUploadKey/nar_zst876=== PAUSE TestIsValidUploadKey/nar_zst877=== RUN TestIsValidUploadKey/nar_xz878=== PAUSE TestIsValidUploadKey/nar_xz879=== RUN TestIsValidUploadKey/nar_plain880=== PAUSE TestIsValidUploadKey/nar_plain881=== RUN TestIsValidUploadKey/listing882=== PAUSE TestIsValidUploadKey/listing883=== RUN TestIsValidUploadKey/build_log884=== PAUSE TestIsValidUploadKey/build_log885=== RUN TestIsValidUploadKey/build_log_home-manager_file886=== PAUSE TestIsValidUploadKey/build_log_home-manager_file887=== RUN TestIsValidUploadKey/build_log_plus_in_name888=== PAUSE TestIsValidUploadKey/build_log_plus_in_name889=== RUN TestIsValidUploadKey/build_log_question_mark890=== PAUSE TestIsValidUploadKey/build_log_question_mark891=== RUN TestIsValidUploadKey/build_log_equals892=== PAUSE TestIsValidUploadKey/build_log_equals893=== RUN TestIsValidUploadKey/realisation894=== PAUSE TestIsValidUploadKey/realisation895=== RUN TestIsValidUploadKey/realisation_plus_in_output896=== PAUSE TestIsValidUploadKey/realisation_plus_in_output897=== RUN TestIsValidUploadKey/nix-cache-info898=== PAUSE TestIsValidUploadKey/nix-cache-info899=== RUN TestIsValidUploadKey/index.html900=== PAUSE TestIsValidUploadKey/index.html901=== RUN TestIsValidUploadKey/narinfo_key,_nar_type902=== PAUSE TestIsValidUploadKey/narinfo_key,_nar_type903=== RUN TestIsValidUploadKey/nar_key,_narinfo_type904=== PAUSE TestIsValidUploadKey/nar_key,_narinfo_type905=== RUN TestIsValidUploadKey/listing_key,_narinfo_type906=== PAUSE TestIsValidUploadKey/listing_key,_narinfo_type907=== RUN TestIsValidUploadKey/traversal908=== PAUSE TestIsValidUploadKey/traversal909=== RUN TestIsValidUploadKey/traversal_nar910=== PAUSE TestIsValidUploadKey/traversal_nar911=== RUN TestIsValidUploadKey/absolute912=== PAUSE TestIsValidUploadKey/absolute913=== RUN TestIsValidUploadKey/empty_key914=== PAUSE TestIsValidUploadKey/empty_key915=== RUN TestIsValidUploadKey/unknown_type916=== PAUSE TestIsValidUploadKey/unknown_type917=== CONT TestReadProxyNarStreaming918--- PASS: TestObjectStatsTrigger (1.28s)919=== CONT TestPendingClosureWriteTimeout920=== RUN TestPendingClosureWriteTimeout/empty921=== PAUSE TestPendingClosureWriteTimeout/empty922=== RUN TestPendingClosureWriteTimeout/400_objects923=== PAUSE TestPendingClosureWriteTimeout/400_objects924=== RUN TestPendingClosureWriteTimeout/670k_objects925=== PAUSE TestPendingClosureWriteTimeout/670k_objects926=== RUN TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline927=== PAUSE TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline928=== CONT TestGenerateLandingPage929--- PASS: TestGenerateLandingPage (0.00s)930=== CONT TestProxyWriteTimeout931=== RUN TestProxyWriteTimeout/narinfo932=== PAUSE TestProxyWriteTimeout/narinfo933=== RUN TestProxyWriteTimeout/1_GiB_nar934=== PAUSE TestProxyWriteTimeout/1_GiB_nar935=== RUN TestProxyWriteTimeout/10_GiB_nar936=== PAUSE TestProxyWriteTimeout/10_GiB_nar937=== RUN TestProxyWriteTimeout/unknown_size938=== PAUSE TestProxyWriteTimeout/unknown_size939=== CONT TestPush_OverlappingRootsStoreOneRowPerKey9402026/10/25 17:19:03 INFO Received uploads request method=POST path=/api/pending_closures9412026/10/25 17:19:03 INFO Received cleanup request method=DELETE path=/api/pending_closures9422026/10/25 17:19:03 WARN Failed to abort upload, keeping its closure key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst error="Get \"http://127.0.0.1:1/bucket6/?location=\": dial tcp 127.0.0.1:1: connect: connection refused" code=""9432026/10/25 17:19:03 INFO Aborted multipart uploads count=0 kept=19442026/10/25 17:19:03 INFO Received cleanup request method=DELETE path=/api/pending_closures9452026/10/25 17:19:03 INFO Aborted multipart uploads count=1 kept=0946--- PASS: TestMultipartCleanup (1.69s)947=== CONT TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle948--- PASS: TestGetExistingObjectsLocksRows (1.70s)949=== CONT TestPresentNotReportedWhileGCDeletesClosure950=== RUN TestPresentNotReportedWhileGCDeletesClosure/stale951=== PAUSE TestPresentNotReportedWhileGCDeletesClosure/stale952=== RUN TestPresentNotReportedWhileGCDeletesClosure/fresh953=== PAUSE TestPresentNotReportedWhileGCDeletesClosure/fresh954=== CONT TestReadRedirectUsesPublicS3URL9552026/10/25 17:19:03 INFO Received uploads request method=POST path=/api/pending_closures9562026/10/25 17:19:03 INFO Received uploads request method=POST path=/api/pending_closures957--- PASS: TestCreatePendingClosureVerifyS3FailureReleasesConnection (2.20s)958=== CONT TestSkippedUploadsHandler9592026/10/25 17:19:03 INFO Client skipped oversized paths paths=3 nar_bytes=5000000000960--- PASS: TestSkippedUploadsHandler (0.00s)961=== CONT TestReadProxyContentNegotiation9622026/10/25 17:19:03 INFO Received uploads request method=POST path=/api/pending_closures9632026/10/25 17:19:04 INFO Received cleanup request method=DELETE path=/api/pending_closures9642026/10/25 17:19:04 INFO Received uploads request method=POST path=/api/pending_closures9652026/10/25 17:19:04 INFO Aborted multipart uploads count=0 kept=09662026/10/25 17:19:04 WARN Force mode enabled - objects will be deleted immediately without grace period9672026/10/25 17:19:04 ERROR failed to remove object object=nar/dddddddddddddddddddddddddddddddddddddddddddddddddddd.nar.zst error="Access Denied."9682026/10/25 17:19:04 ERROR failed to remove object object=dddddddddddddddddddddddddddddddd.narinfo error="Access Denied."969--- PASS: TestFailedS3DeleteKeepsTombstone (2.61s)970=== CONT TestReadProxyRangeRequest9712026/10/25 17:19:04 INFO Aborted multipart uploads count=0 kept=09722026/10/25 17:19:04 WARN Force mode enabled - objects will be deleted immediately without grace period9732026/10/25 17:19:04 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=09742026/10/25 17:19:04 INFO Vacuumed table table=pending_closures9752026/10/25 17:19:04 INFO Vacuumed table table=pending_objects9762026/10/25 17:19:04 INFO Vacuumed table table=multipart_uploads9772026/10/25 17:19:04 INFO Vacuumed table table=closures9782026/10/25 17:19:04 INFO Vacuumed table table=objects9792026/10/25 17:19:04 INFO Aborted multipart uploads count=0 kept=09802026/10/25 17:19:04 WARN Force mode enabled - objects will be deleted immediately without grace period9812026/10/25 17:19:04 WARN Authentication failed token_preview=wrongtoken token_length=10 reason="static API token mismatch"982--- PASS: TestService_AuthMiddleware (2.79s)983=== CONT TestParseSize984--- PASS: TestParseSize (0.00s)985=== CONT TestReadProxyNarinfoAlreadyDecompressed9862026/10/25 17:19:04 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=09872026/10/25 17:19:04 INFO Vacuumed table table=pending_closures9882026/10/25 17:19:04 INFO Vacuumed table table=pending_objects9892026/10/25 17:19:04 INFO Vacuumed table table=multipart_uploads9902026/10/25 17:19:04 INFO Vacuumed table table=closures9912026/10/25 17:19:04 INFO Vacuumed table table=objects992--- PASS: TestSweepSkipsRowsLockedByPush (2.98s)993=== CONT TestReadRedirectKeepsNarinfoProxied9942026/10/25 17:19:04 INFO Aborted multipart uploads count=0 kept=09952026/10/25 17:19:04 WARN Force mode enabled - objects will be deleted immediately without grace period9962026/10/25 17:19:04 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=09972026/10/25 17:19:04 INFO Vacuumed table table=pending_closures9982026/10/25 17:19:04 INFO Vacuumed table table=pending_objects9992026/10/25 17:19:04 INFO Vacuumed table table=multipart_uploads10002026/10/25 17:19:04 INFO Vacuumed table table=closures10012026/10/25 17:19:04 INFO Received uploads request method=POST path=/api/pending_closures10022026/10/25 17:19:04 INFO Vacuumed table table=objects1003--- PASS: TestCommitRacingPendingCleanupKeepsObjects (3.27s)1004=== CONT TestService_Rustfstest1005--- PASS: TestMultipartUploadAbortedWhenCancelledBeforeRecorded (3.31s)1006=== CONT TestReadProxyNarinfo1007--- PASS: TestMetricsInventory (3.46s)1008=== CONT TestReadRedirectNar1009--- PASS: TestRegisterCompletedObjectNeedsPendingRow (3.77s)1010=== CONT TestPresignedUploadRegisteredBeforeCommit1011=== NAME TestNARDeduplicationMetadataUploadBug1012 metadata_upload_test.go:48: First store path: /private/var/tb/1/scratch/9b0bff5f52e90cd9/build/TestNARDeduplicationMetadataUploadBug647449186/001/store/6m9pfz7a60rgmbpfik20hmznz9wbqfrw-file1.txt10132026/10/25 17:19:05 WARN mTLS auth: subject not in bound subjects subject="CN=reader"10142026/10/25 17:19:05 WARN mTLS auth: subject not in bound subjects subject="CN=reader"1015--- PASS: TestService_NativeMTLS (3.96s)1016=== CONT TestIsValidCachePath1017=== RUN TestIsValidCachePath/narinfo1018=== PAUSE TestIsValidCachePath/narinfo1019=== RUN TestIsValidCachePath/narinfo_all_nix_base32_chars1020=== PAUSE TestIsValidCachePath/narinfo_all_nix_base32_chars1021=== RUN TestIsValidCachePath/nar_zst1022=== PAUSE TestIsValidCachePath/nar_zst1023=== RUN TestIsValidCachePath/nar_xz1024=== PAUSE TestIsValidCachePath/nar_xz1025=== RUN TestIsValidCachePath/nar_bz21026=== PAUSE TestIsValidCachePath/nar_bz21027=== RUN TestIsValidCachePath/nar_uncompressed1028=== PAUSE TestIsValidCachePath/nar_uncompressed1029=== RUN TestIsValidCachePath/ls1030=== PAUSE TestIsValidCachePath/ls1031=== RUN TestIsValidCachePath/log1032=== PAUSE TestIsValidCachePath/log1033=== RUN TestIsValidCachePath/realisation1034=== PAUSE TestIsValidCachePath/realisation1035=== RUN TestIsValidCachePath/nix-cache-info1036=== PAUSE TestIsValidCachePath/nix-cache-info1037=== RUN TestIsValidCachePath/index.html1038=== PAUSE TestIsValidCachePath/index.html1039=== RUN TestIsValidCachePath/traversal_parent1040=== PAUSE TestIsValidCachePath/traversal_parent1041=== RUN TestIsValidCachePath/traversal_in_middle1042=== PAUSE TestIsValidCachePath/traversal_in_middle1043=== RUN TestIsValidCachePath/invalid_char_e1044=== PAUSE TestIsValidCachePath/invalid_char_e1045=== RUN TestIsValidCachePath/invalid_char_u1046=== PAUSE TestIsValidCachePath/invalid_char_u1047=== RUN TestIsValidCachePath/random_path1048=== PAUSE TestIsValidCachePath/random_path1049=== RUN TestIsValidCachePath/empty1050=== PAUSE TestIsValidCachePath/empty1051=== RUN TestIsValidCachePath/leading_slash1052=== PAUSE TestIsValidCachePath/leading_slash1053=== RUN TestIsValidCachePath/wrong_extension1054=== PAUSE TestIsValidCachePath/wrong_extension1055=== RUN TestIsValidCachePath/short_hash1056=== PAUSE TestIsValidCachePath/short_hash1057=== CONT TestReadProxyDisabled10582026/10/25 17:19:05 INFO Received push request method=POST path=/api/pushes10592026/10/25 17:19:05 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)10602026/10/25 17:19:05 INFO Uploading 6m9pfz7a60rgmbpfik20hmznz9wbqfrw-file1.txt (160B)10612026/10/25 17:19:05 WARN Failed to register uploaded object key=6m9pfz7a60rgmbpfik20hmznz9wbqfrw.ls error="server returned 404: 404 page not found\n"10622026/10/25 17:19:05 WARN Failed to register uploaded object key=nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst error="server returned 404: 404 page not found\n"10632026/10/25 17:19:05 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign10642026/10/25 17:19:05 INFO Signed narinfos id=1 count=110652026/10/25 17:19:05 INFO Uploading 1 narinfos10662026/10/25 17:19:05 INFO Received complete push request method=POST path=/api/pushes/1/complete10672026/10/25 17:19:05 WARN Failed to register uploaded object key=6m9pfz7a60rgmbpfik20hmznz9wbqfrw.narinfo error="server returned 404: 404 page not found\n"10682026/10/25 17:19:05 INFO Completed push id=1 objects=3 duration=13.179834ms10692026/10/25 17:19:05 INFO Upload complete. (255ms)1070=== NAME TestNARDeduplicationMetadataUploadBug1071 metadata_upload_test.go:54: Retrieved narinfo from S3:1072 StorePath: /private/var/tb/1/scratch/9b0bff5f52e90cd9/build/TestNARDeduplicationMetadataUploadBug647449186/001/store/6m9pfz7a60rgmbpfik20hmznz9wbqfrw-file1.txt1073 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1074 Compression: zstd1075 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1076 NarSize: 1601077 References: 1078 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1079 metadata_upload_test.go:55: Retrieved .ls file from S3 (compressed size: 77 bytes)1080 metadata_upload_test.go:55: Decompressed .ls content (64 bytes):1081 {"version":1,"root":{"type":"regular","size":44,"narOffset":96}}10822026/10/25 17:19:05 INFO Received push request method=POST path=/api/pushes1083 metadata_upload_test.go:64: Second store path (same content): /private/var/tb/1/scratch/9b0bff5f52e90cd9/build/TestNARDeduplicationMetadataUploadBug647449186/001/store/bmljgp68fjl040y4d705x6hg8l52hwyd-file2.txt10842026/10/25 17:19:05 INFO Received complete push request method=POST path=/api/pushes/1/complete10852026/10/25 17:19:06 INFO Completed push id=1 objects=6 duration=20.636333ms1086--- PASS: TestPush_CompleteCommitsEveryRoot (4.28s)1087=== CONT TestCompletedNarNotReofferedAcrossClosures10882026/10/25 17:19:06 INFO Received cleanup request method=DELETE path=/api/pending_closures10892026/10/25 17:19:06 INFO Aborted multipart uploads count=0 kept=010902026/10/25 17:19:06 INFO Received uploads request method=POST path=/api/pending_closures10912026/10/25 17:19:06 INFO Received push request method=POST path=/api/pushes10922026/10/25 17:19:06 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)10932026/10/25 17:19:06 INFO Received cleanup request method=DELETE path=/api/pending_closures10942026/10/25 17:19:06 INFO Aborted multipart uploads count=1 kept=010952026/10/25 17:19:06 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign10962026/10/25 17:19:06 INFO Signed narinfos id=2 count=110972026/10/25 17:19:06 INFO Uploading 1 narinfos10982026/10/25 17:19:06 WARN Failed to register uploaded object key=bmljgp68fjl040y4d705x6hg8l52hwyd.ls error="server returned 404: 404 page not found\n"10992026/10/25 17:19:06 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete11002026-10-25 17:19:06.216 UTC [47466] ERROR: Closure does not exist: id=111012026-10-25 17:19:06.216 UTC [47466] CONTEXT: PL/pgSQL function commit_pending_closure(bigint) line 13 at RAISE11022026-10-25 17:19:06.216 UTC [47466] STATEMENT: -- name: CommitPendingClosure :one1103 SELECT commit_pending_closure($1::bigint)::bigint1104 1105--- PASS: TestService_cleanupPendingClosuresHandler (4.48s)1106=== CONT TestParseSingleRange1107=== RUN TestParseSingleRange/none1108=== PAUSE TestParseSingleRange/none1109=== RUN TestParseSingleRange/unknown_unit1110=== PAUSE TestParseSingleRange/unknown_unit1111=== RUN TestParseSingleRange/multi-range_ignored1112=== PAUSE TestParseSingleRange/multi-range_ignored1113=== RUN TestParseSingleRange/malformed_no_dash1114=== PAUSE TestParseSingleRange/malformed_no_dash1115=== RUN TestParseSingleRange/malformed_both_empty1116=== PAUSE TestParseSingleRange/malformed_both_empty1117=== RUN TestParseSingleRange/malformed_end_before_start1118=== PAUSE TestParseSingleRange/malformed_end_before_start1119=== RUN TestParseSingleRange/closed1120=== PAUSE TestParseSingleRange/closed1121=== RUN TestParseSingleRange/open-ended1122=== PAUSE TestParseSingleRange/open-ended1123=== RUN TestParseSingleRange/end_clamped_to_size1124=== PAUSE TestParseSingleRange/end_clamped_to_size1125=== RUN TestParseSingleRange/suffix1126=== PAUSE TestParseSingleRange/suffix1127=== RUN TestParseSingleRange/suffix_exceeds_size1128=== PAUSE TestParseSingleRange/suffix_exceeds_size1129=== RUN TestParseSingleRange/single_byte1130=== PAUSE TestParseSingleRange/single_byte1131=== RUN TestParseSingleRange/start_past_EOF1132=== PAUSE TestParseSingleRange/start_past_EOF1133=== RUN TestParseSingleRange/start_far_past_EOF1134=== PAUSE TestParseSingleRange/start_far_past_EOF1135=== CONT TestReadProxyRootRedirectsToIndexHTML11362026/10/25 17:19:06 INFO Received complete push request method=POST path=/api/pushes/2/complete11372026/10/25 17:19:06 WARN Failed to register uploaded object key=bmljgp68fjl040y4d705x6hg8l52hwyd.narinfo error="server returned 404: 404 page not found\n"11382026/10/25 17:19:06 INFO Completed push id=2 objects=3 duration=1.421709ms11392026/10/25 17:19:06 INFO Upload complete. (156ms)1140=== NAME TestNARDeduplicationMetadataUploadBug1141 metadata_upload_test.go:76: Retrieved narinfo from S3:1142 StorePath: /private/var/tb/1/scratch/9b0bff5f52e90cd9/build/TestNARDeduplicationMetadataUploadBug647449186/001/store/bmljgp68fjl040y4d705x6hg8l52hwyd-file2.txt1143 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1144 Compression: zstd1145 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1146 NarSize: 1601147 References: 1148 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1149 metadata_upload_test.go:77: Retrieved .ls file from S3 (compressed size: 62 bytes)1150 metadata_upload_test.go:77: Decompressed .ls content (49 bytes):1151 {"version":1,"root":{"type":"regular","size":44}}1152--- PASS: TestNARDeduplicationMetadataUploadBug (4.55s)1153=== CONT TestCompleteMultipartUpload_ErrorButObjectExists11542026/10/25 17:19:06 WARN readiness check failed error="closed pool"1155--- PASS: TestService_readinessHandler (4.59s)1156=== CONT TestReadProxyConditionalGet11572026/10/25 17:19:06 INFO Aborted multipart uploads count=0 kept=011582026/10/25 17:19:06 WARN Force mode enabled - objects will be deleted immediately without grace period11592026/10/25 17:19:06 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=011602026/10/25 17:19:06 INFO Vacuumed table table=pending_closures11612026/10/25 17:19:06 INFO Vacuumed table table=pending_objects11622026/10/25 17:19:06 INFO Vacuumed table table=multipart_uploads11632026/10/25 17:19:06 INFO Vacuumed table table=closures11642026/10/25 17:19:06 INFO Vacuumed table table=objects1165--- PASS: TestSweepRechecksPendingAfterLocking (4.87s)1166=== CONT TestReadProxyHead11672026/10/25 17:19:06 INFO Received uploads request method=POST path=/api/pending_closures11682026/10/25 17:19:06 INFO Received uploads request method=POST path=/api/pending_closures11692026/10/25 17:19:06 INFO Received uploads request method=POST path=/api/pending_closures1170--- PASS: TestCreatePendingClosure_SmallNARUsesSimplePUT (5.32s)1171=== CONT TestRedundantMultipartUpload11722026/10/25 17:19:07 INFO Received uploads request method=POST path=/api/pending_closures11732026/10/25 17:19:07 INFO Received uploads request method=POST path=/api/pending_closures11742026/10/25 17:19:07 INFO Received uploads request method=POST path=/api/pending_closures1175--- PASS: TestPushWaitsForSweepHoldingRow (5.60s)1176=== CONT TestReadProxyInvalidPath11772026/10/25 17:19:07 INFO Received push request method=POST path=/api/pushes11782026/10/25 17:19:07 INFO Received complete push request method=POST path=/api/pushes/1/complete11792026/10/25 17:19:07 INFO Completed push id=1 objects=4 duration=45.853917ms11802026/10/25 17:19:07 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete11812026/10/25 17:19:07 INFO Completed upload id=2 objects=2 duration=1.013875ms1182--- PASS: TestMetricsCommit (5.86s)1183=== CONT TestReadProxyOutlastsServerWriteTimeout11842026/10/25 17:19:07 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11852026/10/25 17:19:07 INFO Received push request method=POST path=/api/pushes11862026/10/25 17:19:07 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst upload_id=OTU4ZTMxMDgtYjVmNi00ZjRmLWJjMzEtZDc3ZWE2ZjY2NDgzLjZkODU2MGNjLTVmMTQtNGNlNC1iY2ViLWM4MGY4OWIxNmEwMngxNzkyOTQ4NzQ2NjMxOTg3MDAw parts=1011872026/10/25 17:19:07 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete11882026/10/25 17:19:07 INFO Completed upload id=1 objects=2 duration=20.074375ms11892026/10/25 17:19:07 INFO Received uploads request method=POST path=/api/pending_closures11902026/10/25 17:19:07 INFO Received uploads request method=POST path=/api/pending_closures11912026/10/25 17:19:07 INFO Object in database but missing from S3 key=dadb44fdadb44fdadb44fdadb44f0000.narinfo11922026/10/25 17:19:07 WARN Found objects in DB but missing from S3, will re-upload count=11193--- PASS: TestService_verifyS3Integrity (6.12s)1194=== CONT TestPush_SignsNarinfosOfItsPendingObjects1195--- PASS: TestPush_OverlappingRootsStoreOneRowPerKey (4.86s)1196=== CONT TestReadProxy4041197--- PASS: TestReadProxyNarStreaming (5.40s)1198=== CONT TestPush_RejectsBadRequests11992026/10/25 17:19:08 INFO Received uploads request method=POST path=/api/pending_closures12002026/10/25 17:19:08 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1201--- PASS: TestReadRedirectUsesPublicS3URL (5.13s)1202=== CONT TestClientCADerivations12032026/10/25 17:19:08 INFO Completed multipart upload object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst upload_id=OTU4ZTMxMDgtYjVmNi00ZjRmLWJjMzEtZDc3ZWE2ZjY2NDgzLmJmMjkzMTk3LTU3ZTctNDM1Zi04NDJhLTAyZDE5MGFlMDFjM3gxNzkyOTQ4NzQ3MjQwNDI4MDAw parts=1012042026/10/25 17:19:08 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete12052026/10/25 17:19:08 INFO Received complete multipart upload request method=POST path=/api/multipart/complete12062026/10/25 17:19:08 INFO Completed upload id=1 objects=2 duration=17.723458ms12072026/10/25 17:19:08 INFO Received get closure request method=GET path=/api/closures/0000000000000000000000000000000012082026/10/25 17:19:08 INFO Received uploads request method=POST path=/api/pending_closures12092026/10/25 17:19:08 INFO Starting cleanup of old closures method=DELETE path=/api/closures12102026/10/25 17:19:08 INFO Aborted multipart uploads count=0 kept=012112026/10/25 17:19:08 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=012122026/10/25 17:19:08 INFO Vacuumed table table=pending_closures12132026/10/25 17:19:08 INFO Vacuumed table table=pending_objects12142026/10/25 17:19:08 INFO Vacuumed table table=multipart_uploads12152026/10/25 17:19:08 INFO Vacuumed table table=closures12162026/10/25 17:19:08 INFO Vacuumed table table=objects12172026/10/25 17:19:08 INFO Received get closure request method=GET path=/api/closures/000000000000000000000000000000001218--- PASS: TestService_createPendingClosureHandler (7.21s)1219=== CONT TestPush_SkippedKeySurvivesGCBeforeCommit1220--- PASS: TestReadProxyContentNegotiation (5.05s)1221=== CONT TestPush_RootsAreLockedInByteOrder1222--- PASS: TestReadProxyRangeRequest (4.83s)1223=== CONT TestPush_CompleteWaitsForCleanupOfThePush1224--- PASS: TestReadProxyNarinfoAlreadyDecompressed (4.94s)1225=== CONT TestPush_RepeatedRootCommitsOnce1226--- PASS: TestReadRedirectKeepsNarinfoProxied (5.04s)1227=== CONT TestService_RequireScope_OIDC12282026/10/25 17:19:09 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:52626/oidc12292026/10/25 17:19:10 INFO Aborted multipart uploads count=1 kept=012302026/10/25 17:19:10 ERROR Failed to decode narinfo key=3hcdxyjf9yiq7qf3i4548drb6sjmwa1v.narinfo limit=16777216 error=<nil>1231--- PASS: TestReadProxyNarinfo (5.04s)1232=== CONT TestClientFallsBackToClosures12332026/10/25 17:19:10 INFO Received cleanup request method=DELETE path=/api/pending_closures12342026/10/25 17:19:10 INFO Aborted multipart uploads count=1 kept=01235--- PASS: TestPendingCleanupUsesOneCutoff (8.39s)1236=== CONT TestGCSweepDeliversEachKeyOnce1237--- PASS: TestService_Rustfstest (5.20s)1238=== CONT TestTombstonedObjectOfferedWithoutWaiting1239--- PASS: TestReadRedirectNar (5.30s)1240=== CONT TestClientPushesUseOnePush12412026/10/25 17:19:10 INFO Received uploads request method=POST path=/api/pending_closures12422026/10/25 17:19:10 INFO Registered completed upload object_key=nar/jjjjjjjjjjjjjjjjjjjjjjjjjjjjjj0100000000000000000000.nar.zst12432026/10/25 17:19:10 INFO Received uploads request method=POST path=/api/pending_closures1244--- PASS: TestPresignedUploadRegisteredBeforeCommit (5.29s)1245=== CONT TestGCSweepSkipsPendingObjects1246--- PASS: TestReadProxyDisabled (5.21s)1247=== CONT TestPinProtectsFromGC12482026/10/25 17:19:11 INFO Received uploads request method=POST path=/api/pending_closures1249--- PASS: TestReadProxyRootRedirectsToIndexHTML (5.32s)1250=== CONT TestDeduplicatedObjectsRecordedAsPending12512026/10/25 17:19:11 INFO Received uploads request method=POST path=/api/pending_closures12522026/10/25 17:19:12 WARN Rate limiter enabled after throttle name=s3-test rate=512532026/10/25 17:19:12 WARN S3 rate limit hit operation="complete multipart upload" error="Please reduce your request rate."1254=== NAME TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle1255 throttle_test.go:213: Proxy stats: total=13, throttled=10, completeMultipart=101256 throttle_test.go:215: Rate limiter: enabled=true, rate=5.001257--- PASS: TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle (8.71s)1258=== CONT TestPushDedupSurvivesConcurrentGC1259--- PASS: TestReadProxyConditionalGet (5.86s)1260=== CONT TestGCMetrics12612026/10/25 17:19:12 INFO Received complete multipart upload request method=POST path=/api/multipart/complete12622026/10/25 17:19:12 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified key does not exist." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=OTU4ZTMxMDgtYjVmNi00ZjRmLWJjMzEtZDc3ZWE2ZjY2NDgzLmFiYzdhY2VkLTlmMzgtNGZhOC1hMjY2LTY5MjkzM2MyZGJiN3gxNzkyOTQ4NzUxODgyNjQxMDAw12632026/10/25 17:19:12 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=OTU4ZTMxMDgtYjVmNi00ZjRmLWJjMzEtZDc3ZWE2ZjY2NDgzLmFiYzdhY2VkLTlmMzgtNGZhOC1hMjY2LTY5MjkzM2MyZGJiN3gxNzkyOTQ4NzUxODgyNjQxMDAw parts=11264--- PASS: TestCompleteMultipartUpload_ErrorButObjectExists (6.03s)1265=== CONT TestGCBugBareHashReferences1266--- PASS: TestReadProxyHead (5.92s)1267=== CONT TestGCAdvisoryLockBlocksConcurrentRun12682026/10/25 17:19:12 INFO Received uploads request method=POST path=/api/pending_closures12692026/10/25 17:19:12 INFO Received uploads request method=POST path=/api/pending_closures12702026/10/25 17:19:13 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1271--- PASS: TestReadProxyInvalidPath (5.73s)1272=== CONT TestLeadEndsOnShutdown12732026/10/25 17:19:13 INFO Completed multipart upload object_key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhh0100000000000000000000.nar.zst upload_id=OTU4ZTMxMDgtYjVmNi00ZjRmLWJjMzEtZDc3ZWE2ZjY2NDgzLmJmMTJjYjIyLWRjN2QtNGYwNi1hOWQ2LWY5MzcxNzFjNDZjYngxNzkyOTQ4NzUxMjcwOTM3MDAw parts=1212742026/10/25 17:19:13 INFO Received uploads request method=POST path=/api/pending_closures1275--- PASS: TestCompletedNarNotReofferedAcrossClosures (7.25s)1276=== CONT TestLeadIncumbentAnnouncesAtOnce12772026/10/25 17:19:14 INFO Received push request method=POST path=/api/pushes12782026/10/25 17:19:14 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign12792026/10/25 17:19:14 INFO Signed narinfos id=1 count=112802026/10/25 17:19:14 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign12812026/10/25 17:19:14 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign12822026/10/25 17:19:14 ERROR Failed to sign narinfos signer="index 1" error="signing key cannot be nil"12832026/10/25 17:19:14 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign12842026/10/25 17:19:14 ERROR Failed to sign narinfos signer=niks3-test-1 error="signer failed"12852026/10/25 17:19:14 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign12862026/10/25 17:19:14 ERROR Signer returned unexpected signature count signer=niks3-test-1 got=0 want=112872026/10/25 17:19:14 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign12882026/10/25 17:19:14 ERROR Signer returned unexpected object key signer=niks3-test-1 object_key=unexpected.narinfo1289--- PASS: TestPush_SignsNarinfosOfItsPendingObjects (6.47s)1290=== CONT TestCacheStatsHandler1291--- PASS: TestReadProxy404 (6.61s)1292=== CONT TestCacheConfigHandler1293=== RUN TestCacheConfigHandler/full_config,_no_issuer1294=== PAUSE TestCacheConfigHandler/full_config,_no_issuer1295=== RUN TestCacheConfigHandler/no_cache_url_configured1296=== PAUSE TestCacheConfigHandler/no_cache_url_configured1297=== RUN TestCacheConfigHandler/no_signing_keys1298=== PAUSE TestCacheConfigHandler/no_signing_keys1299=== RUN TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1300=== PAUSE TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1301=== CONT TestService_ReadScope_PublicByDefault1302=== RUN TestPush_RejectsBadRequests/no_objects1303=== PAUSE TestPush_RejectsBadRequests/no_objects1304=== RUN TestPush_RejectsBadRequests/bad_root1305=== PAUSE TestPush_RejectsBadRequests/bad_root1306=== RUN TestPush_RejectsBadRequests/root_not_in_objects1307=== PAUSE TestPush_RejectsBadRequests/root_not_in_objects1308=== RUN TestPush_RejectsBadRequests/no_roots1309=== PAUSE TestPush_RejectsBadRequests/no_roots1310=== CONT TestClientSharedPathCommittedMidPush13112026/10/25 17:19:14 INFO Received complete multipart upload request method=POST path=/api/multipart/complete13122026/10/25 17:19:15 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=OTU4ZTMxMDgtYjVmNi00ZjRmLWJjMzEtZDc3ZWE2ZjY2NDgzLjU0ZDc4ZWU4LTViMTUtNDMyNC1hZmUzLTRhM2Y4MmUxMjU0NHgxNzkyOTQ4NzUyNzk5NzU2MDAw parts=1213132026/10/25 17:19:15 INFO Received uploads request method=POST path=/api/pending_closures13142026/10/25 17:19:15 INFO Received uploads request method=POST path=/api/pending_closures13152026/10/25 17:19:15 INFO Received push request method=POST path=/api/pushes13162026-10-25 17:19:15.327 UTC [47635] ERROR: could not obtain lock on row in relation "closures"13172026-10-25 17:19:15.327 UTC [47635] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT13182026-10-25 17:19:15.328 UTC [47635] ERROR: could not obtain lock on row in relation "closures"13192026-10-25 17:19:15.328 UTC [47635] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT13202026-10-25 17:19:15.336 UTC [47635] ERROR: could not obtain lock on row in relation "closures"13212026-10-25 17:19:15.336 UTC [47635] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT13222026-10-25 17:19:15.340 UTC [47635] ERROR: could not obtain lock on row in relation "closures"13232026-10-25 17:19:15.340 UTC [47635] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT13242026-10-25 17:19:15.347 UTC [47635] ERROR: could not obtain lock on row in relation "closures"13252026-10-25 17:19:15.347 UTC [47635] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT1326--- PASS: TestPush_RootsAreLockedInByteOrder (6.38s)1327=== CONT TestClientWithDependencies13282026/10/25 17:19:15 INFO Received push request method=POST path=/api/pushes1329=== NAME TestClientCADerivations1330 client_ca_test.go:136: Built CA derivation: /private/var/tb/1/scratch/9b0bff5f52e90cd9/build/TestClientCADerivations355013220/001/store/2rpl2sl6lfwl91xv5hl8qn792kasg11w-ca-test13312026/10/25 17:19:15 INFO Received complete push request method=POST path=/api/pushes/1/complete13322026/10/25 17:19:15 INFO Completed push id=1 objects=4 duration=37.946ms1333 client_ca_test.go:139: Found 1 dependencies (including self)13342026/10/25 17:19:15 INFO Received push request method=POST path=/api/pushes13352026/10/25 17:19:15 INFO Aborted multipart uploads count=0 kept=013362026/10/25 17:19:15 WARN Force mode enabled - objects will be deleted immediately without grace period13372026/10/25 17:19:15 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=013382026/10/25 17:19:15 INFO Vacuumed table table=pending_closures13392026/10/25 17:19:15 INFO Received push request method=POST path=/api/pushes13402026/10/25 17:19:15 INFO Vacuumed table table=pending_objects13412026/10/25 17:19:15 INFO Vacuumed table table=multipart_uploads13422026/10/25 17:19:15 INFO Vacuumed table table=closures13432026/10/25 17:19:15 INFO Vacuumed table table=objects13442026/10/25 17:19:15 INFO Received complete push request method=POST path=/api/pushes/2/complete13452026/10/25 17:19:15 INFO Completed push id=2 objects=4 duration=9.979083ms1346--- PASS: TestPush_SkippedKeySurvivesGCBeforeCommit (6.90s)1347=== CONT TestClientMultipleUploads13482026/10/25 17:19:15 INFO Received push request method=POST path=/api/pushes13492026/10/25 17:19:15 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)13502026/10/25 17:19:15 INFO Uploading 2rpl2sl6lfwl91xv5hl8qn792kasg11w-ca-test (144B)13512026/10/25 17:19:15 WARN Failed to register uploaded object key=2rpl2sl6lfwl91xv5hl8qn792kasg11w.ls error="server returned 404: 404 page not found\n"13522026/10/25 17:19:15 WARN Failed to register uploaded object key=nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst error="server returned 404: 404 page not found\n"13532026/10/25 17:19:15 WARN Failed to register uploaded object key=log/wqvyh3qb1v5r7y5mmprxv2a2fpav0r46-ca-test.drv error="server returned 404: 404 page not found\n"13542026/10/25 17:19:15 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign13552026/10/25 17:19:15 INFO Signed narinfos id=1 count=113562026/10/25 17:19:15 INFO Uploading 1 narinfos13572026/10/25 17:19:16 INFO Received complete push request method=POST path=/api/pushes/1/complete13582026/10/25 17:19:16 WARN Failed to register uploaded object key=2rpl2sl6lfwl91xv5hl8qn792kasg11w.narinfo error="server returned 404: 404 page not found\n"13592026/10/25 17:19:16 INFO Completed push id=1 objects=4 duration=25.729792ms13602026/10/25 17:19:16 INFO Upload complete. (356ms)13612026/10/25 17:19:16 INFO Received push request method=POST path=/api/pushes1362=== NAME TestClientCADerivations1363 client_ca_test.go:180: Narinfo contains CA field: StorePath: /private/var/tb/1/scratch/9b0bff5f52e90cd9/build/TestClientCADerivations355013220/001/store/2rpl2sl6lfwl91xv5hl8qn792kasg11w-ca-test1364 URL: nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst1365 Compression: zstd1366 NarHash: sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1367 NarSize: 1441368 References: 1369 Deriver: /private/var/tb/1/scratch/9b0bff5f52e90cd9/build/TestClientCADerivations355013220/001/store/wqvyh3qb1v5r7y5mmprxv2a2fpav0r46-ca-test.drv1370 CA: fixed:r:sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1371 client_ca_test.go:185: Checking for realisation files in S3...1372 client_ca_test.go:207: No realisation files uploaded - this is expected for locally built CA derivations1373 client_ca_test.go:208: Locally built CA derivations don't have DrvOutput IDs until they're substituted from a cache13742026/10/25 17:19:16 INFO Received complete push request method=POST path=/api/pushes/1/complete13752026/10/25 17:19:16 INFO Completed push id=1 objects=4 duration=18.136042ms1376--- PASS: TestPush_RepeatedRootCommitsOnce (6.69s)13772026-10-25 17:19:16.159 UTC [47808] ERROR: Push does not exist: id=113782026-10-25 17:19:16.159 UTC [47808] CONTEXT: PL/pgSQL function commit_push(bigint) line 11 at RAISE13792026-10-25 17:19:16.159 UTC [47808] STATEMENT: SELECT commit_push($1)1380=== CONT TestClientIntegration1381--- PASS: TestPush_CompleteWaitsForCleanupOfThePush (6.98s)1382=== CONT TestClientErrorHandling1383=== RUN TestClientErrorHandling/InvalidStorePath1384=== PAUSE TestClientErrorHandling/InvalidStorePath1385=== RUN TestClientErrorHandling/InvalidAuthToken1386=== PAUSE TestClientErrorHandling/InvalidAuthToken1387=== RUN TestClientErrorHandling/ServerNotAvailable1388=== PAUSE TestClientErrorHandling/ServerNotAvailable1389=== CONT TestLeadElectsOneAndHandsOver1390=== NAME TestClientCADerivations1391 client_ca_test.go:258: nix copy output: error: binary cache 's3://bucket52?endpoint=http://localhost:52480®ion=eu-west-1' is for Nix stores with prefix '/nix/store', not '/private/var/tb/1/scratch/9b0bff5f52e90cd9/build/TestClientCADerivations355013220/001/store'1392 client_ca_test.go:259: nix copy failed (might be expected with isolated stores): exit status 11393--- PASS: TestClientCADerivations (7.71s)1394=== CONT TestConcurrentCommitsSharingObjectsDoNotDeadlock1395=== RUN TestService_RequireScope_OIDC/builder_may_write1396=== PAUSE TestService_RequireScope_OIDC/builder_may_write1397=== RUN TestService_RequireScope_OIDC/builder_may_not_admin1398=== PAUSE TestService_RequireScope_OIDC/builder_may_not_admin1399=== RUN TestService_RequireScope_OIDC/ops_may_admin1400=== PAUSE TestService_RequireScope_OIDC/ops_may_admin1401=== RUN TestService_RequireScope_OIDC/ops_may_not_write1402=== PAUSE TestService_RequireScope_OIDC/ops_may_not_write1403=== RUN TestService_RequireScope_OIDC/reader_may_not_write1404=== PAUSE TestService_RequireScope_OIDC/reader_may_not_write1405=== RUN TestService_RequireScope_OIDC/static_token_may_admin1406=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin1407=== RUN TestService_RequireScope_OIDC/static_token_may_write1408=== PAUSE TestService_RequireScope_OIDC/static_token_may_write1409=== RUN TestService_RequireScope_OIDC/reader_may_read1410=== PAUSE TestService_RequireScope_OIDC/reader_may_read1411=== RUN TestService_RequireScope_OIDC/writer_implies_read1412=== PAUSE TestService_RequireScope_OIDC/writer_implies_read1413=== RUN TestService_RequireScope_OIDC/anonymous_may_not_read1414=== PAUSE TestService_RequireScope_OIDC/anonymous_may_not_read1415=== RUN TestService_RequireScope_OIDC/reader_may_read_with_netrc1416=== PAUSE TestService_RequireScope_OIDC/reader_may_read_with_netrc1417=== RUN TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1418=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1419=== RUN TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read1420=== PAUSE TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read1421=== RUN TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1422=== PAUSE TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1423=== CONT TestDeleteClosuresRacingPins14242026/10/25 17:19:16 INFO Received complete multipart upload request method=POST path=/api/multipart/complete14252026/10/25 17:19:16 WARN Failed to abort redundant multipart upload, keeping its row object_key=nar/gggggggggggggggggggggggggggggg0200000000000000000000.nar.zst upload_id=OTU4ZTMxMDgtYjVmNi00ZjRmLWJjMzEtZDc3ZWE2ZjY2NDgzLjM1YTdjYTQ0LWY4ZjEtNGFlMi05N2Q1LWViZmY5ZGVmMGNmOHgxNzkyOTQ4NzU1MDg1OTgwMDAw error="Get \"http://127.0.0.1:1/bucket46/?location=\": dial tcp 127.0.0.1:1: connect: connection refused"14262026/10/25 17:19:16 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0200000000000000000000.nar.zst upload_id=OTU4ZTMxMDgtYjVmNi00ZjRmLWJjMzEtZDc3ZWE2ZjY2NDgzLjliNTdhZGIxLWFjZmQtNDQwOS04Mzc0LWJmZjI3ODg0ODBkZXgxNzkyOTQ4NzU1MDQyNTcwMDAw parts=1214272026/10/25 17:19:16 INFO Received cleanup request method=DELETE path=/api/pending_closures14282026/10/25 17:19:16 INFO Aborted multipart uploads count=1 kept=01429--- PASS: TestRedundantMultipartUpload (9.63s)1430=== CONT TestResolveDBConnectionString1431=== RUN TestResolveDBConnectionString/flag_wins1432=== PAUSE TestResolveDBConnectionString/flag_wins1433=== RUN TestResolveDBConnectionString/file_when_flag_empty1434=== PAUSE TestResolveDBConnectionString/file_when_flag_empty1435=== RUN TestResolveDBConnectionString/missing_file_is_an_error1436=== PAUSE TestResolveDBConnectionString/missing_file_is_an_error1437=== RUN TestResolveDBConnectionString/PGHOST_allows_empty1438=== PAUSE TestResolveDBConnectionString/PGHOST_allows_empty1439=== RUN TestResolveDBConnectionString/nothing_configured1440=== PAUSE TestResolveDBConnectionString/nothing_configured1441=== CONT TestService_ReadAuthMiddleware14422026/10/25 17:19:16 INFO Aborted multipart uploads count=0 kept=014432026/10/25 17:19:16 WARN Force mode enabled - objects will be deleted immediately without grace period14442026/10/25 17:19:17 INFO Received uploads request method=POST path=/api/pending_closures1445--- PASS: TestTombstonedObjectOfferedWithoutWaiting (6.84s)1446=== CONT TestConnectWaitsForAPeerMigration14472026/10/25 17:19:17 INFO Received uploads request method=POST path=/api/pending_closures14482026/10/25 17:19:17 INFO Received uploads request method=POST path=/api/pending_closures14492026/10/25 17:19:17 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)14502026/10/25 17:19:17 INFO Uploading 16qpflqkpqgmpakf5aqxc7x9764r55ad-shared-dep (136B)14512026/10/25 17:19:17 INFO Uploading mlz3qa7m7qgr81cncd17hbayakp8kcpp-b (256B)14522026/10/25 17:19:17 WARN Failed to register uploaded object key=nar/1v895ry0c46pdr3kgpqzyaa3n9gvrvi5dhp1vbkfxrmyf8yn3ajm.nar.zst error="server returned 404: 404 page not found\n"14532026/10/25 17:19:17 WARN Failed to register uploaded object key=16qpflqkpqgmpakf5aqxc7x9764r55ad.ls error="server returned 404: 404 page not found\n"14542026/10/25 17:19:17 WARN Failed to register uploaded object key=mlz3qa7m7qgr81cncd17hbayakp8kcpp.ls error="server returned 404: 404 page not found\n"14552026/10/25 17:19:17 WARN Failed to register uploaded object key=frkpd26jfn5l2q78ak7a95wp29gkl56s.ls error="server returned 404: 404 page not found\n"14562026/10/25 17:19:17 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign14572026/10/25 17:19:17 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"14582026/10/25 17:19:17 INFO Signed narinfos id=1 count=214592026/10/25 17:19:17 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign14602026/10/25 17:19:17 INFO Signed narinfos id=2 count=214612026/10/25 17:19:17 INFO Uploading 4 narinfos14622026/10/25 17:19:17 WARN Failed to register uploaded object key=16qpflqkpqgmpakf5aqxc7x9764r55ad.narinfo error="server returned 404: 404 page not found\n"14632026/10/25 17:19:17 WARN Failed to register uploaded object key=mlz3qa7m7qgr81cncd17hbayakp8kcpp.narinfo error="server returned 404: 404 page not found\n"14642026/10/25 17:19:17 WARN Failed to register uploaded object key=frkpd26jfn5l2q78ak7a95wp29gkl56s.narinfo error="server returned 404: 404 page not found\n"14652026/10/25 17:19:17 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete14662026/10/25 17:19:17 WARN Failed to register uploaded object key=16qpflqkpqgmpakf5aqxc7x9764r55ad.narinfo error="server returned 404: 404 page not found\n"14672026/10/25 17:19:17 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=014682026/10/25 17:19:17 INFO Vacuumed table table=pending_closures14692026/10/25 17:19:17 INFO Vacuumed table table=pending_objects14702026/10/25 17:19:17 INFO Vacuumed table table=multipart_uploads14712026/10/25 17:19:17 INFO Completed upload id=1 objects=6 duration=28.092875ms14722026/10/25 17:19:17 INFO Vacuumed table table=closures14732026/10/25 17:19:17 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete14742026/10/25 17:19:17 INFO Completed upload id=2 objects=6 duration=801.125µs14752026/10/25 17:19:17 INFO Upload complete. (389ms)1476=== NAME TestClientFallsBackToClosures1477 client_pushes_test.go:112: Retrieved narinfo from S3:1478 StorePath: /private/var/tb/1/scratch/9b0bff5f52e90cd9/build/TestClientFallsBackToClosures2384456255/001/store/16qpflqkpqgmpakf5aqxc7x9764r55ad-shared-dep1479 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1480 Compression: zstd1481 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821482 NarSize: 1361483 References: 1484 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1485 client_pushes_test.go:112: Retrieved narinfo from S3:1486 StorePath: /private/var/tb/1/scratch/9b0bff5f52e90cd9/build/TestClientFallsBackToClosures2384456255/001/store/frkpd26jfn5l2q78ak7a95wp29gkl56s-a1487 URL: nar/1v895ry0c46pdr3kgpqzyaa3n9gvrvi5dhp1vbkfxrmyf8yn3ajm.nar.zst1488 Compression: zstd1489 NarHash: sha256:1v895ry0c46pdr3kgpqzyaa3n9gvrvi5dhp1vbkfxrmyf8yn3ajm1490 NarSize: 2561491 References: /private/var/tb/1/scratch/9b0bff5f52e90cd9/build/TestClientFallsBackToClosures2384456255/001/store/16qpflqkpqgmpakf5aqxc7x9764r55ad-shared-dep1492 CA: text:sha256:1dqlmjrnswxk62rv9yjcybhjnp371yghzgiph70c2nsk8nr96pkl14932026/10/25 17:19:17 INFO Vacuumed table table=objects1494--- PASS: TestGCSweepDeliversEachKeyOnce (7.22s)1495=== CONT TestGracefulShutdownDrainsInflight1496=== NAME TestClientFallsBackToClosures1497 client_pushes_test.go:112: Retrieved narinfo from S3:1498 StorePath: /private/var/tb/1/scratch/9b0bff5f52e90cd9/build/TestClientFallsBackToClosures2384456255/001/store/mlz3qa7m7qgr81cncd17hbayakp8kcpp-b1499 URL: nar/1v895ry0c46pdr3kgpqzyaa3n9gvrvi5dhp1vbkfxrmyf8yn3ajm.nar.zst1500 Compression: zstd1501 NarHash: sha256:1v895ry0c46pdr3kgpqzyaa3n9gvrvi5dhp1vbkfxrmyf8yn3ajm1502 NarSize: 2561503 References: /private/var/tb/1/scratch/9b0bff5f52e90cd9/build/TestClientFallsBackToClosures2384456255/001/store/16qpflqkpqgmpakf5aqxc7x9764r55ad-shared-dep1504 CA: text:sha256:1dqlmjrnswxk62rv9yjcybhjnp371yghzgiph70c2nsk8nr96pkl15052026/10/25 17:19:17 INFO Starting HTTP server address=127.0.0.1:5276415062026/10/25 17:19:17 INFO Shutdown signal received, draining in-flight requests timeout=10s1507--- PASS: TestClientFallsBackToClosures (7.29s)1508=== CONT TestService_AuthMiddleware_OIDC1509--- PASS: TestGracefulShutdownDrainsInflight (0.07s)1510=== CONT TestService_healthCheckHandler15112026/10/25 17:19:17 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:52767/oidc15122026/10/25 17:19:17 INFO Received uploads request method=POST path=/api/pending_closures15132026/10/25 17:19:17 INFO Aborted multipart uploads count=0 kept=01514--- PASS: TestReadProxyOutlastsServerWriteTimeout (10.14s)1515=== CONT TestCreatePin_ReservedPins15162026/10/25 17:19:17 WARN Force mode enabled - objects will be deleted immediately without grace period15172026/10/25 17:19:17 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=015182026/10/25 17:19:17 INFO Vacuumed table table=pending_closures15192026/10/25 17:19:17 INFO Vacuumed table table=pending_objects15202026/10/25 17:19:17 INFO Vacuumed table table=multipart_uploads15212026/10/25 17:19:17 INFO Vacuumed table table=closures15222026/10/25 17:19:17 INFO Vacuumed table table=objects1523--- PASS: TestGCSweepSkipsPendingObjects (7.03s)1524=== CONT TestPresentRefreshesOnlyStaleClosures15252026/10/25 17:19:17 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:52772/oidc15262026/10/25 17:19:17 INFO Received push request method=POST path=/api/pushes15272026/10/25 17:19:17 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)15282026/10/25 17:19:17 INFO Uploading 8bmkfvpgcdqbaxagvzll8h1mkjjhr07r-shared-dep (136B)15292026/10/25 17:19:17 INFO Uploading x4ynr3k90gynmjj4drzvx1y0lxcws1hg-b (256B)15302026/10/25 17:19:18 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"15312026/10/25 17:19:18 WARN Failed to register uploaded object key=8bmkfvpgcdqbaxagvzll8h1mkjjhr07r.ls error="server returned 404: 404 page not found\n"15322026/10/25 17:19:18 WARN Failed to register uploaded object key=3y614k4g67hbg35i440hpf8wkbzxivyc.ls error="server returned 404: 404 page not found\n"15332026/10/25 17:19:18 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign15342026/10/25 17:19:18 WARN Failed to register uploaded object key=nar/0l09bjl7x7w29flpy91j1pyzhm7v1ca7yxb070sjgrb4yvd6x08i.nar.zst error="server returned 404: 404 page not found\n"15352026/10/25 17:19:18 WARN Failed to register uploaded object key=x4ynr3k90gynmjj4drzvx1y0lxcws1hg.ls error="server returned 404: 404 page not found\n"15362026/10/25 17:19:18 INFO Signed narinfos id=1 count=315372026/10/25 17:19:18 INFO Uploading 3 narinfos15382026/10/25 17:19:18 WARN Failed to register uploaded object key=8bmkfvpgcdqbaxagvzll8h1mkjjhr07r.narinfo error="server returned 404: 404 page not found\n"15392026/10/25 17:19:18 WARN Failed to register uploaded object key=x4ynr3k90gynmjj4drzvx1y0lxcws1hg.narinfo error="server returned 404: 404 page not found\n"15402026/10/25 17:19:18 INFO Received complete push request method=POST path=/api/pushes/1/complete15412026/10/25 17:19:18 WARN Failed to register uploaded object key=3y614k4g67hbg35i440hpf8wkbzxivyc.narinfo error="server returned 404: 404 page not found\n"15422026/10/25 17:19:18 INFO Completed push id=1 objects=8 duration=18.5315ms15432026/10/25 17:19:18 INFO Upload complete. (315ms)1544=== NAME TestClientPushesUseOnePush1545 client_pushes_test.go:97: Retrieved narinfo from S3:1546 StorePath: /private/var/tb/1/scratch/9b0bff5f52e90cd9/build/TestClientPushesUseOnePush4028541848/001/store/8bmkfvpgcdqbaxagvzll8h1mkjjhr07r-shared-dep1547 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1548 Compression: zstd1549 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821550 NarSize: 1361551 References: 1552 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1553 client_pushes_test.go:97: Retrieved narinfo from S3:1554 StorePath: /private/var/tb/1/scratch/9b0bff5f52e90cd9/build/TestClientPushesUseOnePush4028541848/001/store/3y614k4g67hbg35i440hpf8wkbzxivyc-a1555 URL: nar/0l09bjl7x7w29flpy91j1pyzhm7v1ca7yxb070sjgrb4yvd6x08i.nar.zst1556 Compression: zstd1557 NarHash: sha256:0l09bjl7x7w29flpy91j1pyzhm7v1ca7yxb070sjgrb4yvd6x08i1558 NarSize: 2561559 References: /private/var/tb/1/scratch/9b0bff5f52e90cd9/build/TestClientPushesUseOnePush4028541848/001/store/8bmkfvpgcdqbaxagvzll8h1mkjjhr07r-shared-dep1560 CA: text:sha256:1z651pvd5gx1f89fy6m24cdzr8975h27961a0ngcg0i1yll1lh7j1561 client_pushes_test.go:97: Retrieved narinfo from S3:1562 StorePath: /private/var/tb/1/scratch/9b0bff5f52e90cd9/build/TestClientPushesUseOnePush4028541848/001/store/x4ynr3k90gynmjj4drzvx1y0lxcws1hg-b1563 URL: nar/0l09bjl7x7w29flpy91j1pyzhm7v1ca7yxb070sjgrb4yvd6x08i.nar.zst1564 Compression: zstd1565 NarHash: sha256:0l09bjl7x7w29flpy91j1pyzhm7v1ca7yxb070sjgrb4yvd6x08i1566 NarSize: 2561567 References: /private/var/tb/1/scratch/9b0bff5f52e90cd9/build/TestClientPushesUseOnePush4028541848/001/store/8bmkfvpgcdqbaxagvzll8h1mkjjhr07r-shared-dep1568 CA: text:sha256:1z651pvd5gx1f89fy6m24cdzr8975h27961a0ngcg0i1yll1lh7j15692026/10/25 17:19:18 INFO Received uploads request method=POST path=/api/pending_closures1570--- PASS: TestClientPushesUseOnePush (7.67s)1571=== CONT TestPresentReportsOnlyClosureRoots1572--- PASS: TestDeduplicatedObjectsRecordedAsPending (6.64s)1573=== CONT TestService_AuthMiddleware_MTLSBoundSubjects1574=== NAME TestPinProtectsFromGC1575 client_integration_test.go:731: Pinned store path: /private/var/tb/1/scratch/9b0bff5f52e90cd9/build/TestPinProtectsFromGC1517031939/001/store/krfnb77p9h0aykmy9bmlqsacprrrrgc9-pinned-file.txt1576 client_integration_test.go:732: Unpinned store path: /private/var/tb/1/scratch/9b0bff5f52e90cd9/build/TestPinProtectsFromGC1517031939/001/store/fy2cf4gw90xfhyrg5dv0r034zjnas1jl-unpinned-file.txt15772026/10/25 17:19:18 INFO Aborted multipart uploads count=0 kept=015782026/10/25 17:19:18 INFO Received push request method=POST path=/api/pushes15792026/10/25 17:19:18 WARN Force mode enabled - objects will be deleted immediately without grace period15802026/10/25 17:19: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=015812026/10/25 17:19:18 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)15822026/10/25 17:19:18 INFO Uploading krfnb77p9h0aykmy9bmlqsacprrrrgc9-pinned-file.txt (128B)15832026/10/25 17:19:18 INFO Vacuumed table table=pending_closures15842026/10/25 17:19:18 INFO Vacuumed table table=pending_objects15852026/10/25 17:19:18 INFO Vacuumed table table=multipart_uploads15862026/10/25 17:19:18 INFO Vacuumed table table=closures15872026/10/25 17:19:18 INFO Vacuumed table table=objects1588--- PASS: TestGCMetrics (6.20s)1589=== CONT TestGCTaskStore_Fail1590--- PASS: TestGCTaskStore_Fail (0.00s)1591=== CONT TestOrphanedObjectsGC15922026/10/25 17:19:18 WARN Failed to register uploaded object key=nar/0qmhsg42pqsz7x6hh02j8gznnac3yi3qpjhrqbwvz88i194jbb5s.nar.zst error="server returned 404: 404 page not found\n"15932026/10/25 17:19:18 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign15942026/10/25 17:19:18 WARN Failed to register uploaded object key=krfnb77p9h0aykmy9bmlqsacprrrrgc9.ls error="server returned 404: 404 page not found\n"15952026/10/25 17:19:18 INFO Signed narinfos id=1 count=115962026/10/25 17:19:18 INFO Uploading 1 narinfos15972026/10/25 17:19:18 INFO Received complete push request method=POST path=/api/pushes/1/complete15982026/10/25 17:19:18 WARN Failed to register uploaded object key=krfnb77p9h0aykmy9bmlqsacprrrrgc9.narinfo error="server returned 404: 404 page not found\n"15992026/10/25 17:19:18 INFO Completed push id=1 objects=3 duration=13.822542ms16002026/10/25 17:19:18 INFO Upload complete. (222ms)16012026/10/25 17:19:18 INFO Received push request method=POST path=/api/pushes16022026/10/25 17:19:18 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)16032026/10/25 17:19:18 INFO Uploading fy2cf4gw90xfhyrg5dv0r034zjnas1jl-unpinned-file.txt (128B)16042026/10/25 17:19:18 INFO Received uploads request method=POST path=/api/pending_closures16052026/10/25 17:19:18 WARN Failed to register uploaded object key=fy2cf4gw90xfhyrg5dv0r034zjnas1jl.ls error="server returned 404: 404 page not found\n"16062026/10/25 17:19:18 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign16072026/10/25 17:19:18 WARN Failed to register uploaded object key=nar/0gh0wdnr6gmk4r5sfzzh12isnl14rgmkrwy1ws41hpsrlndclg5h.nar.zst error="server returned 404: 404 page not found\n"16082026/10/25 17:19:18 INFO Signed narinfos id=2 count=116092026/10/25 17:19:18 INFO Uploading 1 narinfos16102026/10/25 17:19:18 INFO Received complete push request method=POST path=/api/pushes/2/complete16112026/10/25 17:19:18 WARN Failed to register uploaded object key=fy2cf4gw90xfhyrg5dv0r034zjnas1jl.narinfo error="server returned 404: 404 page not found\n"16122026/10/25 17:19:18 INFO Completed push id=2 objects=3 duration=1.222542ms16132026/10/25 17:19:18 INFO Upload complete. (227ms)16142026/10/25 17:19:18 INFO Starting cleanup of old closures method=DELETE path=/api/closures16152026/10/25 17:19:18 INFO Garbage collection started16162026/10/25 17:19:18 INFO Aborted multipart uploads count=0 kept=016172026/10/25 17:19:18 INFO Aborted multipart uploads count=0 kept=016182026/10/25 17:19:18 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=016192026/10/25 17:19:18 WARN Force mode enabled - objects will be deleted immediately without grace period16202026/10/25 17:19:18 INFO Vacuumed table table=pending_closures16212026/10/25 17:19:18 INFO Vacuumed table table=pending_objects16222026/10/25 17:19:18 INFO Vacuumed table table=multipart_uploads16232026/10/25 17:19:18 INFO Vacuumed table table=closures16242026/10/25 17:19:18 INFO Vacuumed table table=objects16252026/10/25 17:19:18 INFO Aborted multipart uploads count=0 kept=016262026/10/25 17:19:18 WARN Force mode enabled - objects will be deleted immediately without grace period16272026/10/25 17:19: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=016282026/10/25 17:19:18 INFO Vacuumed table table=pending_closures16292026/10/25 17:19:18 INFO Vacuumed table table=pending_objects16302026/10/25 17:19:19 INFO Vacuumed table table=multipart_uploads16312026/10/25 17:19:19 INFO Vacuumed table table=closures16322026/10/25 17:19:19 INFO Vacuumed table table=objects1633--- PASS: TestPushDedupSurvivesConcurrentGC (6.88s)1634=== CONT TestObjectStatsUpdatedOncePerCommit16352026/10/25 17:19:19 ERROR failed to check GC advisory lock error="query pg_locks: failed to connect to `user=_tribuchetbld1 database=niks3`: /nonexistent/.s.PGSQL.5432 (/nonexistent): dial error: dial unix /nonexistent/.s.PGSQL.5432: connect: no such file or directory"1636--- PASS: TestGCAdvisoryLockBlocksConcurrentRun (6.52s)1637=== CONT TestOrphanedObjectsGCStressTest1638--- PASS: TestGCBugBareHashReferences (6.76s)1639=== CONT TestService_AuthMiddleware_MTLSProxyHeader16402026/10/25 17:19:19 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=1 objects-marked-for-deletion=3 objects-deleted-after-grace-period=3 objects-failed-to-delete=016412026/10/25 17:19:19 INFO Vacuumed table table=pending_closures16422026/10/25 17:19:19 INFO Vacuumed table table=pending_objects16432026/10/25 17:19:19 INFO Vacuumed table table=multipart_uploads16442026/10/25 17:19:19 INFO Vacuumed table table=closures16452026/10/25 17:19:19 INFO Vacuumed table table=objects16462026/10/25 17:19:19 INFO lead: acquired remote=192.0.2.1:123416472026/10/25 17:19:19 INFO lead: acquired remote=192.0.2.1:123416482026/10/25 17:19:19 INFO lead: released remote=192.0.2.1:12341649--- PASS: TestLeadIncumbentAnnouncesAtOnce (6.14s)1650=== CONT TestForceGCDuringPushOffersSweptObject/before_pending_rows1651--- PASS: TestCacheStatsHandler (5.27s)1652=== CONT TestForceGCDuringPushOffersSweptObject/after_presence_check1653--- PASS: TestService_ReadScope_PublicByDefault (5.20s)1654=== CONT TestServerTLSConfig/no_client_CA1655=== CONT TestServerTLSConfig/not_a_PEM_file1656=== CONT TestServerTLSConfig/missing_CA_file1657--- PASS: TestServerTLSConfig (0.00s)1658 --- PASS: TestServerTLSConfig/no_client_CA (0.00s)1659 --- PASS: TestServerTLSConfig/not_a_PEM_file (0.00s)1660 --- PASS: TestServerTLSConfig/missing_CA_file (0.00s)1661=== CONT TestGCEndsOnShutdown/before_the_run16622026/10/25 17:19:20 INFO lead: released remote=192.0.2.1:12341663--- PASS: TestLeadEndsOnShutdown (7.26s)1664=== CONT TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark16652026/10/25 17:19:20 INFO Received push request method=POST path=/api/pushes16662026/10/25 17:19:20 INFO Uploading 2 paths to 127.0.0.1 (0 already cached)16672026/10/25 17:19:20 INFO Uploading gmxgdzhq6a7nvrvsq5iw5m44k0b8m1yx-shared-dep (136B)16682026/10/25 17:19:20 INFO Uploading 06vvyzpfknl80k81941wm434awn8kvzh-top (264B)16692026/10/25 17:19:20 WARN Failed to register uploaded object key=gmxgdzhq6a7nvrvsq5iw5m44k0b8m1yx.ls error="server returned 404: 404 page not found\n"16702026/10/25 17:19:20 WARN Failed to register uploaded object key=06vvyzpfknl80k81941wm434awn8kvzh.ls error="server returned 404: 404 page not found\n"16712026/10/25 17:19:20 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"16722026/10/25 17:19:20 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign16732026/10/25 17:19:20 WARN Failed to register uploaded object key=nar/1v39a4xya0azh8b6jcrgzzl60fnx690ihfkw35h69jpl76vk9ca8.nar.zst error="server returned 404: 404 page not found\n"16742026/10/25 17:19:20 INFO Signed narinfos id=1 count=216752026/10/25 17:19:20 INFO Uploading 2 narinfos1676=== NAME TestClientMultipleUploads1677 client_integration_test.go:358: Created store path 0: /private/var/tb/1/scratch/9b0bff5f52e90cd9/build/TestClientMultipleUploads650379873/001/store/4dmlciiyk18gpiz9hbvxy56sdk4wghbh-test-file-0.txt16782026/10/25 17:19:20 WARN Failed to register uploaded object key=06vvyzpfknl80k81941wm434awn8kvzh.narinfo error="server returned 404: 404 page not found\n"16792026/10/25 17:19:20 INFO Received complete push request method=POST path=/api/pushes/1/complete16802026/10/25 17:19:20 WARN Failed to register uploaded object key=gmxgdzhq6a7nvrvsq5iw5m44k0b8m1yx.narinfo error="server returned 404: 404 page not found\n"1681=== NAME TestClientWithDependencies1682 client_integration_test.go:613: Built derivation: /private/var/tb/1/scratch/9b0bff5f52e90cd9/build/TestClientWithDependencies1217592815/001/store/08d06s41fj5rma1s5ylwc726yrnqfdwk-test-script16832026/10/25 17:19:20 INFO Completed push id=1 objects=6 duration=12.149417ms16842026/10/25 17:19:20 INFO Upload complete. (283ms)1685=== NAME TestClientSharedPathCommittedMidPush1686 client_integration_test.go:680: Retrieved narinfo from S3:1687 StorePath: /private/var/tb/1/scratch/9b0bff5f52e90cd9/build/TestClientSharedPathCommittedMidPush81717741/001/store/gmxgdzhq6a7nvrvsq5iw5m44k0b8m1yx-shared-dep1688 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1689 Compression: zstd1690 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821691 NarSize: 1361692 References: 1693 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1694 client_integration_test.go:680: Retrieved narinfo from S3:1695 StorePath: /private/var/tb/1/scratch/9b0bff5f52e90cd9/build/TestClientSharedPathCommittedMidPush81717741/001/store/06vvyzpfknl80k81941wm434awn8kvzh-top1696 URL: nar/1v39a4xya0azh8b6jcrgzzl60fnx690ihfkw35h69jpl76vk9ca8.nar.zst1697 Compression: zstd1698 NarHash: sha256:1v39a4xya0azh8b6jcrgzzl60fnx690ihfkw35h69jpl76vk9ca81699 NarSize: 2641700 References: /private/var/tb/1/scratch/9b0bff5f52e90cd9/build/TestClientSharedPathCommittedMidPush81717741/001/store/gmxgdzhq6a7nvrvsq5iw5m44k0b8m1yx-shared-dep1701 CA: text:sha256:1z84b326nrwp1q9wj1z9107zdnl6a8kkbs0fp2pl9hrqgbg5xhbj1702--- PASS: TestClientSharedPathCommittedMidPush (5.93s)1703=== CONT TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete1704=== NAME TestClientWithDependencies1705 client_integration_test.go:615: Found 1 dependencies (including self)1706=== NAME TestClientMultipleUploads1707 client_integration_test.go:358: Created store path 1: /private/var/tb/1/scratch/9b0bff5f52e90cd9/build/TestClientMultipleUploads650379873/001/store/c6qrx1w0zhjy9r27s4r3nvxgajh8nv5r-test-file-1.txt1708 client_integration_test.go:358: Created store path 2: /private/var/tb/1/scratch/9b0bff5f52e90cd9/build/TestClientMultipleUploads650379873/001/store/154dv2jn5ixhd2pybnmf2wm8znxy2dq7-test-file-2.txt1709=== NAME TestClientIntegration1710 client_integration_test.go:286: Created store path: /private/var/tb/1/scratch/9b0bff5f52e90cd9/build/TestClientIntegration73353954/002/store/4kd4c11sac1mrcpjb46v1zng3d3iw3dy-test-file.txt17112026/10/25 17:19:20 INFO lead: acquired remote=192.0.2.1:123417122026/10/25 17:19:20 INFO Received push request method=POST path=/api/pushes17132026/10/25 17:19:20 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)17142026/10/25 17:19:20 INFO Uploading 08d06s41fj5rma1s5ylwc726yrnqfdwk-test-script (136B)17152026/10/25 17:19:20 WARN Failed to register uploaded object key=08d06s41fj5rma1s5ylwc726yrnqfdwk.ls error="server returned 404: 404 page not found\n"17162026/10/25 17:19:20 WARN Failed to register uploaded object key=nar/1s7yghixzpinyqm7g59kyn3sav81pmnsdi5v63m6x4r2vacy907j.nar.zst error="server returned 404: 404 page not found\n"17172026/10/25 17:19:20 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign17182026/10/25 17:19:20 WARN Failed to register uploaded object key=log/zfa2h23zvdn6d6z2hqvqshy6cvcaksag-test-script.drv error="server returned 404: 404 page not found\n"17192026/10/25 17:19:20 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=017202026/10/25 17:19:20 INFO Received push request method=POST path=/api/pushes17212026/10/25 17:19:20 INFO Received push request method=POST path=/api/pushes17222026/10/25 17:19:20 INFO Signed narinfos id=1 count=117232026/10/25 17:19:20 INFO Uploading 1 narinfos17242026/10/25 17:19:20 INFO Received create pin request method=POST path=/api/pins/myapp17252026/10/25 17:19:20 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)17262026/10/25 17:19:20 INFO Uploading 4kd4c11sac1mrcpjb46v1zng3d3iw3dy-test-file.txt (152B)17272026/10/25 17:19:20 INFO Uploading 3 paths to 127.0.0.1 (0 already cached)17282026/10/25 17:19:20 INFO Uploading c6qrx1w0zhjy9r27s4r3nvxgajh8nv5r-test-file-1.txt (160B)17292026/10/25 17:19:20 INFO Uploading 154dv2jn5ixhd2pybnmf2wm8znxy2dq7-test-file-2.txt (160B)17302026/10/25 17:19:20 INFO Uploading 4dmlciiyk18gpiz9hbvxy56sdk4wghbh-test-file-0.txt (160B)17312026/10/25 17:19:20 INFO Received complete push request method=POST path=/api/pushes/1/complete17322026/10/25 17:19:20 WARN Failed to register uploaded object key=08d06s41fj5rma1s5ylwc726yrnqfdwk.narinfo error="server returned 404: 404 page not found\n"17332026/10/25 17:19:20 INFO Created/updated pin name=myapp store_path=/private/var/tb/1/scratch/9b0bff5f52e90cd9/build/TestPinProtectsFromGC1517031939/001/store/krfnb77p9h0aykmy9bmlqsacprrrrgc9-pinned-file.txt narinfo_key=krfnb77p9h0aykmy9bmlqsacprrrrgc9.narinfo17342026/10/25 17:19:20 INFO Starting cleanup of old closures method=DELETE path=/api/closures17352026/10/25 17:19:20 INFO Garbage collection started17362026/10/25 17:19:20 INFO Aborted multipart uploads count=0 kept=017372026/10/25 17:19:20 WARN Force mode enabled - objects will be deleted immediately without grace period17382026/10/25 17:19:20 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=017392026/10/25 17:19:20 INFO Completed push id=1 objects=4 duration=61.895292ms17402026/10/25 17:19:20 INFO Vacuumed table table=pending_closures17412026/10/25 17:19:20 INFO Upload complete. (305ms)17422026/10/25 17:19:20 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign1743=== NAME TestClientWithDependencies1744 client_integration_test.go:617: Skipping nix copy test - isolated store (/private/var/tb/1/scratch/9b0bff5f52e90cd9/build/TestClientWithDependencies1217592815/001/store) requires matching store prefix17452026/10/25 17:19:20 WARN Failed to register uploaded object key=c6qrx1w0zhjy9r27s4r3nvxgajh8nv5r.ls error="server returned 404: 404 page not found\n"17462026/10/25 17:19:20 WARN Failed to register uploaded object key=nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst error="server returned 404: 404 page not found\n"17472026/10/25 17:19:20 WARN Failed to register uploaded object key=4kd4c11sac1mrcpjb46v1zng3d3iw3dy.ls error="server returned 404: 404 page not found\n"17482026/10/25 17:19:20 INFO Vacuumed table table=pending_objects17492026/10/25 17:19:20 INFO Signed narinfos id=1 count=117502026/10/25 17:19:20 WARN Failed to register uploaded object key=154dv2jn5ixhd2pybnmf2wm8znxy2dq7.ls error="server returned 404: 404 page not found\n"17512026/10/25 17:19:20 WARN Failed to register uploaded object key=nar/0ahq3izw3h0b0c08p3xdfclh758fwxnp85ccvflasb4vnfsv50ri.nar.zst error="server returned 404: 404 page not found\n"17522026/10/25 17:19:20 WARN Failed to register uploaded object key=4dmlciiyk18gpiz9hbvxy56sdk4wghbh.ls error="server returned 404: 404 page not found\n"17532026/10/25 17:19:21 INFO Uploading 1 narinfos17542026/10/25 17:19:21 INFO Vacuumed table table=multipart_uploads17552026/10/25 17:19:21 INFO Vacuumed table table=closures17562026/10/25 17:19:21 WARN Failed to register uploaded object key=nar/1823g6vx4q5zqvr73m7lkq1wpk40fin7bsc792di430yk7sg4lka.nar.zst error="server returned 404: 404 page not found\n"17572026/10/25 17:19:21 INFO Vacuumed table table=objects17582026/10/25 17:19:21 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign17592026/10/25 17:19:21 WARN Failed to register uploaded object key=nar/13p9pqi0ga6fx2apcwls9hjnv7nmf740ggpn5zvfzdsp5vz2bbg4.nar.zst error="server returned 404: 404 page not found\n"17602026/10/25 17:19:21 INFO Signed narinfos id=1 count=317612026/10/25 17:19:21 INFO Uploading 3 narinfos17622026/10/25 17:19:21 INFO Received complete push request method=POST path=/api/pushes/1/complete17632026/10/25 17:19:21 WARN Failed to register uploaded object key=4kd4c11sac1mrcpjb46v1zng3d3iw3dy.narinfo error="server returned 404: 404 page not found\n"17642026/10/25 17:19:21 WARN Failed to register uploaded object key=c6qrx1w0zhjy9r27s4r3nvxgajh8nv5r.narinfo error="server returned 404: 404 page not found\n"17652026/10/25 17:19:21 INFO Completed push id=1 objects=3 duration=17.245ms17662026/10/25 17:19:21 INFO Upload complete. (300ms)17672026/10/25 17:19:21 WARN Failed to register uploaded object key=154dv2jn5ixhd2pybnmf2wm8znxy2dq7.narinfo error="server returned 404: 404 page not found\n"17682026/10/25 17:19:21 INFO Received complete push request method=POST path=/api/pushes/1/complete17692026/10/25 17:19:21 WARN Failed to register uploaded object key=4dmlciiyk18gpiz9hbvxy56sdk4wghbh.narinfo error="server returned 404: 404 page not found\n"1770--- PASS: TestClientWithDependencies (5.72s)1771=== CONT TestUploadHandlersRejectOversizedBody/create_pending_closure17722026/10/25 17:19:21 INFO Received uploads request method=POST path=/17732026/10/25 17:19:21 INFO Completed push id=1 objects=9 duration=13.615625ms17742026/10/25 17:19:21 INFO Upload complete. (329ms)1775=== NAME TestClientMultipleUploads1776 client_integration_test.go:369: Uploaded 3 paths in 401.179958ms1777--- PASS: TestClientMultipleUploads (5.26s)1778=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info17792026/10/25 17:19:21 INFO Received uploads request method=POST path=/1780=== CONT TestUploadHandlersRejectOversizedBody/request_more_parts17812026/10/25 17:19:21 INFO Received request for more parts method=POST path=/17822026/10/25 17:19:21 INFO All 1 paths already cached1783=== NAME TestClientIntegration1784 client_integration_test.go:312: Retrieved narinfo from S3:1785 StorePath: /private/var/tb/1/scratch/9b0bff5f52e90cd9/build/TestClientIntegration73353954/002/store/4kd4c11sac1mrcpjb46v1zng3d3iw3dy-test-file.txt1786 URL: nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst1787 Compression: zstd1788 NarHash: sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11789 NarSize: 1521790 References: 1791 CA: fixed:r:sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11792 client_integration_test.go:313: Retrieved .ls file from S3 (compressed size: 77 bytes)1793 client_integration_test.go:313: Decompressed .ls content (64 bytes):1794 {"version":1,"root":{"type":"regular","size":39,"narOffset":96}}1795 client_integration_test.go:316: Testing garbage collection...1796=== CONT TestUploadHandlersRejectOversizedBody/complete_multipart17972026/10/25 17:19:21 INFO Received complete multipart upload request method=POST path=/1798=== CONT TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key17992026/10/25 17:19:21 INFO Received complete multipart upload request method=POST path=/1800=== CONT TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key18012026/10/25 17:19:21 INFO Received request for more parts method=POST path=/1802=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal18032026/10/25 17:19:21 INFO Received uploads request method=POST path=/1804--- PASS: TestUploadHandlersRejectInvalidKeys (0.00s)1805 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info (0.00s)1806 --- PASS: TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key (0.00s)1807 --- PASS: TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key (0.00s)1808 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal (0.00s)1809=== CONT TestIsValidUploadKey/narinfo1810=== CONT TestIsValidUploadKey/realisation_plus_in_output1811=== CONT TestIsValidUploadKey/unknown_type1812=== CONT TestIsValidUploadKey/empty_key1813=== CONT TestIsValidUploadKey/absolute1814=== CONT TestIsValidUploadKey/traversal_nar1815=== CONT TestIsValidUploadKey/traversal1816=== CONT TestIsValidUploadKey/listing_key,_narinfo_type1817=== CONT TestIsValidUploadKey/nar_key,_narinfo_type1818=== CONT TestIsValidUploadKey/narinfo_key,_nar_type1819=== CONT TestIsValidUploadKey/index.html1820=== CONT TestIsValidUploadKey/nix-cache-info1821=== CONT TestIsValidUploadKey/build_log_home-manager_file1822=== CONT TestIsValidUploadKey/realisation1823=== CONT TestIsValidUploadKey/build_log_equals1824=== CONT TestIsValidUploadKey/build_log_question_mark1825=== CONT TestIsValidUploadKey/build_log_plus_in_name1826=== CONT TestIsValidUploadKey/nar_plain1827=== CONT TestIsValidUploadKey/build_log1828=== CONT TestIsValidUploadKey/listing1829=== CONT TestIsValidUploadKey/nar_xz1830=== CONT TestIsValidUploadKey/nar_zst1831--- PASS: TestIsValidUploadKey (0.02s)1832 --- PASS: TestIsValidUploadKey/narinfo (0.00s)1833 --- PASS: TestIsValidUploadKey/realisation_plus_in_output (0.00s)1834 --- PASS: TestIsValidUploadKey/unknown_type (0.00s)1835 --- PASS: TestIsValidUploadKey/empty_key (0.00s)1836 --- PASS: TestIsValidUploadKey/absolute (0.00s)1837 --- PASS: TestIsValidUploadKey/traversal_nar (0.00s)1838 --- PASS: TestIsValidUploadKey/traversal (0.00s)1839 --- PASS: TestIsValidUploadKey/listing_key,_narinfo_type (0.00s)1840 --- PASS: TestIsValidUploadKey/nar_key,_narinfo_type (0.00s)1841 --- PASS: TestIsValidUploadKey/narinfo_key,_nar_type (0.00s)1842 --- PASS: TestIsValidUploadKey/index.html (0.00s)1843 --- PASS: TestIsValidUploadKey/nix-cache-info (0.00s)1844 --- PASS: TestIsValidUploadKey/build_log_home-manager_file (0.00s)1845 --- PASS: TestIsValidUploadKey/realisation (0.00s)1846 --- PASS: TestIsValidUploadKey/build_log_equals (0.00s)1847 --- PASS: TestIsValidUploadKey/build_log_question_mark (0.00s)1848 --- PASS: TestIsValidUploadKey/build_log_plus_in_name (0.00s)1849 --- PASS: TestIsValidUploadKey/nar_plain (0.00s)1850 --- PASS: TestIsValidUploadKey/build_log (0.00s)1851 --- PASS: TestIsValidUploadKey/listing (0.00s)1852 --- PASS: TestIsValidUploadKey/nar_xz (0.00s)1853 --- PASS: TestIsValidUploadKey/nar_zst (0.00s)1854=== CONT TestPendingClosureWriteTimeout/empty1855=== CONT TestPendingClosureWriteTimeout/670k_objects1856=== CONT TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline18572026/10/25 17:19:21 INFO Starting cleanup of old closures method=DELETE path=/api/closures18582026/10/25 17:19:21 INFO Garbage collection started18592026/10/25 17:19:21 INFO Aborted multipart uploads count=0 kept=018602026/10/25 17:19:21 WARN Force mode enabled - objects will be deleted immediately without grace period1861--- PASS: TestService_ReadAuthMiddleware (4.81s)1862=== CONT TestPendingClosureWriteTimeout/400_objects1863=== CONT TestProxyWriteTimeout/narinfo1864=== CONT TestProxyWriteTimeout/10_GiB_nar1865=== CONT TestProxyWriteTimeout/unknown_size1866=== CONT TestProxyWriteTimeout/1_GiB_nar1867--- PASS: TestProxyWriteTimeout (0.01s)1868 --- PASS: TestProxyWriteTimeout/narinfo (0.00s)1869 --- PASS: TestProxyWriteTimeout/10_GiB_nar (0.00s)1870 --- PASS: TestProxyWriteTimeout/unknown_size (0.00s)1871 --- PASS: TestProxyWriteTimeout/1_GiB_nar (0.00s)1872=== CONT TestPresentNotReportedWhileGCDeletesClosure/stale1873=== CONT TestPresentNotReportedWhileGCDeletesClosure/fresh1874--- PASS: TestUploadHandlersRejectOversizedBody (0.05s)1875 --- PASS: TestUploadHandlersRejectOversizedBody/request_more_parts (0.03s)1876 --- PASS: TestUploadHandlersRejectOversizedBody/complete_multipart (0.03s)1877 --- PASS: TestUploadHandlersRejectOversizedBody/create_pending_closure (0.46s)18782026/10/25 17:19: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=018792026/10/25 17:19:21 INFO Vacuumed table table=pending_closures18802026/10/25 17:19:21 INFO Vacuumed table table=pending_objects18812026/10/25 17:19:21 INFO Vacuumed table table=multipart_uploads18822026/10/25 17:19:21 INFO Vacuumed table table=closures18832026/10/25 17:19:21 INFO Vacuumed table table=objects1884--- PASS: TestService_healthCheckHandler (4.30s)1885=== CONT TestIsValidCachePath/narinfo1886=== CONT TestIsValidCachePath/index.html1887=== CONT TestIsValidCachePath/short_hash1888=== CONT TestIsValidCachePath/wrong_extension1889=== CONT TestIsValidCachePath/leading_slash1890=== CONT TestIsValidCachePath/empty1891=== CONT TestIsValidCachePath/random_path1892=== CONT TestIsValidCachePath/invalid_char_u1893=== CONT TestIsValidCachePath/invalid_char_e1894=== CONT TestIsValidCachePath/traversal_in_middle1895=== CONT TestIsValidCachePath/traversal_parent1896=== CONT TestIsValidCachePath/nar_uncompressed1897=== CONT TestIsValidCachePath/nix-cache-info1898=== CONT TestIsValidCachePath/realisation1899=== CONT TestIsValidCachePath/log1900=== CONT TestIsValidCachePath/ls1901=== CONT TestIsValidCachePath/nar_xz1902=== CONT TestIsValidCachePath/nar_bz21903=== CONT TestIsValidCachePath/nar_zst1904=== CONT TestIsValidCachePath/narinfo_all_nix_base32_chars1905=== CONT TestParseSingleRange/none1906=== CONT TestParseSingleRange/open-ended1907--- PASS: TestIsValidCachePath (0.00s)1908 --- PASS: TestIsValidCachePath/narinfo (0.00s)1909 --- PASS: TestIsValidCachePath/index.html (0.00s)1910 --- PASS: TestIsValidCachePath/short_hash (0.00s)1911 --- PASS: TestIsValidCachePath/wrong_extension (0.00s)1912 --- PASS: TestIsValidCachePath/leading_slash (0.00s)1913 --- PASS: TestIsValidCachePath/empty (0.00s)1914 --- PASS: TestIsValidCachePath/random_path (0.00s)1915 --- PASS: TestIsValidCachePath/invalid_char_u (0.00s)1916 --- PASS: TestIsValidCachePath/invalid_char_e (0.00s)1917 --- PASS: TestIsValidCachePath/traversal_in_middle (0.00s)1918 --- PASS: TestIsValidCachePath/traversal_parent (0.00s)1919 --- PASS: TestIsValidCachePath/nar_uncompressed (0.00s)1920 --- PASS: TestIsValidCachePath/nix-cache-info (0.00s)1921 --- PASS: TestIsValidCachePath/realisation (0.00s)1922 --- PASS: TestIsValidCachePath/log (0.00s)1923 --- PASS: TestIsValidCachePath/ls (0.00s)1924 --- PASS: TestIsValidCachePath/nar_xz (0.00s)1925 --- PASS: TestIsValidCachePath/nar_bz2 (0.00s)1926 --- PASS: TestIsValidCachePath/nar_zst (0.00s)1927 --- PASS: TestIsValidCachePath/narinfo_all_nix_base32_chars (0.00s)1928=== CONT TestParseSingleRange/start_far_past_EOF1929=== CONT TestParseSingleRange/start_past_EOF1930=== CONT TestParseSingleRange/single_byte1931=== CONT TestParseSingleRange/suffix_exceeds_size1932=== CONT TestParseSingleRange/suffix1933=== CONT TestParseSingleRange/end_clamped_to_size1934=== CONT TestParseSingleRange/malformed_both_empty1935=== CONT TestParseSingleRange/closed1936=== CONT TestParseSingleRange/malformed_end_before_start1937=== CONT TestParseSingleRange/multi-range_ignored1938=== CONT TestParseSingleRange/malformed_no_dash1939=== CONT TestParseSingleRange/unknown_unit1940--- PASS: TestParseSingleRange (0.00s)1941 --- PASS: TestParseSingleRange/none (0.00s)1942 --- PASS: TestParseSingleRange/open-ended (0.00s)1943 --- PASS: TestParseSingleRange/start_far_past_EOF (0.00s)1944 --- PASS: TestParseSingleRange/start_past_EOF (0.00s)1945 --- PASS: TestParseSingleRange/single_byte (0.00s)1946 --- PASS: TestParseSingleRange/suffix_exceeds_size (0.00s)1947 --- PASS: TestParseSingleRange/suffix (0.00s)1948 --- PASS: TestParseSingleRange/end_clamped_to_size (0.00s)1949 --- PASS: TestParseSingleRange/malformed_both_empty (0.00s)1950 --- PASS: TestParseSingleRange/closed (0.00s)1951 --- PASS: TestParseSingleRange/malformed_end_before_start (0.00s)1952 --- PASS: TestParseSingleRange/multi-range_ignored (0.00s)1953 --- PASS: TestParseSingleRange/malformed_no_dash (0.00s)1954 --- PASS: TestParseSingleRange/unknown_unit (0.00s)1955=== CONT TestCacheConfigHandler/full_config,_no_issuer1956=== CONT TestCacheConfigHandler/no_signing_keys1957=== CONT TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1958=== CONT TestCacheConfigHandler/no_cache_url_configured1959--- PASS: TestCacheConfigHandler (0.02s)1960 --- PASS: TestCacheConfigHandler/full_config,_no_issuer (0.00s)1961 --- PASS: TestCacheConfigHandler/no_signing_keys (0.00s)1962 --- PASS: TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator (0.00s)1963 --- PASS: TestCacheConfigHandler/no_cache_url_configured (0.00s)1964=== CONT TestPush_RejectsBadRequests/no_objects19652026/10/25 17:19:21 INFO Received push request method=POST path=/api/pushes1966--- PASS: TestConcurrentCommitsSharingObjectsDoNotDeadlock (5.45s)1967=== CONT TestPush_RejectsBadRequests/root_not_in_objects1968=== CONT TestPush_RejectsBadRequests/no_roots19692026/10/25 17:19:21 INFO Received push request method=POST path=/api/pushes1970=== CONT TestPush_RejectsBadRequests/bad_root19712026/10/25 17:19:21 INFO Received push request method=POST path=/api/pushes1972=== CONT TestClientErrorHandling/InvalidStorePath19732026/10/25 17:19:21 INFO Received push request method=POST path=/api/pushes1974=== CONT TestClientErrorHandling/ServerNotAvailable1975--- PASS: TestPush_RejectsBadRequests (6.52s)1976 --- PASS: TestPush_RejectsBadRequests/no_objects (0.00s)1977 --- PASS: TestPush_RejectsBadRequests/root_not_in_objects (0.00s)1978 --- PASS: TestPush_RejectsBadRequests/no_roots (0.00s)1979 --- PASS: TestPush_RejectsBadRequests/bad_root (0.00s)19802026/10/25 17:19:21 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/present1981=== RUN TestService_AuthMiddleware_OIDC/valid_OIDC_token1982=== PAUSE TestService_AuthMiddleware_OIDC/valid_OIDC_token1983=== RUN TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1984=== PAUSE TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1985=== RUN TestService_AuthMiddleware_OIDC/malformed_token_rejected1986=== PAUSE TestService_AuthMiddleware_OIDC/malformed_token_rejected1987=== RUN TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1988=== PAUSE TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1989=== CONT TestClientErrorHandling/InvalidAuthToken19902026/10/25 17:19:21 INFO lead: released remote=192.0.2.1:123419912026/10/25 17:19:22 INFO lead: acquired remote=192.0.2.1:123419922026/10/25 17:19:22 WARN Request failed, retrying attempt=2 backoff=189.956997ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present19932026/10/25 17:19:22 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux19942026/10/25 17:19:22 WARN Refused reserved pin name=worker-x86_64-linux19952026/10/25 17:19:22 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux19962026/10/25 17:19:22 INFO Received create pin request method=POST path=/api/pins/my-app19972026/10/25 17:19:22 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux1998--- PASS: TestCreatePin_ReservedPins (4.42s)1999=== CONT TestService_RequireScope_OIDC/builder_may_write2000=== CONT TestService_RequireScope_OIDC/reader_may_read2001=== CONT TestService_RequireScope_OIDC/empty_netrc_password_may_not_read2002=== CONT TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read20032026/10/25 17:19:22 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]2004=== CONT TestService_RequireScope_OIDC/static_token_may_admin_with_netrc2005=== CONT TestService_RequireScope_OIDC/reader_may_read_with_netrc2006=== CONT TestService_RequireScope_OIDC/anonymous_may_not_read2007=== CONT TestService_RequireScope_OIDC/writer_implies_read2008=== CONT TestService_RequireScope_OIDC/reader_may_not_write2009=== CONT TestService_RequireScope_OIDC/static_token_may_write2010=== CONT TestService_RequireScope_OIDC/static_token_may_admin2011=== CONT TestService_RequireScope_OIDC/ops_may_admin2012=== CONT TestService_RequireScope_OIDC/ops_may_not_write2013=== CONT TestService_RequireScope_OIDC/builder_may_not_admin2014=== CONT TestResolveDBConnectionString/flag_wins2015=== CONT TestResolveDBConnectionString/missing_file_is_an_error2016=== CONT TestResolveDBConnectionString/file_when_flag_empty2017=== CONT TestResolveDBConnectionString/PGHOST_allows_empty2018=== CONT TestResolveDBConnectionString/nothing_configured2019--- PASS: TestService_RequireScope_OIDC (6.53s)2020 --- PASS: TestService_RequireScope_OIDC/builder_may_write (0.00s)2021 --- PASS: TestService_RequireScope_OIDC/reader_may_read (0.00s)2022 --- PASS: TestService_RequireScope_OIDC/empty_netrc_password_may_not_read (0.00s)2023 --- PASS: TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read (0.00s)2024 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin_with_netrc (0.00s)2025 --- PASS: TestService_RequireScope_OIDC/reader_may_read_with_netrc (0.00s)2026 --- PASS: TestService_RequireScope_OIDC/anonymous_may_not_read (0.00s)2027 --- PASS: TestService_RequireScope_OIDC/writer_implies_read (0.00s)2028 --- PASS: TestService_RequireScope_OIDC/reader_may_not_write (0.00s)2029 --- PASS: TestService_RequireScope_OIDC/static_token_may_write (0.00s)2030 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin (0.00s)2031 --- PASS: TestService_RequireScope_OIDC/ops_may_admin (0.00s)2032 --- PASS: TestService_RequireScope_OIDC/ops_may_not_write (0.00s)2033 --- PASS: TestService_RequireScope_OIDC/builder_may_not_admin (0.00s)2034=== CONT TestService_AuthMiddleware_OIDC/valid_OIDC_token2035=== CONT TestService_AuthMiddleware_OIDC/malformed_token_rejected20362026/10/25 17:19:22 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]2037=== CONT TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2038=== CONT TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected2039--- PASS: TestResolveDBConnectionString (0.01s)2040 --- PASS: TestResolveDBConnectionString/flag_wins (0.00s)2041 --- PASS: TestResolveDBConnectionString/missing_file_is_an_error (0.00s)2042 --- PASS: TestResolveDBConnectionString/file_when_flag_empty (0.00s)2043 --- PASS: TestResolveDBConnectionString/PGHOST_allows_empty (0.00s)2044 --- PASS: TestResolveDBConnectionString/nothing_configured (0.00s)20452026/10/25 17:19:22 WARN Authentication failed token_preview=eyJhbGciOi...EQQTi_ljPA token_length=701 oidc_error="no rule matched: claim \"repository_owner\" value [otherorg] not in allowed patterns [myorg]" oidc_provider=test tried_providers=[test]2046--- PASS: TestService_AuthMiddleware_OIDC (4.58s)2047 --- PASS: TestService_AuthMiddleware_OIDC/valid_OIDC_token (0.00s)2048 --- PASS: TestService_AuthMiddleware_OIDC/malformed_token_rejected (0.00s)2049 --- PASS: TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured (0.00s)2050 --- PASS: TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected (0.01s)20512026/10/25 17:19:22 WARN Request failed, retrying attempt=3 backoff=363.623022ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present2052--- PASS: TestPresentRefreshesOnlyStaleClosures (4.49s)20532026/10/25 17:19:22 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted,O=Other"20542026/10/25 17:19:22 WARN mTLS auth: bound subjects configured but subject DN unavailable20552026/10/25 17:19:22 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted"2056--- PASS: TestService_AuthMiddleware_MTLSBoundSubjects (4.26s)2057--- PASS: TestPresentReportsOnlyClosureRoots (4.41s)20582026/10/25 17:19:22 WARN Request failed, retrying attempt=4 backoff=841.015286ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present2059--- PASS: TestObjectStatsUpdatedOncePerCommit (3.84s)2060--- PASS: TestDeleteClosuresRacingPins (6.64s)2061=== NAME TestPinProtectsFromGC2062 client_integration_test.go:840: Pin successfully protected closure from garbage collection2063--- PASS: TestPinProtectsFromGC (12.06s)20642026/10/25 17:19:23 INFO lead: released remote=192.0.2.1:12342065--- PASS: TestLeadElectsOneAndHandsOver (6.96s)2066--- PASS: TestConnectWaitsForAPeerMigration (6.14s)2067--- PASS: TestService_AuthMiddleware_MTLSProxyHeader (4.13s)20682026/10/25 17:19:23 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=02069=== NAME TestClientIntegration2070 client_integration_test.go:323: Objects in database after GC:2071 client_integration_test.go:323: Successfully deleted all objects with GC --force2072--- PASS: TestClientIntegration (7.16s)20732026/10/25 17:19:23 WARN Request failed, retrying attempt=5 backoff=1.730886109s error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present20742026/10/25 17:19:23 INFO Received uploads request method=POST path=/api/pending_closures20752026/10/25 17:19:23 INFO Aborted multipart uploads count=0 kept=020762026/10/25 17:19:23 WARN Force mode enabled - objects will be deleted immediately without grace period20772026/10/25 17:19:23 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=020782026/10/25 17:19:23 INFO Vacuumed table table=pending_closures20792026/10/25 17:19:23 INFO Vacuumed table table=pending_objects20802026/10/25 17:19:23 INFO Vacuumed table table=multipart_uploads20812026/10/25 17:19:23 INFO Vacuumed table table=closures20822026/10/25 17:19:23 INFO Vacuumed table table=objects20832026/10/25 17:19:23 INFO Received uploads request method=POST path=/api/pending_closures20842026/10/25 17:19:23 INFO Aborted multipart uploads count=0 kept=020852026/10/25 17:19:23 WARN Force mode enabled - objects will be deleted immediately without grace period20862026/10/25 17:19:23 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=020872026/10/25 17:19:23 INFO Vacuumed table table=pending_closures20882026/10/25 17:19:23 INFO Vacuumed table table=pending_objects20892026/10/25 17:19:23 INFO Vacuumed table table=multipart_uploads20902026/10/25 17:19:23 INFO Vacuumed table table=closures20912026/10/25 17:19:23 INFO Vacuumed table table=objects2092--- PASS: TestForceGCDuringPushOffersSweptObject (0.00s)2093 --- PASS: TestForceGCDuringPushOffersSweptObject/before_pending_rows (4.48s)2094 --- PASS: TestForceGCDuringPushOffersSweptObject/after_presence_check (4.40s)2095=== NAME TestOrphanedObjectsGC2096 orphaned_objects_gc_test.go:287: GC Test Summary:2097 orphaned_objects_gc_test.go:288: - Kept: 2 objects from closure A2098 orphaned_objects_gc_test.go:289: - Deleted: 2 objects from closure B2099 orphaned_objects_gc_test.go:290: - Deleted: 6 orphaned chain objects (X1->X2->X3)2100 orphaned_objects_gc_test.go:291: - Deleted: 2 orphaned single objects (Y)2101 orphaned_objects_gc_test.go:292: - Total deleted: 10 objects2102--- PASS: TestOrphanedObjectsGC (5.80s)21032026/10/25 17:19:24 INFO Aborted multipart uploads count=0 kept=021042026/10/25 17:19:24 WARN Force mode enabled - objects will be deleted immediately without grace period21052026-10-25 17:19:24.414 UTC [47962] ERROR: canceling statement due to user request21062026-10-25 17:19:24.414 UTC [47962] STATEMENT: -- name: MarkStaleObjects :execrows2107 WITH RECURSIVE ct AS (2108 SELECT timezone('UTC', now()) AS now2109 ),2110 closure_reach AS (2111 -- Start with all closure keys2112 SELECT o.key, o.refs2113 FROM objects o2114 INNER JOIN closures c ON o.key = c.key2115 UNION2116 -- Recursively add all referenced objects2117 SELECT o.key, o.refs2118 FROM objects o2119 INNER JOIN closure_reach cr ON o.key = ANY(cr.refs)2120 ),2121 reachable_objects AS (2122 SELECT DISTINCT key FROM closure_reach2123 ),2124 stale_objects AS (2125 SELECT o.key2126 FROM objects AS o, ct2127 WHERE2128 NOT EXISTS (2129 SELECT 12130 FROM reachable_objects ro2131 WHERE ro.key = o.key2132 )2133 AND NOT EXISTS (2134 SELECT 12135 FROM pending_objects AS po2136 WHERE po.key = o.key2137 )2138 AND o.deleted_at IS NULL -- Only mark fresh objects2139 ORDER BY o.key COLLATE "C" -- lock in key order, like commit_pending_closure2140 FOR UPDATE2141 )2142 UPDATE objects2143 SET2144 deleted_at = ct.now,2145 first_deleted_at = COALESCE(first_deleted_at, ct.now)2146 FROM stale_objects, ct2147 WHERE objects.key = stale_objects.key2148 21492026/10/25 17:19:24 INFO Aborted multipart uploads count=0 kept=021502026/10/25 17:19:24 WARN Force mode enabled - objects will be deleted immediately without grace period21512026/10/25 17:19:24 ERROR failed to remove object object=nar/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa.nar.zst error="Post \"http://localhost:52480/bucket95/?delete=\": context canceled"2152--- PASS: TestGCEndsOnShutdown (0.00s)2153 --- PASS: TestGCEndsOnShutdown/before_the_run (4.47s)2154 --- PASS: TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark (4.09s)2155 --- PASS: TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete (4.06s)21562026/10/25 17:19:24 INFO Received uploads request method=POST path=/api/pending_closures21572026/10/25 17:19:25 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-config21582026/10/25 17:19:25 WARN Request failed, retrying attempt=2 backoff=188.000589ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21592026/10/25 17:19:25 WARN Request failed, retrying attempt=3 backoff=387.322223ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config2160--- PASS: TestPendingClosureWriteTimeout (0.00s)2161 --- PASS: TestPendingClosureWriteTimeout/empty (0.00s)2162 --- PASS: TestPendingClosureWriteTimeout/670k_objects (0.00s)2163 --- PASS: TestPendingClosureWriteTimeout/400_objects (0.00s)2164 --- PASS: TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline (4.42s)2165--- PASS: TestPresentNotReportedWhileGCDeletesClosure (0.00s)2166 --- PASS: TestPresentNotReportedWhileGCDeletesClosure/fresh (3.89s)2167 --- PASS: TestPresentNotReportedWhileGCDeletesClosure/stale (4.15s)21682026/10/25 17:19:25 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"21692026/10/25 17:19:25 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"21702026/10/25 17:19:25 WARN Request failed, retrying attempt=4 backoff=855.794288ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21712026/10/25 17:19:26 WARN Request failed, retrying attempt=5 backoff=1.533028233s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21722026/10/25 17:19:28 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"21732026/10/25 17:19:28 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-config21742026/10/25 17:19:28 WARN Request failed, retrying attempt=2 backoff=198.051823ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21752026/10/25 17:19:28 WARN Request failed, retrying attempt=3 backoff=433.026512ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config2176=== NAME TestOrphanedObjectsGCStressTest2177 orphaned_objects_gc_test.go:422: Created 10 active closures, 5 to-delete closures, 20 orphaned chains2178 orphaned_objects_gc_test.go:440: Marked 210 objects for deletion21792026/10/25 17:19:29 WARN Request failed, retrying attempt=4 backoff=773.667183ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21802026/10/25 17:19:29 WARN Request failed, retrying attempt=5 backoff=1.697793357s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21812026/10/25 17:19:31 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_closures21822026/10/25 17:19:31 WARN Request failed, retrying attempt=2 backoff=186.978603ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures21832026/10/25 17:19:31 WARN Request failed, retrying attempt=3 backoff=376.478823ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures21842026/10/25 17:19:32 WARN Request failed, retrying attempt=4 backoff=844.691401ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures21852026/10/25 17:19:33 WARN Request failed, retrying attempt=5 backoff=1.551488455s error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures2186--- PASS: TestClientErrorHandling (0.01s)2187 --- PASS: TestClientErrorHandling/InvalidStorePath (3.75s)2188 --- PASS: TestClientErrorHandling/InvalidAuthToken (3.94s)2189 --- PASS: TestClientErrorHandling/ServerNotAvailable (13.11s)2190=== NAME TestOrphanedObjectsGCStressTest2191 orphaned_objects_gc_test.go:503: Stress test completed successfully:2192 orphaned_objects_gc_test.go:504: - Active objects preserved: 202193 orphaned_objects_gc_test.go:505: - Objects deleted: 2102194 orphaned_objects_gc_test.go:506: - Total GC'd: 2102195--- PASS: TestOrphanedObjectsGCStressTest (18.37s)2196PASS2197{"timestamp":"2026-10-25T17:19:37.428782Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:52594","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)"}21982026-10-25 17:19:37.661 UTC [47310] LOG: received smart shutdown request21992026-10-25 17:19:37.663 UTC [47310] LOG: background worker "logical replication launcher" (PID 47320) exited with exit code 122002026-10-25 17:19:37.677 UTC [47315] LOG: shutting down22012026-10-25 17:19:37.678 UTC [47315] LOG: checkpoint starting: shutdown immediate22022026-10-25 17:19:40.748 UTC [47315] LOG: checkpoint complete: wrote 11484 buffers (70.1%), wrote 4 SLRU buffers; 0 WAL file(s) added, 0 removed, 31 recycled; write=1.384 s, sync=1.643 s, total=3.071 s; sync files=34044, longest=0.005 s, average=0.001 s; distance=501964 kB, estimate=501964 kB; lsn=0/201BFF58, redo lsn=0/201BFF5822032026-10-25 17:19:40.759 UTC [47310] LOG: database system is shut down2204Running OIDC tests...2205=== RUN TestAudienceForIssuer2206=== PAUSE TestAudienceForIssuer2207=== RUN TestGlobMatch2208=== PAUSE TestGlobMatch2209=== RUN TestValidateToken_ValidToken2210=== PAUSE TestValidateToken_ValidToken2211=== RUN TestValidateToken_WrongAudience2212=== PAUSE TestValidateToken_WrongAudience2213=== RUN TestValidateToken_Expired2214=== PAUSE TestValidateToken_Expired2215=== RUN TestValidateToken_BoundClaimsMismatch2216=== PAUSE TestValidateToken_BoundClaimsMismatch2217=== RUN TestValidateToken_BoundSubjectMismatch2218=== PAUSE TestValidateToken_BoundSubjectMismatch2219=== RUN TestValidateToken_MultipleProviders2220=== PAUSE TestValidateToken_MultipleProviders2221=== RUN TestValidateToken_NoMatchingProvider2222=== PAUSE TestValidateToken_NoMatchingProvider2223=== RUN TestValidateToken_KubernetesServiceAccount2224=== PAUSE TestValidateToken_KubernetesServiceAccount2225=== RUN TestNewValidator_KubernetesRequiresCA2226=== PAUSE TestNewValidator_KubernetesRequiresCA2227=== RUN TestValidateToken_KubernetesIssuerFromOwnToken2228=== PAUSE TestValidateToken_KubernetesIssuerFromOwnToken2229=== RUN TestPins_ReservedForMatchingRule2230=== PAUSE TestPins_ReservedForMatchingRule2231=== RUN TestPins_TopLevelShorthand2232=== PAUSE TestPins_TopLevelShorthand2233=== RUN TestPins_ConfigValidation2234=== PAUSE TestPins_ConfigValidation2235=== RUN TestScopes_LegacyProviderDefaultsToWrite2236=== PAUSE TestScopes_LegacyProviderDefaultsToWrite2237=== RUN TestScopes_Rules2238=== PAUSE TestScopes_Rules2239=== RUN TestScopes_ConfigValidation2240=== PAUSE TestScopes_ConfigValidation2241=== CONT TestAudienceForIssuer2242--- PASS: TestAudienceForIssuer (0.00s)2243=== CONT TestValidateToken_BoundClaimsMismatch2244=== CONT TestValidateToken_WrongAudience2245=== CONT TestValidateToken_ValidToken2246=== CONT TestGlobMatch2247=== RUN TestGlobMatch/foo_foo2248=== PAUSE TestGlobMatch/foo_foo2249=== CONT TestValidateToken_Expired2250=== CONT TestPins_ConfigValidation2251=== CONT TestScopes_ConfigValidation2252=== CONT TestScopes_Rules2253=== CONT TestScopes_LegacyProviderDefaultsToWrite2254=== CONT TestValidateToken_KubernetesServiceAccount2255--- PASS: TestPins_ConfigValidation (0.01s)2256=== CONT TestPins_ReservedForMatchingRule2257=== CONT TestValidateToken_KubernetesIssuerFromOwnToken2258=== CONT TestPins_TopLevelShorthand2259=== CONT TestNewValidator_KubernetesRequiresCA2260=== CONT TestValidateToken_MultipleProviders2261=== CONT TestValidateToken_NoMatchingProvider2262=== CONT TestValidateToken_BoundSubjectMismatch2263=== RUN TestGlobMatch/foo_bar2264=== PAUSE TestGlobMatch/foo_bar2265=== RUN TestGlobMatch/*_2266=== PAUSE TestGlobMatch/*_2267=== RUN TestGlobMatch/*_anything2268=== PAUSE TestGlobMatch/*_anything2269=== RUN TestGlobMatch/foo*_foo2270--- PASS: TestScopes_ConfigValidation (0.01s)2271=== PAUSE TestGlobMatch/foo*_foo2272=== RUN TestGlobMatch/foo*_foobar2273=== PAUSE TestGlobMatch/foo*_foobar2274=== RUN TestGlobMatch/foo*_bar2275=== PAUSE TestGlobMatch/foo*_bar2276=== RUN TestGlobMatch/*bar_bar2277=== PAUSE TestGlobMatch/*bar_bar2278=== RUN TestGlobMatch/*bar_foobar2279=== PAUSE TestGlobMatch/*bar_foobar2280=== RUN TestGlobMatch/*bar_foo2281=== PAUSE TestGlobMatch/*bar_foo2282=== RUN TestGlobMatch/foo*bar_foobar2283=== PAUSE TestGlobMatch/foo*bar_foobar2284=== RUN TestGlobMatch/foo*bar_foo123bar2285=== PAUSE TestGlobMatch/foo*bar_foo123bar2286=== RUN TestGlobMatch/foo*bar_foobarbaz2287=== PAUSE TestGlobMatch/foo*bar_foobarbaz2288=== RUN TestGlobMatch/*/*_foo/bar2289=== PAUSE TestGlobMatch/*/*_foo/bar2290=== RUN TestGlobMatch/*/*_foo2291=== PAUSE TestGlobMatch/*/*_foo2292=== RUN TestGlobMatch/refs/heads/*_refs/heads/main2293=== PAUSE TestGlobMatch/refs/heads/*_refs/heads/main2294=== RUN TestGlobMatch/refs/heads/*_refs/tags/v1.02295=== PAUSE TestGlobMatch/refs/heads/*_refs/tags/v1.02296=== RUN TestGlobMatch/refs/*/main_refs/heads/main2297=== PAUSE TestGlobMatch/refs/*/main_refs/heads/main2298=== RUN TestGlobMatch/fo?_foo2299=== PAUSE TestGlobMatch/fo?_foo2300=== RUN TestGlobMatch/fo?_fo2301=== PAUSE TestGlobMatch/fo?_fo2302=== RUN TestGlobMatch/fo?_fooo2303=== PAUSE TestGlobMatch/fo?_fooo2304=== RUN TestGlobMatch/?oo_foo2305=== PAUSE TestGlobMatch/?oo_foo2306=== RUN TestGlobMatch/?oo_boo2307=== PAUSE TestGlobMatch/?oo_boo2308=== RUN TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2309=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2310=== RUN TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2311=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2312=== CONT TestGlobMatch/foo_foo2313=== CONT TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2314=== CONT TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2315=== CONT TestGlobMatch/?oo_boo2316=== CONT TestGlobMatch/?oo_foo2317=== CONT TestGlobMatch/fo?_fooo2318=== CONT TestGlobMatch/fo?_fo2319=== CONT TestGlobMatch/fo?_foo2320=== CONT TestGlobMatch/refs/*/main_refs/heads/main2321=== CONT TestGlobMatch/refs/heads/*_refs/tags/v1.02322=== CONT TestGlobMatch/refs/heads/*_refs/heads/main2323=== CONT TestGlobMatch/*/*_foo2324=== CONT TestGlobMatch/*/*_foo/bar2325=== CONT TestGlobMatch/foo*bar_foobarbaz2326=== CONT TestGlobMatch/foo*bar_foo123bar2327=== CONT TestGlobMatch/foo*bar_foobar2328=== CONT TestGlobMatch/*bar_foo2329=== CONT TestGlobMatch/*bar_foobar2330=== CONT TestGlobMatch/*bar_bar2331=== CONT TestGlobMatch/foo*_bar2332=== CONT TestGlobMatch/foo*_foobar2333=== CONT TestGlobMatch/foo*_foo2334=== CONT TestGlobMatch/*_anything2335=== CONT TestGlobMatch/*_2336=== CONT TestGlobMatch/foo_bar2337--- PASS: TestGlobMatch (0.05s)2338 --- PASS: TestGlobMatch/foo_foo (0.00s)2339 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main (0.00s)2340 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main (0.00s)2341 --- PASS: TestGlobMatch/?oo_boo (0.00s)2342 --- PASS: TestGlobMatch/?oo_foo (0.00s)2343 --- PASS: TestGlobMatch/fo?_fooo (0.00s)2344 --- PASS: TestGlobMatch/fo?_fo (0.00s)2345 --- PASS: TestGlobMatch/fo?_foo (0.00s)2346 --- PASS: TestGlobMatch/refs/*/main_refs/heads/main (0.00s)2347 --- PASS: TestGlobMatch/refs/heads/*_refs/tags/v1.0 (0.00s)2348 --- PASS: TestGlobMatch/refs/heads/*_refs/heads/main (0.00s)2349 --- PASS: TestGlobMatch/*/*_foo (0.00s)2350 --- PASS: TestGlobMatch/*/*_foo/bar (0.00s)2351 --- PASS: TestGlobMatch/foo*bar_foobarbaz (0.00s)2352 --- PASS: TestGlobMatch/foo*bar_foo123bar (0.00s)2353 --- PASS: TestGlobMatch/foo*bar_foobar (0.00s)2354 --- PASS: TestGlobMatch/*bar_foo (0.00s)2355 --- PASS: TestGlobMatch/*bar_foobar (0.00s)2356 --- PASS: TestGlobMatch/*bar_bar (0.00s)2357 --- PASS: TestGlobMatch/foo*_bar (0.00s)2358 --- PASS: TestGlobMatch/foo*_foobar (0.00s)2359 --- PASS: TestGlobMatch/foo*_foo (0.00s)2360 --- PASS: TestGlobMatch/*_anything (0.00s)2361 --- PASS: TestGlobMatch/*_ (0.00s)2362 --- PASS: TestGlobMatch/foo_bar (0.00s)23632026/10/25 17:19:43 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:53032/oidc23642026/10/25 17:19:43 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:53033/oidc2365--- PASS: TestValidateToken_ValidToken (0.06s)2366--- PASS: TestValidateToken_BoundSubjectMismatch (0.03s)23672026/10/25 17:19:43 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:53036/oidc2368--- PASS: TestScopes_Rules (0.40s)23692026/10/25 17:19:43 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:53038/oidc23702026/10/25 17:19:44 INFO OIDC provider initialized name=kubernetes issuer=https://oidc.eks.invalid/id/ABC1232371--- PASS: TestValidateToken_Expired (0.85s)23722026/10/25 17:19:44 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:53041/oidc2373--- PASS: TestPins_TopLevelShorthand (0.87s)23742026/10/25 17:19:44 http: TLS handshake error from 127.0.0.1:53043: remote error: tls: bad certificate23752026/10/25 17:19:44 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:53047/oidc2376--- PASS: TestPins_ReservedForMatchingRule (0.96s)2377--- PASS: TestValidateToken_KubernetesIssuerFromOwnToken (0.97s)2378--- PASS: TestNewValidator_KubernetesRequiresCA (0.97s)23792026/10/25 17:19:44 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:53050/oidc2380--- PASS: TestValidateToken_WrongAudience (1.14s)23812026/10/25 17:19:44 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:53052/oidc23822026/10/25 17:19:44 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:53054/oidc2383--- PASS: TestValidateToken_BoundClaimsMismatch (1.14s)2384--- PASS: TestScopes_LegacyProviderDefaultsToWrite (1.14s)23852026/10/25 17:19:44 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:53049/oidc23862026/10/25 17:19:44 INFO OIDC provider initialized name=kubernetes issuer=https://127.0.0.1:5305623872026/10/25 17:19:44 INFO OIDC provider initialized name=provider2 issuer=http://127.0.0.1:53058/oidc2388--- PASS: TestValidateToken_KubernetesServiceAccount (1.27s)2389--- PASS: TestValidateToken_MultipleProviders (1.28s)23902026/10/25 17:19:44 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:53046/oidc2391--- PASS: TestValidateToken_NoMatchingProvider (1.30s)2392PASS2393Running hook tests...2394=== RUN TestSendPathsEmpty2395=== PAUSE TestSendPathsEmpty2396=== RUN TestQueueEnqueueAndFetch2397=== PAUSE TestQueueEnqueueAndFetch2398=== RUN TestQueueDeduplication2399=== PAUSE TestQueueDeduplication2400=== RUN TestQueueRemove2401=== PAUSE TestQueueRemove2402=== RUN TestQueueFetchBatchLimit2403=== PAUSE TestQueueFetchBatchLimit2404=== RUN TestQueueRetryMovesToBack2405=== PAUSE TestQueueRetryMovesToBack2406=== RUN TestQueueFetchRemoveLifecycle2407=== PAUSE TestQueueFetchRemoveLifecycle2408=== RUN TestQueueConcurrentWriters2409=== PAUSE TestQueueConcurrentWriters2410=== RUN TestQueueRemoveLargeClosure2411=== PAUSE TestQueueRemoveLargeClosure2412=== RUN TestServerClientIntegration2413--- PASS: TestServerClientIntegration (0.00s)2414=== RUN TestServerQueueError24152026/10/25 17:19:44 ERROR Failed to queue paths error="permission denied" count=12416--- PASS: TestServerQueueError (0.00s)2417=== RUN TestGetListenerSocketActivation2418 server_test.go:142: systemd socket activation does not exist on darwin2419--- SKIP: TestGetListenerSocketActivation (0.00s)2420=== RUN TestDrainIsolatesPoisonPath2421=== PAUSE TestDrainIsolatesPoisonPath2422=== RUN TestRunNotBlockedByPoisonHead2423=== PAUSE TestRunNotBlockedByPoisonHead2424=== RUN TestDrainGivesUpWhenServerDown2425=== PAUSE TestDrainGivesUpWhenServerDown2426=== RUN TestFailedPathPrunedByLaterClosure2427=== PAUSE TestFailedPathPrunedByLaterClosure2428=== RUN TestWorkerUploadsAndRemoves2429=== PAUSE TestWorkerUploadsAndRemoves2430=== RUN TestWorkerSkipsGCdPaths2431=== PAUSE TestWorkerSkipsGCdPaths2432=== RUN TestWorkerPrunesClosureDeps2433=== PAUSE TestWorkerPrunesClosureDeps2434=== RUN TestDrainTimeout2435=== PAUSE TestDrainTimeout2436=== RUN TestWorkerRemoveFailureIsNotProgress2437=== PAUSE TestWorkerRemoveFailureIsNotProgress2438=== RUN TestWorkerKeepsPathItCannotStat2439=== PAUSE TestWorkerKeepsPathItCannotStat2440=== CONT TestSendPathsEmpty2441=== CONT TestRunNotBlockedByPoisonHead2442--- PASS: TestSendPathsEmpty (0.00s)2443=== CONT TestDrainIsolatesPoisonPath2444=== CONT TestQueueRemoveLargeClosure2445=== CONT TestQueueConcurrentWriters2446=== CONT TestWorkerPrunesClosureDeps2447=== CONT TestQueueFetchRemoveLifecycle2448=== CONT TestWorkerKeepsPathItCannotStat2449=== CONT TestQueueRetryMovesToBack2450=== CONT TestWorkerRemoveFailureIsNotProgress2451=== CONT TestQueueFetchBatchLimit2452=== CONT TestDrainTimeout2453=== CONT TestQueueRemove2454=== CONT TestQueueDeduplication2455=== CONT TestQueueEnqueueAndFetch2456=== CONT TestWorkerSkipsGCdPaths2457=== CONT TestFailedPathPrunedByLaterClosure2458=== CONT TestDrainGivesUpWhenServerDown2459=== CONT TestWorkerUploadsAndRemoves24602026/10/25 17:19:44 INFO Uploading batch count=224612026/10/25 17:19:44 WARN Cannot stat store path, will retry later path=/private/var/tb/1/scratch/9b0bff5f52e90cd9/build/TestWorkerKeepsPathItCannotStat2543536137/002/locked/aaa error="stat /private/var/tb/1/scratch/9b0bff5f52e90cd9/build/TestWorkerKeepsPathItCannotStat2543536137/002/locked/aaa: permission denied"24622026/10/25 17:19:44 INFO Uploading batch count=124632026/10/25 17:19:44 ERROR Upload failed error="upload failed" count=124642026/10/25 17:19:44 WARN Cannot stat store path, will retry later path=/private/var/tb/1/scratch/9b0bff5f52e90cd9/build/TestWorkerKeepsPathItCannotStat2543536137/002/locked/aaa error="stat /private/var/tb/1/scratch/9b0bff5f52e90cd9/build/TestWorkerKeepsPathItCannotStat2543536137/002/locked/aaa: permission denied"24652026/10/25 17:19:44 INFO Uploading batch count=124662026/10/25 17:19:44 WARN Cannot stat store path, will retry later path=/private/var/tb/1/scratch/9b0bff5f52e90cd9/build/TestWorkerKeepsPathItCannotStat2543536137/002/locked/aaa error="stat /private/var/tb/1/scratch/9b0bff5f52e90cd9/build/TestWorkerKeepsPathItCannotStat2543536137/002/locked/aaa: permission denied"24672026/10/25 17:19:44 INFO Uploading batch count=124682026/10/25 17:19:44 INFO Upload queue status pending=224692026/10/25 17:19:44 INFO Uploading batch count=224702026/10/25 17:19:44 ERROR Upload failed error="upload failed" count=224712026/10/25 17:19:44 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/1/scratch/9b0bff5f52e90cd9/build/TestDrainGivesUpWhenServerDown2579943827/002/a24722026/10/25 17:19:44 WARN Store path no longer exists (garbage collected?), removing from queue path=/private/var/tb/1/scratch/9b0bff5f52e90cd9/build/TestWorkerSkipsGCdPaths3149148777/002/nonexistent2473--- PASS: TestQueueEnqueueAndFetch (0.01s)2474--- PASS: TestQueueFetchRemoveLifecycle (0.02s)24752026/10/25 17:19:44 INFO Uploading batch count=12476--- PASS: TestFailedPathPrunedByLaterClosure (0.01s)24772026/10/25 17:19:44 INFO Uploading batch count=424782026/10/25 17:19:44 ERROR Upload failed error="upload failed" count=42479--- PASS: TestQueueRemove (0.02s)24802026/10/25 17:19:44 ERROR Drain finished with paths left in queue remaining=124812026/10/25 17:19:44 WARN Store path no longer exists (garbage collected?), removing from queue path=/private/var/tb/1/scratch/9b0bff5f52e90cd9/build/TestWorkerRemoveFailureIsNotProgress3001932354/002/nonexistent2482--- PASS: TestQueueFetchBatchLimit (0.02s)24832026/10/25 17:19:44 INFO Upload queue status pending=224842026/10/25 17:19:44 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/1/scratch/9b0bff5f52e90cd9/build/TestDrainGivesUpWhenServerDown2579943827/002/b24852026/10/25 17:19:44 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/1/scratch/9b0bff5f52e90cd9/build/TestDrainIsolatesPoisonPath2251787639/002/bbb24862026/10/25 17:19:44 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=124872026/10/25 17:19:44 INFO Uploading batch count=124882026/10/25 17:19:44 INFO Upload queue status pending=224892026/10/25 17:19:44 WARN Store path no longer exists (garbage collected?), removing from queue path=/private/var/tb/1/scratch/9b0bff5f52e90cd9/build/TestWorkerRemoveFailureIsNotProgress3001932354/002/nonexistent24902026/10/25 17:19:44 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=124912026/10/25 17:19:44 WARN Store path no longer exists (garbage collected?), removing from queue path=/private/var/tb/1/scratch/9b0bff5f52e90cd9/build/TestWorkerRemoveFailureIsNotProgress3001932354/002/nonexistent24922026/10/25 17:19:44 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=124932026/10/25 17:19:44 ERROR Drain finished with paths left in queue remaining=124942026/10/25 17:19:44 INFO Uploading batch count=224952026/10/25 17:19:44 INFO Uploading batch count=224962026/10/25 17:19:44 ERROR Upload failed error="upload failed" count=224972026/10/25 17:19:44 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/1/scratch/9b0bff5f52e90cd9/build/TestDrainGivesUpWhenServerDown2579943827/002/c24982026/10/25 17:19:44 INFO Upload queue status pending=32499--- PASS: TestWorkerKeepsPathItCannotStat (0.02s)25002026/10/25 17:19:44 INFO Uploading batch count=125012026/10/25 17:19:44 INFO Uploading batch count=125022026/10/25 17:19:44 ERROR Upload failed error="upload failed" count=125032026/10/25 17:19:44 ERROR Upload failed error="upload failed" count=12504--- PASS: TestQueueDeduplication (0.02s)25052026/10/25 17:19:44 INFO Uploading batch count=125062026/10/25 17:19:44 ERROR Upload failed error="upload failed" count=125072026/10/25 17:19:44 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/1/scratch/9b0bff5f52e90cd9/build/TestDrainGivesUpWhenServerDown2579943827/002/d25082026/10/25 17:19:44 INFO Uploading batch count=125092026/10/25 17:19:44 ERROR Upload failed error="upload failed" count=125102026/10/25 17:19:44 INFO Uploading batch count=225112026/10/25 17:19:44 ERROR Upload failed error="upload failed" count=225122026/10/25 17:19:44 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/1/scratch/9b0bff5f52e90cd9/build/TestDrainGivesUpWhenServerDown2579943827/002/e2513--- PASS: TestWorkerRemoveFailureIsNotProgress (0.02s)2514--- PASS: TestQueueRetryMovesToBack (0.02s)25152026/10/25 17:19:44 ERROR Drain finished with paths left in queue remaining=125162026/10/25 17:19:44 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/1/scratch/9b0bff5f52e90cd9/build/TestDrainGivesUpWhenServerDown2579943827/002/f25172026/10/25 17:19:44 ERROR Drain finished with paths left in queue remaining=102518--- PASS: TestDrainIsolatesPoisonPath (0.02s)2519--- PASS: TestDrainGivesUpWhenServerDown (0.02s)2520--- PASS: TestWorkerSkipsGCdPaths (0.03s)2521--- PASS: TestWorkerPrunesClosureDeps (0.04s)2522--- PASS: TestWorkerUploadsAndRemoves (0.03s)2523--- PASS: TestQueueRemoveLargeClosure (0.06s)2524--- PASS: TestQueueConcurrentWriters (0.13s)25252026/10/25 17:19:45 ERROR Upload failed error="context deadline exceeded" count=225262026/10/25 17:19:45 ERROR Drain finished with paths left in queue remaining=42527--- PASS: TestDrainTimeout (0.21s)25282026/10/25 17:19:45 INFO Uploading batch count=125292026/10/25 17:19:45 INFO Uploading batch count=125302026/10/25 17:19:45 INFO Uploading batch count=125312026/10/25 17:19:45 ERROR Upload failed error="upload failed" count=125322026/10/25 17:19:45 INFO Uploading batch count=125332026/10/25 17:19:45 ERROR Upload failed error="upload failed" count=125342026/10/25 17:19:45 INFO Uploading batch count=125352026/10/25 17:19:45 ERROR Upload failed error="upload failed" count=125362026/10/25 17:19:45 INFO Uploading batch count=125372026/10/25 17:19:45 ERROR Upload failed error="upload failed" count=125382026/10/25 17:19:45 ERROR Drain finished with paths left in queue remaining=12539--- PASS: TestRunNotBlockedByPoisonHead (1.03s)2540PASS2541Running signing tests...2542=== RUN TestExternalSigner2543=== PAUSE TestExternalSigner2544=== RUN TestExternalSignerWrongPublicKey2545=== PAUSE TestExternalSignerWrongPublicKey2546=== RUN TestExternalSignerErrors2547=== PAUSE TestExternalSignerErrors2548=== RUN TestExternalSignerRestartsAfterCrash2549=== PAUSE TestExternalSignerRestartsAfterCrash2550=== RUN TestExternalSignerProgramErrorKeepsProcess2551=== PAUSE TestExternalSignerProgramErrorKeepsProcess2552=== RUN TestExternalSignerClose2553=== PAUSE TestExternalSignerClose2554=== RUN TestExternalSignerRejectsInvalidPublicKey2555=== PAUSE TestExternalSignerRejectsInvalidPublicKey2556=== RUN TestExternalSignerCancellation2557=== PAUSE TestExternalSignerCancellation2558=== RUN TestGenerateFingerprint2559=== PAUSE TestGenerateFingerprint2560=== RUN TestParseSigningKey2561=== PAUSE TestParseSigningKey2562=== RUN TestSign2563=== PAUSE TestSign2564=== RUN TestSignBatch2565=== PAUSE TestSignBatch2566=== RUN TestNilKeyPublicKey2567=== PAUSE TestNilKeyPublicKey2568=== RUN TestSignErrors2569=== PAUSE TestSignErrors2570=== CONT TestExternalSigner2571=== CONT TestExternalSignerCancellation2572=== CONT TestExternalSignerProgramErrorKeepsProcess2573=== CONT TestSignBatch2574=== CONT TestSignErrors2575=== CONT TestExternalSignerRejectsInvalidPublicKey2576=== CONT TestNilKeyPublicKey2577--- PASS: TestNilKeyPublicKey (0.00s)2578=== RUN TestExternalSignerRejectsInvalidPublicKey/#002579=== CONT TestExternalSignerClose2580=== CONT TestExternalSignerErrors2581=== RUN TestExternalSignerErrors/exit_at_startup2582=== PAUSE TestExternalSignerErrors/exit_at_startup2583=== RUN TestExternalSignerErrors/invalid_JSON2584=== PAUSE TestExternalSignerErrors/invalid_JSON2585=== RUN TestExternalSignerErrors/missing_signatures2586=== PAUSE TestExternalSignerErrors/missing_signatures2587=== RUN TestExternalSignerErrors/null_signatures2588=== PAUSE TestExternalSignerErrors/null_signatures2589=== RUN TestExternalSignerErrors/exit_on_request2590=== PAUSE TestExternalSignerErrors/exit_on_request2591=== RUN TestExternalSignerErrors/wrong_id2592=== PAUSE TestExternalSignerErrors/wrong_id2593=== RUN TestExternalSignerErrors/unrequested_key2594=== PAUSE TestExternalSignerErrors/unrequested_key2595=== RUN TestExternalSignerErrors/missing_signature_name2596=== PAUSE TestExternalSignerErrors/missing_signature_name2597=== RUN TestExternalSignerErrors/wrong_shape2598=== PAUSE TestExternalSignerErrors/wrong_shape2599=== RUN TestExternalSignerErrors/too_few_signatures2600=== PAUSE TestExternalSignerErrors/too_few_signatures2601=== RUN TestExternalSignerErrors/invalid_signature_base642602=== PAUSE TestExternalSignerErrors/invalid_signature_base642603=== RUN TestExternalSignerErrors/program_error2604=== CONT TestExternalSignerRestartsAfterCrash2605=== CONT TestExternalSignerWrongPublicKey2606=== CONT TestParseSigningKey2607=== RUN TestParseSigningKey/valid_32-byte_key2608=== CONT TestSign2609=== CONT TestGenerateFingerprint2610=== RUN TestGenerateFingerprint/basic_with_references2611=== PAUSE TestExternalSignerRejectsInvalidPublicKey/#002612=== PAUSE TestGenerateFingerprint/basic_with_references2613=== RUN TestGenerateFingerprint/no_references2614=== PAUSE TestGenerateFingerprint/no_references2615=== RUN TestExternalSignerRejectsInvalidPublicKey/no-colon2616=== PAUSE TestExternalSignerRejectsInvalidPublicKey/no-colon2617=== RUN TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2618=== PAUSE TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2619=== RUN TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2620=== PAUSE TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2621=== RUN TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2622=== PAUSE TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2623=== CONT TestExternalSignerRejectsInvalidPublicKey/#002624=== CONT TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2625=== RUN TestGenerateFingerprint/unsorted_references_get_sorted2626=== PAUSE TestGenerateFingerprint/unsorted_references_get_sorted2627=== RUN TestGenerateFingerprint/invalid_nar_hash_prefix2628=== CONT TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2629=== PAUSE TestGenerateFingerprint/invalid_nar_hash_prefix2630=== RUN TestGenerateFingerprint/invalid_nar_hash_length2631=== PAUSE TestParseSigningKey/valid_32-byte_key2632=== RUN TestParseSigningKey/valid_32-byte_key_with_different_name2633=== PAUSE TestParseSigningKey/valid_32-byte_key_with_different_name2634=== PAUSE TestExternalSignerErrors/program_error2635=== RUN TestParseSigningKey/no_colon2636=== RUN TestExternalSignerErrors/null2637=== PAUSE TestExternalSignerErrors/null2638=== CONT TestExternalSignerRejectsInvalidPublicKey/no-colon2639=== PAUSE TestGenerateFingerprint/invalid_nar_hash_length2640=== RUN TestGenerateFingerprint/invalid_store_path_prefix2641=== PAUSE TestGenerateFingerprint/invalid_store_path_prefix2642=== CONT TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2643=== RUN TestGenerateFingerprint/invalid_reference_prefix2644=== PAUSE TestGenerateFingerprint/invalid_reference_prefix2645=== CONT TestGenerateFingerprint/basic_with_references2646--- PASS: TestExternalSignerRejectsInvalidPublicKey (0.00s)2647 --- PASS: TestExternalSignerRejectsInvalidPublicKey/#00 (0.00s)2648 --- PASS: TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA= (0.00s)2649 --- PASS: TestExternalSignerRejectsInvalidPublicKey/test-key:invalid! (0.00s)2650 --- PASS: TestExternalSignerRejectsInvalidPublicKey/no-colon (0.00s)2651 --- PASS: TestExternalSignerRejectsInvalidPublicKey/test-key:YQ== (0.00s)2652=== CONT TestGenerateFingerprint/invalid_reference_prefix2653=== CONT TestGenerateFingerprint/invalid_store_path_prefix2654=== CONT TestGenerateFingerprint/invalid_nar_hash_length2655=== CONT TestGenerateFingerprint/invalid_nar_hash_prefix2656=== CONT TestGenerateFingerprint/unsorted_references_get_sorted2657=== CONT TestGenerateFingerprint/no_references2658--- PASS: TestGenerateFingerprint (0.00s)2659 --- PASS: TestGenerateFingerprint/basic_with_references (0.00s)2660 --- PASS: TestGenerateFingerprint/invalid_reference_prefix (0.00s)2661 --- PASS: TestGenerateFingerprint/invalid_store_path_prefix (0.00s)2662 --- PASS: TestGenerateFingerprint/invalid_nar_hash_length (0.00s)2663 --- PASS: TestGenerateFingerprint/invalid_nar_hash_prefix (0.00s)2664 --- PASS: TestGenerateFingerprint/unsorted_references_get_sorted (0.00s)2665 --- PASS: TestGenerateFingerprint/no_references (0.00s)2666=== RUN TestExternalSignerErrors/wrong_signatures_shape2667=== PAUSE TestExternalSignerErrors/wrong_signatures_shape2668=== RUN TestExternalSignerErrors/wrong_signature_name2669=== PAUSE TestExternalSignerErrors/wrong_signature_name2670=== RUN TestExternalSignerErrors/wrong_signature_length2671=== PAUSE TestExternalSignerErrors/wrong_signature_length2672=== CONT TestExternalSignerErrors/exit_at_startup2673=== CONT TestExternalSignerErrors/too_few_signatures2674=== CONT TestExternalSignerErrors/wrong_id2675=== CONT TestExternalSignerErrors/missing_signature_name2676=== CONT TestExternalSignerErrors/exit_on_request2677=== CONT TestExternalSignerErrors/unrequested_key2678=== CONT TestExternalSignerErrors/wrong_signatures_shape2679=== CONT TestExternalSignerErrors/missing_signatures2680=== CONT TestExternalSignerErrors/wrong_shape2681=== CONT TestExternalSignerErrors/invalid_JSON2682=== CONT TestExternalSignerErrors/null_signatures2683=== PAUSE TestParseSigningKey/no_colon2684=== RUN TestParseSigningKey/empty_name2685=== PAUSE TestParseSigningKey/empty_name2686=== RUN TestParseSigningKey/invalid_base642687=== PAUSE TestParseSigningKey/invalid_base642688=== RUN TestParseSigningKey/wrong_length2689=== PAUSE TestParseSigningKey/wrong_length2690=== CONT TestParseSigningKey/valid_32-byte_key2691=== CONT TestParseSigningKey/wrong_length2692=== CONT TestParseSigningKey/empty_name2693=== CONT TestParseSigningKey/no_colon2694=== CONT TestParseSigningKey/valid_32-byte_key_with_different_name2695=== RUN TestSignErrors/nil_key2696=== PAUSE TestSignErrors/nil_key2697=== RUN TestSignErrors/nil_narinfo2698=== PAUSE TestSignErrors/nil_narinfo2699=== RUN TestSignErrors/invalid_narinfo2700=== PAUSE TestSignErrors/invalid_narinfo2701=== RUN TestSignErrors/canceled2702=== PAUSE TestSignErrors/canceled2703=== CONT TestParseSigningKey/invalid_base642704--- PASS: TestParseSigningKey (0.00s)2705 --- PASS: TestParseSigningKey/valid_32-byte_key (0.00s)2706 --- PASS: TestParseSigningKey/wrong_length (0.00s)2707 --- PASS: TestParseSigningKey/empty_name (0.00s)2708 --- PASS: TestParseSigningKey/no_colon (0.00s)2709 --- PASS: TestParseSigningKey/valid_32-byte_key_with_different_name (0.00s)2710 --- PASS: TestParseSigningKey/invalid_base64 (0.00s)2711=== CONT TestExternalSignerErrors/invalid_signature_base642712--- PASS: TestSign (0.00s)2713=== CONT TestSignErrors/nil_key2714--- PASS: TestSignBatch (0.00s)2715=== CONT TestSignErrors/nil_narinfo2716=== CONT TestSignErrors/canceled2717=== CONT TestSignErrors/invalid_narinfo2718=== CONT TestExternalSignerErrors/wrong_signature_name2719=== CONT TestExternalSignerErrors/wrong_signature_length2720=== CONT TestExternalSignerErrors/program_error2721=== CONT TestExternalSignerErrors/null2722--- PASS: TestSignErrors (0.00s)2723 --- PASS: TestSignErrors/nil_key (0.00s)2724 --- PASS: TestSignErrors/nil_narinfo (0.00s)2725 --- PASS: TestSignErrors/canceled (0.00s)2726 --- PASS: TestSignErrors/invalid_narinfo (0.00s)2727--- PASS: TestExternalSigner (0.13s)2728--- PASS: TestExternalSignerWrongPublicKey (0.90s)2729--- PASS: TestExternalSignerCancellation (0.99s)2730--- PASS: TestExternalSignerClose (1.05s)2731--- PASS: TestExternalSignerProgramErrorKeepsProcess (1.22s)2732--- PASS: TestExternalSignerRestartsAfterCrash (1.59s)2733/private/var/tb/1/scratch/9b0bff5f52e90cd9/build/TestExternalSignerRestartsAfterCrash3486872035/001/sign program: line 7: /private/var/tb/1/scratch/9b0bff5f52e90cd9/build/TestExternalSignerRestartsAfterCrash3486872035/001/sign program.starts: No such file or directory2734--- PASS: TestExternalSignerErrors (0.00s)2735 --- PASS: TestExternalSignerErrors/null_signatures (0.19s)2736 --- PASS: TestExternalSignerErrors/missing_signature_name (0.28s)2737 --- PASS: TestExternalSignerErrors/missing_signatures (0.38s)2738 --- PASS: TestExternalSignerErrors/program_error (0.46s)2739 --- PASS: TestExternalSignerErrors/too_few_signatures (0.55s)2740 --- PASS: TestExternalSignerErrors/null (0.63s)2741 --- PASS: TestExternalSignerErrors/wrong_id (0.72s)2742 --- PASS: TestExternalSignerErrors/exit_at_startup (0.80s)2743 --- PASS: TestExternalSignerErrors/invalid_signature_base64 (1.13s)2744 --- PASS: TestExternalSignerErrors/wrong_signatures_shape (1.31s)2745 --- PASS: TestExternalSignerErrors/wrong_shape (1.38s)2746 --- PASS: TestExternalSignerErrors/exit_on_request (1.47s)2747 --- PASS: TestExternalSignerErrors/unrequested_key (1.64s)2748 --- PASS: TestExternalSignerErrors/invalid_JSON (1.72s)2749 --- PASS: TestExternalSignerErrors/wrong_signature_name (1.80s)2750 --- PASS: TestExternalSignerErrors/wrong_signature_length (1.88s)2751PASS2752Running OpenBao signer tests...2753=== RUN TestSign2754=== PAUSE TestSign2755=== RUN TestSignErrors2756=== PAUSE TestSignErrors2757=== RUN TestServe2758=== PAUSE TestServe2759=== RUN TestServeRejectsGarbage2760=== PAUSE TestServeRejectsGarbage2761=== CONT TestSign2762=== CONT TestSignErrors2763=== RUN TestSignErrors/http_error2764=== CONT TestServe2765=== CONT TestServeRejectsGarbage2766--- PASS: TestServeRejectsGarbage (0.00s)2767=== PAUSE TestSignErrors/http_error2768=== RUN TestSignErrors/invalid_json2769=== PAUSE TestSignErrors/invalid_json2770=== RUN TestSignErrors/no_prefix2771=== PAUSE TestSignErrors/no_prefix2772=== RUN TestSignErrors/invalid_base642773=== PAUSE TestSignErrors/invalid_base642774=== CONT TestSignErrors/http_error2775=== CONT TestSignErrors/no_prefix2776--- PASS: TestServe (0.00s)2777=== CONT TestSignErrors/invalid_base642778=== CONT TestSignErrors/invalid_json2779--- PASS: TestSign (0.00s)2780--- PASS: TestSignErrors (0.00s)2781 --- PASS: TestSignErrors/no_prefix (0.00s)2782 --- PASS: TestSignErrors/invalid_json (0.00s)2783 --- PASS: TestSignErrors/http_error (0.00s)2784 --- PASS: TestSignErrors/invalid_base64 (0.00s)2785PASS