niks3-go-unit-tests
checks.aarch64-darwin.go-unit-tests
· build #429
· 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.48s)27=== RUN TestDumpPathCaseHackCollision28--- PASS: TestDumpPathCaseHackCollision (0.01s)29=== RUN TestSupersededNARStillUploadsListing30=== PAUSE TestSupersededNARStillUploadsListing31=== RUN TestDumpPathMatchesNix32=== PAUSE TestDumpPathMatchesNix33=== RUN TestDumpPathSingleFile34=== PAUSE TestDumpPathSingleFile35=== RUN TestDumpPathWriterError36=== PAUSE TestDumpPathWriterError37=== RUN TestEncodeNixBase3238=== PAUSE TestEncodeNixBase3239=== RUN TestEncodeNixBase32WithRealHash40=== PAUSE TestEncodeNixBase32WithRealHash41=== RUN TestConvertHashToNix3242=== PAUSE TestConvertHashToNix3243=== RUN TestGetStorePathHash44=== PAUSE TestGetStorePathHash45=== RUN TestPathInfoHashCompatibility46=== PAUSE TestPathInfoHashCompatibility47=== RUN TestParsePathInfoJSON48=== PAUSE TestParsePathInfoJSON49=== RUN TestParsePathInfoJSONMultiplePaths50=== PAUSE TestParsePathInfoJSONMultiplePaths51=== RUN TestPathInfoCACompatibility52=== PAUSE TestPathInfoCACompatibility53=== RUN TestRateLimiterFeedback54=== PAUSE TestRateLimiterFeedback55=== RUN TestRateLimiterFeedback_400DoesNotCountAsSuccess56=== PAUSE TestRateLimiterFeedback_400DoesNotCountAsSuccess57=== RUN TestRegisterUploadedObject_BoundedAgainstSilentServer58=== PAUSE TestRegisterUploadedObject_BoundedAgainstSilentServer59=== RUN TestResolveStorePath60=== PAUSE TestResolveStorePath61=== RUN TestDoWithRetry_BodyReplayedViaGetBody62=== PAUSE TestDoWithRetry_BodyReplayedViaGetBody63=== RUN TestRetryTimeoutOutlastsMaxRetries64=== PAUSE TestRetryTimeoutOutlastsMaxRetries65=== RUN TestDoWithRetry_FinalResponseBodyReadable66=== PAUSE TestDoWithRetry_FinalResponseBodyReadable67=== RUN TestShellSplit68=== PAUSE TestShellSplit69=== RUN TestShellSplitErrors70=== PAUSE TestShellSplitErrors71=== RUN TestStreamPushReportsEveryPath72=== PAUSE TestStreamPushReportsEveryPath73=== RUN TestStreamPushBatchesUnderLoad74=== PAUSE TestStreamPushBatchesUnderLoad75=== RUN TestStreamPushIsolatesFailures76=== PAUSE TestStreamPushIsolatesFailures77=== RUN TestStreamPushGivesUpOnDeadServer78=== PAUSE TestStreamPushGivesUpOnDeadServer79=== RUN TestStreamPushRequestLine80=== PAUSE TestStreamPushRequestLine81=== RUN TestStreamPushReportsSignatures82=== PAUSE TestStreamPushReportsSignatures83=== RUN TestStreamPushReportsSkippedPaths84=== PAUSE TestStreamPushReportsSkippedPaths85=== RUN TestClientSignaturesByStorePath86=== PAUSE TestClientSignaturesByStorePath87=== RUN TestStreamPushStopsWhenCanceled88=== PAUSE TestStreamPushStopsWhenCanceled89=== RUN TestSetClientTLS90=== PAUSE TestSetClientTLS91=== RUN TestSetClientTLSDoesNotMutateDefaultTransport92=== PAUSE TestSetClientTLSDoesNotMutateDefaultTransport93=== RUN TestSetClientTLSErrors94=== PAUSE TestSetClientTLSErrors95=== RUN TestStaticToken96=== PAUSE TestStaticToken97=== RUN TestFileTokenReadsAndCaches98=== PAUSE TestFileTokenReadsAndCaches99=== RUN TestFileTokenMissing100=== PAUSE TestFileTokenMissing101=== RUN TestFileTokenEmpty102=== PAUSE TestFileTokenEmpty103=== RUN TestScriptTokenNoExpiryRerunsEveryCall104=== PAUSE TestScriptTokenNoExpiryRerunsEveryCall105=== RUN TestScriptTokenCachesUntilRefresh106=== PAUSE TestScriptTokenCachesUntilRefresh107=== RUN TestScriptTokenEmptyToken108=== PAUSE TestScriptTokenEmptyToken109=== RUN TestScriptTokenBadJSON110=== PAUSE TestScriptTokenBadJSON111=== RUN TestScriptTokenScriptFails112=== PAUSE TestScriptTokenScriptFails113=== RUN TestScriptTokenEmptyCommand114=== PAUSE TestScriptTokenEmptyCommand115=== CONT TestDoServerRequestAttachesToken116=== CONT TestDoWithRetry_BodyReplayedViaGetBody117=== CONT TestSetClientTLS118=== CONT TestScriptTokenEmptyCommand119--- PASS: TestScriptTokenEmptyCommand (0.00s)120=== CONT TestPathInfoCACompatibility121=== RUN TestPathInfoCACompatibility/null_ca_field122=== PAUSE TestPathInfoCACompatibility/null_ca_field123=== RUN TestPathInfoCACompatibility/old_string_format_-_text124=== PAUSE TestPathInfoCACompatibility/old_string_format_-_text125=== RUN TestPathInfoCACompatibility/old_string_format_-_fixed_recursive126=== PAUSE TestPathInfoCACompatibility/old_string_format_-_fixed_recursive127=== RUN TestPathInfoCACompatibility/new_structured_format_-_text128=== CONT TestScriptTokenScriptFails129=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_text130=== RUN TestPathInfoCACompatibility/new_structured_format_-_nar_method131=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_nar_method132=== CONT TestParsePathInfoJSONMultiplePaths133=== RUN TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths134=== PAUSE TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths135=== CONT TestScriptTokenBadJSON136=== CONT TestScriptTokenEmptyToken137=== CONT TestScriptTokenCachesUntilRefresh138=== CONT TestScriptTokenNoExpiryRerunsEveryCall139=== CONT TestFileTokenEmpty140=== CONT TestFileTokenMissing1412026/10/25 17:15:44 WARN Rate limiter enabled after throttle name=server-test rate=51422026/10/25 17:15:44 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:51181143=== CONT TestFileTokenReadsAndCaches144=== CONT TestStaticToken145=== CONT TestPartSizeForNAR146=== CONT TestSetClientTLSErrors147=== CONT TestSetClientTLSDoesNotMutateDefaultTransport148=== CONT TestUploadMultipart_PartsInParallel1492026/10/25 17:15:44 WARN Rate limiter backed off name=server-test rate=51502026/10/25 17:15:44 WARN Request returned retryable status, retrying attempt=2 backoff=0s status=503 url=http://127.0.0.1:51181151=== CONT TestDumpPathSingleFile152=== CONT TestDumpPathMatchesNix153=== CONT TestSupersededNARStillUploadsListing154=== RUN TestSupersededNARStillUploadsListing/small_NAR155=== PAUSE TestSupersededNARStillUploadsListing/small_NAR156=== CONT TestDumpPathWriterError157=== CONT TestResolveStorePath158=== CONT TestRegisterUploadedObject_BoundedAgainstSilentServer159=== CONT TestPathInfoHashCompatibility160=== CONT TestRateLimiterFeedback_400DoesNotCountAsSuccess161=== CONT TestRateLimiterFeedback162=== RUN TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths163--- PASS: TestDoServerRequestAttachesToken (0.00s)164=== CONT TestUploadMultipart_SupersededByPeer165=== CONT TestParsePathInfoJSON166=== RUN TestPartSizeForNAR/zero_stays_at_minimum167=== RUN TestSupersededNARStillUploadsListing/dump_cut_short168=== RUN TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)169--- PASS: TestScriptTokenScriptFails (0.01s)170--- PASS: TestStaticToken (0.00s)171--- PASS: TestDoWithRetry_BodyReplayedViaGetBody (0.01s)172--- PASS: TestFileTokenMissing (0.01s)173=== CONT TestUploadMultipart_FailedPartBufferNotReused174=== RUN TestSetClientTLSErrors/missing_cert_file1752026/10/25 17:15:44 WARN Rate limiter enabled after throttle name=server-test rate=5176=== PAUSE TestSetClientTLSErrors/missing_cert_file177=== PAUSE TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths178=== RUN TestRateLimiterFeedback/429_enables_limiter179=== PAUSE TestRateLimiterFeedback/429_enables_limiter180=== RUN TestRateLimiterFeedback/503_enables_limiter181=== PAUSE TestRateLimiterFeedback/503_enables_limiter182=== RUN TestRateLimiterFeedback/200_does_not_enable_limiter183=== PAUSE TestRateLimiterFeedback/200_does_not_enable_limiter184=== RUN TestRateLimiterFeedback/400_does_not_enable_limiter185=== PAUSE TestRateLimiterFeedback/400_does_not_enable_limiter186=== CONT TestGetStorePathHash187=== RUN TestGetStorePathHash/valid_store_path188=== PAUSE TestGetStorePathHash/valid_store_path189=== RUN TestGetStorePathHash/basename_without_hyphen_should_error190=== PAUSE TestGetStorePathHash/basename_without_hyphen_should_error191=== RUN TestGetStorePathHash/hash_with_invalid_characters_should_error192=== PAUSE TestGetStorePathHash/hash_with_invalid_characters_should_error193=== RUN TestGetStorePathHash/hash_with_wrong_length_should_error194=== PAUSE TestGetStorePathHash/hash_with_wrong_length_should_error195=== CONT TestEncodeNixBase32WithRealHash196--- PASS: TestEncodeNixBase32WithRealHash (0.00s)197=== CONT TestConvertHashToNix32198=== RUN TestConvertHashToNix32/SRI_format_to_Nix32199=== PAUSE TestConvertHashToNix32/SRI_format_to_Nix32200=== CONT TestEncodeNixBase32201=== RUN TestParsePathInfoJSON/Nix_format202=== PAUSE TestParsePathInfoJSON/Nix_format203=== PAUSE TestSupersededNARStillUploadsListing/dump_cut_short204=== PAUSE TestPartSizeForNAR/zero_stays_at_minimum205=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)206=== RUN TestSetClientTLSErrors/missing_key_file207=== RUN TestUploadMultipart_SupersededByPeer/exists208=== PAUSE TestSetClientTLSErrors/missing_key_file209=== RUN TestConvertHashToNix32/already_Nix32_format210=== RUN TestEncodeNixBase32/test_string_hash211=== RUN TestParsePathInfoJSON/Lix_format212=== RUN TestSupersededNARStillUploadsListing/listing_upload_fails213=== RUN TestPartSizeForNAR/small_stays_at_minimum214=== PAUSE TestParsePathInfoJSON/Lix_format215=== PAUSE TestEncodeNixBase32/test_string_hash216=== PAUSE TestConvertHashToNix32/already_Nix32_format217=== RUN TestPathInfoHashCompatibility/old_string_format_with_colon218=== RUN TestConvertHashToNix32/invalid_format219=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_colon220=== RUN TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI221=== RUN TestParsePathInfoJSON/empty_input222=== RUN TestEncodeNixBase32/empty_input223=== PAUSE TestEncodeNixBase32/empty_input224=== CONT TestStreamPushIsolatesFailures225=== PAUSE TestSupersededNARStillUploadsListing/listing_upload_fails226=== RUN TestSetClientTLSErrors/missing_ca_file227=== PAUSE TestSetClientTLSErrors/missing_ca_file228=== RUN TestSetClientTLSErrors/invalid_ca_file229=== PAUSE TestSetClientTLSErrors/invalid_ca_file230=== CONT TestShellSplitErrors231--- PASS: TestShellSplitErrors (0.00s)232=== CONT TestClientSignaturesByStorePath233--- PASS: TestClientSignaturesByStorePath (0.00s)234=== CONT TestStreamPushStopsWhenCanceled235=== PAUSE TestPartSizeForNAR/small_stays_at_minimum236=== CONT TestStreamPushBatchesUnderLoad2372026/10/25 17:15:44 ERROR Upload failed error="bad path" count=3238--- PASS: TestStreamPushStopsWhenCanceled (0.00s)239=== CONT TestStreamPushReportsSkippedPaths240--- PASS: TestStreamPushReportsSkippedPaths (0.00s)241=== CONT TestStreamPushReportsEveryPath242=== PAUSE TestConvertHashToNix32/invalid_format243=== RUN TestPartSizeForNAR/80_GiB_fits_at_minimum244=== PAUSE TestPartSizeForNAR/80_GiB_fits_at_minimum245--- PASS: TestStreamPushReportsEveryPath (0.00s)246=== CONT TestStreamPushReportsSignatures247=== CONT TestStreamPushGivesUpOnDeadServer248=== RUN TestPartSizeForNAR/115_GiB_needs_larger_parts249=== PAUSE TestPartSizeForNAR/115_GiB_needs_larger_parts250=== RUN TestPartSizeForNAR/1_TiB251=== PAUSE TestPartSizeForNAR/1_TiB252=== RUN TestPartSizeForNAR/5_TiB_S3_max_object253=== PAUSE TestPartSizeForNAR/5_TiB_S3_max_object254=== RUN TestPartSizeForNAR/capped_at_5_GiB255=== PAUSE TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI256=== PAUSE TestParsePathInfoJSON/empty_input257=== CONT TestStreamPushRequestLine258=== RUN TestParsePathInfoJSON/whitespace_only259=== PAUSE TestParsePathInfoJSON/whitespace_only260=== RUN TestParsePathInfoJSON/invalid_JSON261=== PAUSE TestParsePathInfoJSON/invalid_JSON262--- PASS: TestFileTokenReadsAndCaches (0.04s)263--- PASS: TestStreamPushIsolatesFailures (0.02s)264=== CONT TestRunGarbageCollection_NotFoundAfterLocalRun265=== PAUSE TestUploadMultipart_SupersededByPeer/exists266=== RUN TestUploadMultipart_SupersededByPeer/missing267=== PAUSE TestUploadMultipart_SupersededByPeer/missing268=== CONT TestRegisterUploadedObjectReusesConnections269--- PASS: TestScriptTokenBadJSON (0.04s)270=== CONT TestCaseHackSuffix271=== RUN TestSetClientTLS/rejects_connection_without_client_cert272=== PAUSE TestSetClientTLS/rejects_connection_without_client_cert273=== RUN TestSetClientTLS/succeeds_with_client_cert_and_CA274=== CONT TestRunGarbageCollection_FinishedOnAnotherReplica275=== CONT TestFilterOversizedClosures276=== RUN TestFilterOversizedClosures/no_limit_keeps_everything277=== PAUSE TestFilterOversizedClosures/no_limit_keeps_everything278=== RUN TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped279--- PASS: TestFileTokenEmpty (0.04s)280=== RUN TestPathInfoHashCompatibility/new_structured_format_with_sha512281=== PAUSE TestPathInfoHashCompatibility/new_structured_format_with_sha512282=== PAUSE TestSetClientTLS/succeeds_with_client_cert_and_CA283=== RUN TestSetClientTLS/preserves_debug_logging_transport284=== PAUSE TestSetClientTLS/preserves_debug_logging_transport285=== CONT TestDoWithRetry_FinalResponseBodyReadable286=== CONT TestShellSplit287--- PASS: TestShellSplit (0.00s)288=== CONT TestRetryTimeoutOutlastsMaxRetries289=== PAUSE TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped290=== RUN TestFilterOversizedClosures/all_closures_skipped291=== PAUSE TestFilterOversizedClosures/all_closures_skipped292=== PAUSE TestPartSizeForNAR/capped_at_5_GiB293=== CONT TestPathInfoCACompatibility/null_ca_field294=== CONT TestUploadBuildLog_FileBodyReplayedOnRetry295--- PASS: TestSetClientTLSDoesNotMutateDefaultTransport (0.04s)296=== CONT TestPathInfoCACompatibility/new_structured_format_-_text297--- PASS: TestResolveStorePath (0.04s)298=== CONT TestPathInfoCACompatibility/new_structured_format_-_nar_method299=== CONT TestPathInfoCACompatibility/old_string_format_-_fixed_recursive300=== CONT TestPathInfoCACompatibility/old_string_format_-_text301=== CONT TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths302=== CONT TestRateLimiterFeedback/429_enables_limiter303=== CONT TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths304--- PASS: TestParsePathInfoJSONMultiplePaths (0.02s)305 --- PASS: TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths (0.00s)306 --- PASS: TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths (0.00s)307=== CONT TestRateLimiterFeedback/200_does_not_enable_limiter3082026/10/25 17:15:44 WARN Rate limiter enabled after throttle name=s3-test rate=53092026/10/25 17:15:44 ERROR Upload failed error=boom count=1310--- PASS: TestStreamPushReportsSignatures (0.00s)311=== CONT TestRateLimiterFeedback/400_does_not_enable_limiter3122026/10/25 17:15:44 ERROR Upload failed error="connection refused" count=203132026/10/25 17:15:44 ERROR Server seems unavailable, giving up on batch untried=17314--- PASS: TestStreamPushGivesUpOnDeadServer (0.00s)315=== CONT TestRateLimiterFeedback/503_enables_limiter3162026/10/25 17:15:44 ERROR Upload failed error=boom count=1317--- PASS: TestPathInfoCACompatibility (0.00s)318 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_text (0.00s)319 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_nar_method (0.00s)320 --- PASS: TestPathInfoCACompatibility/old_string_format_-_fixed_recursive (0.00s)321 --- PASS: TestPathInfoCACompatibility/old_string_format_-_text (0.00s)322 --- PASS: TestPathInfoCACompatibility/null_ca_field (0.00s)323=== CONT TestGetStorePathHash/valid_store_path324=== CONT TestGetStorePathHash/hash_with_invalid_characters_should_error325=== CONT TestGetStorePathHash/hash_with_wrong_length_should_error326=== CONT TestGetStorePathHash/basename_without_hyphen_should_error327--- PASS: TestGetStorePathHash (0.00s)328 --- PASS: TestGetStorePathHash/valid_store_path (0.00s)329 --- PASS: TestGetStorePathHash/hash_with_invalid_characters_should_error (0.00s)330 --- PASS: TestGetStorePathHash/hash_with_wrong_length_should_error (0.00s)331 --- PASS: TestGetStorePathHash/basename_without_hyphen_should_error (0.00s)332=== CONT TestEncodeNixBase32/test_string_hash333=== CONT TestEncodeNixBase32/empty_input334--- PASS: TestEncodeNixBase32 (0.00s)335 --- PASS: TestEncodeNixBase32/test_string_hash (0.00s)336 --- PASS: TestEncodeNixBase32/empty_input (0.00s)337=== CONT TestSupersededNARStillUploadsListing/small_NAR338--- PASS: TestScriptTokenEmptyToken (0.05s)339=== CONT TestSetClientTLSErrors/missing_cert_file340=== CONT TestSupersededNARStillUploadsListing/listing_upload_fails3412026/10/25 17:15:44 INFO Uploading abc-hello (1.0GB)3422026/10/25 17:15:44 WARN Rate limiter enabled after throttle name=server-test rate=53432026/10/25 17:15:44 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:51236344=== CONT TestSupersededNARStillUploadsListing/dump_cut_short3452026/10/25 17:15:44 INFO Uploading abc-hello (1.0GB)3462026/10/25 17:15:44 WARN Rate limiter backed off name=server-test rate=5347=== CONT TestSetClientTLSErrors/missing_ca_file3482026/10/25 17:15:44 WARN Rate limiter enabled after throttle name=server-test rate=5349=== CONT TestSetClientTLSErrors/invalid_ca_file350=== CONT TestSetClientTLSErrors/missing_key_file351=== CONT TestConvertHashToNix32/SRI_format_to_Nix32352=== CONT TestConvertHashToNix32/already_Nix32_format353=== CONT TestConvertHashToNix32/invalid_format354--- PASS: TestConvertHashToNix32 (0.02s)355 --- PASS: TestConvertHashToNix32/SRI_format_to_Nix32 (0.00s)356 --- PASS: TestConvertHashToNix32/already_Nix32_format (0.00s)357 --- PASS: TestConvertHashToNix32/invalid_format (0.00s)358=== CONT TestParsePathInfoJSON/Nix_format359=== CONT TestParsePathInfoJSON/empty_input360=== CONT TestParsePathInfoJSON/invalid_JSON361=== CONT TestParsePathInfoJSON/whitespace_only362=== CONT TestParsePathInfoJSON/Lix_format363--- PASS: TestParsePathInfoJSON (0.03s)364 --- PASS: TestParsePathInfoJSON/Nix_format (0.00s)365 --- PASS: TestParsePathInfoJSON/empty_input (0.00s)366 --- PASS: TestParsePathInfoJSON/invalid_JSON (0.00s)367 --- PASS: TestParsePathInfoJSON/whitespace_only (0.00s)368 --- PASS: TestParsePathInfoJSON/Lix_format (0.00s)369=== CONT TestUploadMultipart_SupersededByPeer/exists3702026/10/25 17:15:44 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=429 url=http://127.0.0.1:512253712026/10/25 17:15:44 WARN Rate limiter enabled after throttle name=server-test rate=53722026/10/25 17:15:44 WARN Request returned retryable status, retrying attempt=1 backoff=1ms status=502 url=http://127.0.0.1:512143732026/10/25 17:15:44 INFO Garbage collection started3742026/10/25 17:15:44 INFO Garbage collection started3752026/10/25 17:15:44 WARN Rate limiter enabled after throttle name=s3-test rate=53762026/10/25 17:15:44 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:512633772026/10/25 17:15:44 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:512123782026/10/25 17:15:44 WARN Rate limiter backed off name=server-test rate=53792026/10/25 17:15:44 WARN Rate limiter backed off name=server-test rate=5380--- PASS: TestDoWithRetry_FinalResponseBodyReadable (0.02s)381=== CONT TestSetClientTLS/rejects_connection_without_client_cert382--- PASS: TestRateLimiterFeedback (0.00s)383 --- PASS: TestRateLimiterFeedback/200_does_not_enable_limiter (0.00s)384 --- PASS: TestRateLimiterFeedback/400_does_not_enable_limiter (0.01s)385 --- PASS: TestRateLimiterFeedback/503_enables_limiter (0.02s)386 --- PASS: TestRateLimiterFeedback/429_enables_limiter (0.02s)387=== CONT TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)388=== CONT TestPathInfoHashCompatibility/new_structured_format_with_sha512389=== CONT TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI390=== CONT TestPathInfoHashCompatibility/old_string_format_with_colon391=== CONT TestSetClientTLS/preserves_debug_logging_transport392--- PASS: TestPathInfoHashCompatibility (0.03s)393 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) (0.00s)394 --- PASS: TestPathInfoHashCompatibility/new_structured_format_with_sha512 (0.00s)395 --- PASS: TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI (0.00s)396 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_colon (0.00s)397=== CONT TestSetClientTLS/succeeds_with_client_cert_and_CA398--- PASS: TestSetClientTLSErrors (0.03s)399 --- PASS: TestSetClientTLSErrors/missing_cert_file (0.00s)400 --- PASS: TestSetClientTLSErrors/missing_ca_file (0.00s)401 --- PASS: TestSetClientTLSErrors/missing_key_file (0.00s)402 --- PASS: TestSetClientTLSErrors/invalid_ca_file (0.00s)4032026/10/25 17:15:44 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=04042026/10/25 17:15:44 WARN Request returned retryable status, retrying attempt=2 backoff=1ms status=502 url=http://127.0.0.1:51214405--- PASS: TestStreamPushRequestLine (0.03s)406--- PASS: TestRunGarbageCollection_NotFoundAfterLocalRun (0.03s)407=== CONT TestFilterOversizedClosures/no_limit_keeps_everything408=== CONT TestUploadMultipart_SupersededByPeer/missing409=== CONT TestPartSizeForNAR/5_TiB_S3_max_object410--- PASS: TestUploadBuildLog_FileBodyReplayedOnRetry (0.03s)411=== CONT TestPartSizeForNAR/115_GiB_needs_larger_parts412=== CONT TestPartSizeForNAR/80_GiB_fits_at_minimum413=== CONT TestPartSizeForNAR/small_stays_at_minimum414=== CONT TestFilterOversizedClosures/all_closures_skipped4152026/10/25 17:15:44 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=50416=== CONT TestPartSizeForNAR/1_TiB417=== CONT TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped418=== CONT TestPartSizeForNAR/capped_at_5_GiB419=== CONT TestPartSizeForNAR/zero_stays_at_minimum420--- PASS: TestPartSizeForNAR (0.04s)421 --- PASS: TestPartSizeForNAR/5_TiB_S3_max_object (0.00s)422 --- PASS: TestPartSizeForNAR/115_GiB_needs_larger_parts (0.00s)423 --- PASS: TestPartSizeForNAR/80_GiB_fits_at_minimum (0.00s)424 --- PASS: TestPartSizeForNAR/small_stays_at_minimum (0.00s)425 --- PASS: TestPartSizeForNAR/1_TiB (0.00s)426 --- PASS: TestPartSizeForNAR/capped_at_5_GiB (0.00s)427 --- PASS: TestPartSizeForNAR/zero_stays_at_minimum (0.00s)4282026/10/25 17:15:44 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=2000429--- PASS: TestFilterOversizedClosures (0.00s)430 --- PASS: TestFilterOversizedClosures/no_limit_keeps_everything (0.00s)431 --- PASS: TestFilterOversizedClosures/all_closures_skipped (0.00s)432 --- PASS: TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped (0.00s)4332026/10/25 17:15:44 WARN Garbage collection finished on another replica. Its statistics are not available here434--- PASS: TestRunGarbageCollection_FinishedOnAnotherReplica (0.03s)435--- PASS: TestUploadMultipart_SupersededByPeer (0.03s)436 --- PASS: TestUploadMultipart_SupersededByPeer/exists (0.01s)437 --- PASS: TestUploadMultipart_SupersededByPeer/missing (0.00s)4382026/10/25 17:15:44 WARN Request returned retryable status, retrying attempt=1 backoff=1ms status=502 url=http://127.0.0.1:512144392026/10/25 17:15:44 WARN Request returned retryable status, retrying attempt=2 backoff=1ms status=502 url=http://127.0.0.1:512144402026/10/25 17:15:44 WARN Request returned retryable status, retrying attempt=3 backoff=1ms status=502 url=http://127.0.0.1:512144412026/10/25 17:15:44 WARN Request returned retryable status, retrying attempt=4 backoff=1ms status=502 url=http://127.0.0.1:51214442--- PASS: TestRegisterUploadedObjectReusesConnections (0.04s)4432026/10/25 17:15:44 WARN Request returned retryable status, retrying attempt=5 backoff=1ms status=502 url=http://127.0.0.1:512144442026/10/25 17:15:44 WARN Request returned retryable status, retrying attempt=6 backoff=1ms status=502 url=http://127.0.0.1:512144452026/10/25 17:15:44 http: TLS handshake error from 127.0.0.1:51292: read tcp 127.0.0.1:51200->127.0.0.1:51292: use of closed network connection4462026/10/25 17:15:44 WARN Request returned retryable status, retrying attempt=7 backoff=1ms status=502 url=http://127.0.0.1:512144472026/10/25 17:15:44 WARN Request returned retryable status, retrying attempt=8 backoff=1ms status=502 url=http://127.0.0.1:51214448--- PASS: TestSetClientTLS (0.06s)449 --- PASS: TestSetClientTLS/succeeds_with_client_cert_and_CA (0.01s)450 --- PASS: TestSetClientTLS/preserves_debug_logging_transport (0.01s)451 --- PASS: TestSetClientTLS/rejects_connection_without_client_cert (0.02s)4522026/10/25 17:15:44 WARN Request returned retryable status, retrying attempt=9 backoff=1ms status=502 url=http://127.0.0.1:512144532026/10/25 17:15:44 WARN Request returned retryable status, retrying attempt=10 backoff=1ms status=502 url=http://127.0.0.1:51214454--- PASS: TestScriptTokenCachesUntilRefresh (0.11s)455--- PASS: TestScriptTokenNoExpiryRerunsEveryCall (0.11s)4562026/10/25 17:15:44 WARN Request returned retryable status, retrying attempt=11 backoff=1ms status=502 url=http://127.0.0.1:512144572026/10/25 17:15:44 WARN Request returned retryable status, retrying attempt=12 backoff=1ms status=502 url=http://127.0.0.1:512144582026/10/25 17:15:44 WARN Request returned retryable status, retrying attempt=13 backoff=1ms status=502 url=http://127.0.0.1:512144592026/10/25 17:15:44 INFO Uploading abc-hello (1.0GB)4602026/10/25 17:15:44 WARN Request returned retryable status, retrying attempt=14 backoff=1ms status=502 url=http://127.0.0.1:51214461--- PASS: TestCaseHackSuffix (0.07s)462--- PASS: TestDumpPathSingleFile (0.10s)4632026/10/25 17:15:44 WARN Request returned retryable status, retrying attempt=15 backoff=1ms status=502 url=http://127.0.0.1:51214464--- PASS: TestStreamPushBatchesUnderLoad (0.10s)4652026/10/25 17:15:44 WARN Request failed, retrying attempt=1 backoff=100ms error="Put \"http://127.0.0.1:51265/part/2\": uploading part 1: server returned 404: no such upload\n" url=http://127.0.0.1:51265/part/24662026/10/25 17:15:44 ERROR Failed to close zstd encoder error="io: read/write on closed pipe"4672026/10/25 17:15:44 WARN Request returned retryable status, retrying attempt=16 backoff=1ms status=502 url=http://127.0.0.1:512144682026/10/25 17:15:44 WARN Request returned retryable status, retrying attempt=17 backoff=1ms status=502 url=http://127.0.0.1:51214469--- PASS: TestRetryTimeoutOutlastsMaxRetries (0.12s)470--- PASS: TestDumpPathMatchesNix (0.36s)471--- PASS: TestDumpPathWriterError (0.41s)472--- PASS: TestUploadMultipart_FailedPartBufferNotReused (0.58s)473--- PASS: TestSupersededNARStillUploadsListing (0.02s)474 --- PASS: TestSupersededNARStillUploadsListing/listing_upload_fails (0.02s)475 --- PASS: TestSupersededNARStillUploadsListing/small_NAR (0.03s)476 --- PASS: TestSupersededNARStillUploadsListing/dump_cut_short (0.58s)477--- PASS: TestUploadMultipart_PartsInParallel (0.63s)4782026/10/25 17:15:45 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:51185/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:51185/api/uploads/complete4792026/10/25 17:15:45 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"480--- PASS: TestRateLimiterFeedback_400DoesNotCountAsSuccess (1.00s)4812026/10/25 17:15:45 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:51185/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:51185/api/uploads/complete4822026/10/25 17:15:45 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"4832026/10/25 17:15:45 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:51185/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:51185/api/uploads/complete4842026/10/25 17:15:45 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"485--- PASS: TestRegisterUploadedObject_BoundedAgainstSilentServer (1.02s)486PASS487Running server tests...488The files belonging to this database system will be owned by user "_tribuchetbld4".489This user must also own the server process.490491The database cluster will be initialized with locale "C".492The default database encoding has accordingly been set to "SQL_ASCII".493The default text search configuration will be set to "english".494495Data page checksums are enabled.496497creating directory /private/var/tb/4/scratch/69a84526bfbe447a/build/postgres1342755018/data ... ok498creating subdirectories ... ok499selecting dynamic shared memory implementation ... posix500selecting default "max_connections" ... 100501selecting default "shared_buffers" ... 128MB502selecting default time zone ... UTC503creating configuration files ... ok504running bootstrap script ... ok505performing post-bootstrap initialization ... ok506syncing data to disk ... ok507508initdb: warning: enabling "trust" authentication for local connections509initdb: 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.510511Success. You can now start the database server using:512513 pg_ctl -D /private/var/tb/4/scratch/69a84526bfbe447a/build/postgres1342755018/data -l logfile start514515/private/var/tb/4/scratch/69a84526bfbe447a/build/postgres1342755018:5432 - no response5162026-10-25 17:15:51.263 UTC [38580] LOG: starting PostgreSQL 18.6 on aarch64-apple-darwin25.6.0, compiled by clang version 21.1.8, 64-bit5172026-10-25 17:15:51.271 UTC [38580] LOG: listening on Unix socket "/private/var/tb/4/scratch/69a84526bfbe447a/build/postgres1342755018/.s.PGSQL.5432"5182026-10-25 17:15:51.276 UTC [38587] LOG: database system was shut down at 2026-10-25 17:15:51 UTC5192026-10-25 17:15:51.284 UTC [38580] LOG: database system is ready to accept connections520/private/var/tb/4/scratch/69a84526bfbe447a/build/postgres1342755018:5432 - accepting connections521{"timestamp":"2026-10-25T17:15:51.638922Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"f23b97ac-a5fa-460e-a96b-299aff73ccbf","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":13,"result":"server_error","target":"rustfs::server::http","filename":"rustfs/src/server/layer.rs","line_number":502,"threadName":"rustfs-worker","threadId":"ThreadId(6)"}522{"timestamp":"2026-10-25T17:15:51.747679Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"385e4f5f-de09-4938-84c3-f13a062c03ea","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(8)"}523{"timestamp":"2026-10-25T17:15:51.851373Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"e999674b-bfac-4c57-a5f9-87362e582513","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(10)"}524{"timestamp":"2026-10-25T17:15:51.954794Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"58b5873d-8796-47ec-b188-7d8aa8ef26e4","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(10)"}525{"timestamp":"2026-10-25T17:15:52.05789Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"131b2fda-4520-4dd5-b448-692670f5d10d","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(11)"}526{"timestamp":"2026-10-25T17:15:52.160533Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"8bb386cb-7f88-4010-aaec-40bc4dcc8e7a","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(8)"}527=== RUN TestService_AuthMiddleware528=== PAUSE TestService_AuthMiddleware529=== RUN TestService_AuthMiddleware_MTLSProxyHeader530=== PAUSE TestService_AuthMiddleware_MTLSProxyHeader531=== RUN TestService_AuthMiddleware_MTLSBoundSubjects532=== PAUSE TestService_AuthMiddleware_MTLSBoundSubjects533=== RUN TestService_ReadAuthMiddleware534=== PAUSE TestService_ReadAuthMiddleware535=== RUN TestService_AuthMiddleware_OIDC536=== PAUSE TestService_AuthMiddleware_OIDC537=== RUN TestService_RequireScope_OIDC538=== PAUSE TestService_RequireScope_OIDC539=== RUN TestService_ReadScope_PublicByDefault540=== PAUSE TestService_ReadScope_PublicByDefault541=== RUN TestCacheConfigHandler542=== PAUSE TestCacheConfigHandler543=== RUN TestCacheStatsHandler544=== PAUSE TestCacheStatsHandler545=== RUN TestClientCADerivations546=== PAUSE TestClientCADerivations547=== RUN TestClientErrorHandling548=== PAUSE TestClientErrorHandling549=== RUN TestClientIntegration550=== PAUSE TestClientIntegration551=== RUN TestClientMultipleUploads552=== PAUSE TestClientMultipleUploads553=== RUN TestClientWithDependencies554=== PAUSE TestClientWithDependencies555=== RUN TestClientSharedPathCommittedMidPush556=== PAUSE TestClientSharedPathCommittedMidPush557=== RUN TestPinProtectsFromGC558=== PAUSE TestPinProtectsFromGC559=== RUN TestClientPushesUseOnePush560=== PAUSE TestClientPushesUseOnePush561=== RUN TestClientFallsBackToClosures562=== PAUSE TestClientFallsBackToClosures563=== RUN TestDeleteClosuresRacingPins564=== PAUSE TestDeleteClosuresRacingPins565=== RUN TestConcurrentCommitsSharingObjectsDoNotDeadlock566=== PAUSE TestConcurrentCommitsSharingObjectsDoNotDeadlock567=== RUN TestResolveDBConnectionString568=== PAUSE TestResolveDBConnectionString569=== RUN TestConnectWaitsForAPeerMigration570=== PAUSE TestConnectWaitsForAPeerMigration571=== RUN TestLeadElectsOneAndHandsOver572=== PAUSE TestLeadElectsOneAndHandsOver573=== RUN TestLeadIncumbentWinsAfterRestart5742026/10/25 17:15:55 INFO lead: acquired remote=192.0.2.1:12345752026/10/25 17:15:56 INFO lead: released remote=192.0.2.1:12345762026/10/25 17:15:56 INFO lead: acquired remote=192.0.2.1:12345772026/10/25 17:15:57 INFO lead: released remote=192.0.2.1:1234578--- PASS: TestLeadIncumbentWinsAfterRestart (4.88s)579=== RUN TestLeadIncumbentAnnouncesAtOnce580=== PAUSE TestLeadIncumbentAnnouncesAtOnce581=== RUN TestLeadEndsOnShutdown582=== PAUSE TestLeadEndsOnShutdown583=== RUN TestLeadEndsWhenItsConnectionHangs5842026/10/25 17:15:58 INFO lead: acquired remote=192.0.2.1:12345852026-10-25 17:15:59.568 UTC [38726] FATAL: terminating connection due to administrator command5862026/10/25 17:15:59 INFO lead: acquired remote=192.0.2.1:12345872026/10/25 17:16:00 WARN lead: lock connection lost error="timeout: context deadline exceeded"5882026/10/25 17:16:00 INFO lead: released remote=192.0.2.1:12345892026/10/25 17:16:00 INFO lead: released remote=192.0.2.1:1234590--- PASS: TestLeadEndsWhenItsConnectionHangs (3.81s)591=== RUN TestGCAdvisoryLockBlocksConcurrentRun592=== PAUSE TestGCAdvisoryLockBlocksConcurrentRun593=== RUN TestGCBugBareHashReferences594=== PAUSE TestGCBugBareHashReferences595=== RUN TestGCMetrics596=== PAUSE TestGCMetrics597=== RUN TestPushDedupSurvivesConcurrentGC598=== PAUSE TestPushDedupSurvivesConcurrentGC599=== RUN TestDeduplicatedObjectsRecordedAsPending600=== PAUSE TestDeduplicatedObjectsRecordedAsPending601=== RUN TestGCSweepSkipsPendingObjects602=== PAUSE TestGCSweepSkipsPendingObjects603=== RUN TestTombstonedObjectOfferedWithoutWaiting604=== PAUSE TestTombstonedObjectOfferedWithoutWaiting605=== RUN TestGCSweepDeliversEachKeyOnce606=== PAUSE TestGCSweepDeliversEachKeyOnce607=== RUN TestCreatePendingClosureVerifyS3FailureReleasesConnection608=== PAUSE TestCreatePendingClosureVerifyS3FailureReleasesConnection609=== RUN TestForceGCDuringPushOffersSweptObject610=== PAUSE TestForceGCDuringPushOffersSweptObject611=== RUN TestFailedS3DeleteKeepsTombstone612=== PAUSE TestFailedS3DeleteKeepsTombstone613=== RUN TestSweepSkipsRowsLockedByPush614=== PAUSE TestSweepSkipsRowsLockedByPush615=== RUN TestRegisterCompletedObjectNeedsPendingRow616=== PAUSE TestRegisterCompletedObjectNeedsPendingRow617=== RUN TestGetExistingObjectsLocksRows618=== PAUSE TestGetExistingObjectsLocksRows619=== RUN TestSweepRechecksPendingAfterLocking620=== PAUSE TestSweepRechecksPendingAfterLocking621=== RUN TestPushWaitsForSweepHoldingRow622=== PAUSE TestPushWaitsForSweepHoldingRow623=== RUN TestCommitRacingPendingCleanupKeepsObjects624=== PAUSE TestCommitRacingPendingCleanupKeepsObjects625=== RUN TestGCEndsOnShutdown626=== PAUSE TestGCEndsOnShutdown627=== RUN TestGCTaskStore_StartNew628=== PAUSE TestGCTaskStore_StartNew629=== RUN TestGCTaskStore_DeduplicateSameParams630=== PAUSE TestGCTaskStore_DeduplicateSameParams631=== RUN TestGCTaskStore_ConflictDifferentParams632=== PAUSE TestGCTaskStore_ConflictDifferentParams633=== RUN TestGCTaskStore_GetEmpty634=== PAUSE TestGCTaskStore_GetEmpty635=== RUN TestGCTaskStore_GetReturnsLatest636=== PAUSE TestGCTaskStore_GetReturnsLatest637=== RUN TestGCTaskStore_CompletedAllowsNewTask638=== PAUSE TestGCTaskStore_CompletedAllowsNewTask639=== RUN TestGCTaskStore_PhaseUpdates640=== PAUSE TestGCTaskStore_PhaseUpdates641=== RUN TestGCTaskStore_Fail642=== PAUSE TestGCTaskStore_Fail643=== RUN TestGracefulShutdownDrainsInflight644=== PAUSE TestGracefulShutdownDrainsInflight645=== RUN TestService_healthCheckHandler646=== PAUSE TestService_healthCheckHandler647=== RUN TestService_readinessHandler648=== PAUSE TestService_readinessHandler649=== RUN TestGenerateLandingPage650=== PAUSE TestGenerateLandingPage651=== RUN TestCacheConfigHandlerMaxNarSize652=== PAUSE TestCacheConfigHandlerMaxNarSize653=== RUN TestCreatePendingClosureRejectsOversizedNAR654=== PAUSE TestCreatePendingClosureRejectsOversizedNAR655=== RUN TestNARDeduplicationMetadataUploadBug656=== PAUSE TestNARDeduplicationMetadataUploadBug657=== RUN TestMetricsInventory658=== PAUSE TestMetricsInventory659=== RUN TestMetricsCommit660=== PAUSE TestMetricsCommit661=== RUN TestService_NativeMTLS662=== PAUSE TestService_NativeMTLS663=== RUN TestServerTLSConfig664=== PAUSE TestServerTLSConfig665=== RUN TestMultipartCleanup666=== PAUSE TestMultipartCleanup667=== RUN TestMultipartUploadAbortedWhenCancelledBeforeRecorded668=== PAUSE TestMultipartUploadAbortedWhenCancelledBeforeRecorded669=== RUN TestPendingCleanupUsesOneCutoff670=== PAUSE TestPendingCleanupUsesOneCutoff671=== RUN TestObjectStatsTrigger672=== PAUSE TestObjectStatsTrigger673=== RUN TestObjectStatsUpdatedOncePerCommit674=== PAUSE TestObjectStatsUpdatedOncePerCommit675=== RUN TestOrphanedObjectsGC676=== PAUSE TestOrphanedObjectsGC677=== RUN TestOrphanedObjectsGCStressTest678=== PAUSE TestOrphanedObjectsGCStressTest679=== RUN TestCreatePin_ReservedPins680=== PAUSE TestCreatePin_ReservedPins681=== RUN TestPresentReportsOnlyClosureRoots682=== PAUSE TestPresentReportsOnlyClosureRoots683=== RUN TestPresentRefreshesOnlyStaleClosures684=== PAUSE TestPresentRefreshesOnlyStaleClosures685=== RUN TestPresentNotReportedWhileGCDeletesClosure686=== PAUSE TestPresentNotReportedWhileGCDeletesClosure687=== RUN TestParseSingleRange688=== PAUSE TestParseSingleRange689=== RUN TestProxyHeadersOnlyTrustedOnSocket6902026/10/25 17:16:02 INFO Starting HTTP server address=proxy.sock6912026/10/25 17:16:02 INFO Starting HTTP server address=127.0.0.1:516266922026/10/25 17:16:02 WARN mTLS auth: subject not in bound subjects subject="CN=someone"6932026/10/25 17:16:02 INFO Shutdown signal received, draining in-flight requests timeout=10s694--- PASS: TestProxyHeadersOnlyTrustedOnSocket (1.09s)695=== RUN TestIsValidCachePath696=== PAUSE TestIsValidCachePath697=== RUN TestReadProxyNarinfo698=== PAUSE TestReadProxyNarinfo699=== RUN TestReadProxyNarinfoAlreadyDecompressed700=== PAUSE TestReadProxyNarinfoAlreadyDecompressed701=== RUN TestReadProxyContentNegotiation702=== PAUSE TestReadProxyContentNegotiation703=== RUN TestReadProxyNarStreaming704=== PAUSE TestReadProxyNarStreaming705=== RUN TestReadProxy404706=== PAUSE TestReadProxy404707=== RUN TestReadProxyInvalidPath708=== PAUSE TestReadProxyInvalidPath709=== RUN TestReadProxyHead710=== PAUSE TestReadProxyHead711=== RUN TestReadProxyOutlastsServerWriteTimeout712=== PAUSE TestReadProxyOutlastsServerWriteTimeout713=== RUN TestReadProxyConditionalGet714=== PAUSE TestReadProxyConditionalGet715=== RUN TestReadProxyRootRedirectsToIndexHTML716=== PAUSE TestReadProxyRootRedirectsToIndexHTML717=== RUN TestReadProxyDisabled718=== PAUSE TestReadProxyDisabled719=== RUN TestReadRedirectNar720=== PAUSE TestReadRedirectNar721=== RUN TestReadRedirectKeepsNarinfoProxied722=== PAUSE TestReadRedirectKeepsNarinfoProxied723=== RUN TestReadProxyRangeRequest724=== PAUSE TestReadProxyRangeRequest725=== RUN TestReadRedirectUsesPublicS3URL726=== PAUSE TestReadRedirectUsesPublicS3URL727=== RUN TestPush_OverlappingRootsStoreOneRowPerKey728=== PAUSE TestPush_OverlappingRootsStoreOneRowPerKey729=== RUN TestPush_CompleteCommitsEveryRoot730=== PAUSE TestPush_CompleteCommitsEveryRoot731=== RUN TestPush_RepeatedRootCommitsOnce732=== PAUSE TestPush_RepeatedRootCommitsOnce733=== RUN TestPush_CompleteWaitsForCleanupOfThePush734=== PAUSE TestPush_CompleteWaitsForCleanupOfThePush735=== RUN TestPush_RootsAreLockedInByteOrder736=== PAUSE TestPush_RootsAreLockedInByteOrder737=== RUN TestPush_SkippedKeySurvivesGCBeforeCommit738=== PAUSE TestPush_SkippedKeySurvivesGCBeforeCommit739=== RUN TestPush_RejectsBadRequests740=== PAUSE TestPush_RejectsBadRequests741=== RUN TestPush_SignsNarinfosOfItsPendingObjects742=== PAUSE TestPush_SignsNarinfosOfItsPendingObjects743=== RUN TestRedundantMultipartUpload744=== PAUSE TestRedundantMultipartUpload745=== RUN TestCompleteMultipartUpload_ErrorButObjectExists746=== PAUSE TestCompleteMultipartUpload_ErrorButObjectExists747=== RUN TestCompletedNarNotReofferedAcrossClosures748=== PAUSE TestCompletedNarNotReofferedAcrossClosures749=== RUN TestPresignedUploadRegisteredBeforeCommit750=== PAUSE TestPresignedUploadRegisteredBeforeCommit751=== RUN TestService_Rustfstest752=== PAUSE TestService_Rustfstest753=== RUN TestParseSize754=== PAUSE TestParseSize755=== RUN TestSkippedUploadsHandler756=== PAUSE TestSkippedUploadsHandler757=== RUN TestSystemdListenerNotActivated758--- PASS: TestSystemdListenerNotActivated (0.00s)759=== RUN TestWatchdogBeatsWhenHealthy760--- PASS: TestWatchdogBeatsWhenHealthy (0.04s)761=== RUN TestWatchdogSkipsWhenUnhealthy7622026/10/25 17:16:02 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7632026/10/25 17:16:02 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7642026/10/25 17:16:02 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7652026/10/25 17:16:02 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7662026/10/25 17:16:02 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7672026/10/25 17:16:02 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7682026/10/25 17:16:02 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7692026/10/25 17:16:02 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7702026/10/25 17:16:02 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7712026/10/25 17:16:02 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"772--- PASS: TestWatchdogSkipsWhenUnhealthy (0.20s)773=== RUN TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle774=== PAUSE TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle775=== RUN TestProxyWriteTimeout776=== PAUSE TestProxyWriteTimeout777=== RUN TestPendingClosureWriteTimeout778=== PAUSE TestPendingClosureWriteTimeout779=== RUN TestIsValidUploadKey780=== PAUSE TestIsValidUploadKey781=== RUN TestUploadHandlersRejectInvalidKeys782=== PAUSE TestUploadHandlersRejectInvalidKeys783=== RUN TestUploadHandlersRejectOversizedBody784=== PAUSE TestUploadHandlersRejectOversizedBody785=== RUN TestService_cleanupPendingClosuresHandler786=== PAUSE TestService_cleanupPendingClosuresHandler787=== RUN TestService_createPendingClosureHandler788=== PAUSE TestService_createPendingClosureHandler789=== RUN TestService_verifyS3Integrity790=== PAUSE TestService_verifyS3Integrity791=== RUN TestCompleteMultipartUnregistered792=== PAUSE TestCompleteMultipartUnregistered793=== RUN TestCreatePendingClosure_SmallNARUsesSimplePUT794=== PAUSE TestCreatePendingClosure_SmallNARUsesSimplePUT795=== CONT TestCompleteMultipartUnregistered796=== CONT TestService_AuthMiddleware797=== CONT TestCreatePendingClosure_SmallNARUsesSimplePUT798=== CONT TestNARDeduplicationMetadataUploadBug799=== CONT TestPushDedupSurvivesConcurrentGC800=== CONT TestCacheConfigHandlerMaxNarSize801=== CONT TestDeduplicatedObjectsRecordedAsPending802=== CONT TestService_verifyS3Integrity803=== CONT TestCreatePendingClosureRejectsOversizedNAR804--- PASS: TestCacheConfigHandlerMaxNarSize (0.00s)805=== CONT TestPush_SignsNarinfosOfItsPendingObjects806=== CONT TestService_cleanupPendingClosuresHandler807=== CONT TestUploadHandlersRejectOversizedBody8082026/10/25 17:16:02 INFO Received uploads request method=POST path=/api/pending_closures809=== CONT TestService_createPendingClosureHandler810=== CONT TestUploadHandlersRejectInvalidKeys811=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info812=== CONT TestIsValidUploadKey813=== CONT TestPendingClosureWriteTimeout814=== CONT TestProxyWriteTimeout815=== CONT TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle816=== CONT TestSkippedUploadsHandler817=== CONT TestParseSize818=== CONT TestService_Rustfstest819=== CONT TestPresignedUploadRegisteredBeforeCommit820=== CONT TestCompletedNarNotReofferedAcrossClosures821=== CONT TestCompleteMultipartUpload_ErrorButObjectExists822=== CONT TestRedundantMultipartUpload823--- PASS: TestCreatePendingClosureRejectsOversizedNAR (0.00s)824=== CONT TestPush_RejectsBadRequests825=== RUN TestPendingClosureWriteTimeout/empty826=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info827=== RUN TestIsValidUploadKey/narinfo828=== RUN TestProxyWriteTimeout/narinfo829=== PAUSE TestProxyWriteTimeout/narinfo830=== RUN TestProxyWriteTimeout/1_GiB_nar831=== PAUSE TestProxyWriteTimeout/1_GiB_nar832=== RUN TestProxyWriteTimeout/10_GiB_nar833=== PAUSE TestProxyWriteTimeout/10_GiB_nar834=== RUN TestProxyWriteTimeout/unknown_size835=== PAUSE TestProxyWriteTimeout/unknown_size8362026/10/25 17:16:02 INFO Client skipped oversized paths paths=3 nar_bytes=5000000000837=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal838=== CONT TestPush_SkippedKeySurvivesGCBeforeCommit839=== CONT TestPush_CompleteWaitsForCleanupOfThePush840--- PASS: TestParseSize (0.00s)841=== CONT TestPush_RootsAreLockedInByteOrder842=== PAUSE TestPendingClosureWriteTimeout/empty843=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal844=== PAUSE TestIsValidUploadKey/narinfo845--- PASS: TestSkippedUploadsHandler (0.03s)846=== RUN TestPendingClosureWriteTimeout/400_objects847=== RUN TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key848=== RUN TestIsValidUploadKey/nar_zst849=== PAUSE TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key850=== RUN TestUploadHandlersRejectOversizedBody/create_pending_closure851=== PAUSE TestPendingClosureWriteTimeout/400_objects852=== PAUSE TestIsValidUploadKey/nar_zst853=== RUN TestIsValidUploadKey/nar_xz854=== RUN TestPendingClosureWriteTimeout/670k_objects855=== PAUSE TestPendingClosureWriteTimeout/670k_objects856=== PAUSE TestIsValidUploadKey/nar_xz857=== RUN TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key858=== PAUSE TestUploadHandlersRejectOversizedBody/create_pending_closure859=== RUN TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline860=== PAUSE TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline861=== PAUSE TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key862=== RUN TestIsValidUploadKey/nar_plain863=== PAUSE TestIsValidUploadKey/nar_plain864=== RUN TestIsValidUploadKey/listing865=== CONT TestPush_RepeatedRootCommitsOnce866=== PAUSE TestIsValidUploadKey/listing867=== RUN TestIsValidUploadKey/build_log868=== PAUSE TestIsValidUploadKey/build_log869=== RUN TestIsValidUploadKey/build_log_home-manager_file870=== RUN TestUploadHandlersRejectOversizedBody/complete_multipart871=== PAUSE TestIsValidUploadKey/build_log_home-manager_file872=== RUN TestIsValidUploadKey/build_log_plus_in_name873=== PAUSE TestIsValidUploadKey/build_log_plus_in_name874=== RUN TestIsValidUploadKey/build_log_question_mark875=== PAUSE TestUploadHandlersRejectOversizedBody/complete_multipart876=== CONT TestPush_CompleteCommitsEveryRoot877=== RUN TestUploadHandlersRejectOversizedBody/request_more_parts878=== PAUSE TestUploadHandlersRejectOversizedBody/request_more_parts879=== PAUSE TestIsValidUploadKey/build_log_question_mark880=== RUN TestIsValidUploadKey/build_log_equals881=== CONT TestPush_OverlappingRootsStoreOneRowPerKey882=== PAUSE TestIsValidUploadKey/build_log_equals883=== RUN TestIsValidUploadKey/realisation884=== PAUSE TestIsValidUploadKey/realisation885=== RUN TestIsValidUploadKey/realisation_plus_in_output886=== PAUSE TestIsValidUploadKey/realisation_plus_in_output887=== RUN TestIsValidUploadKey/nix-cache-info888=== PAUSE TestIsValidUploadKey/nix-cache-info889=== RUN TestIsValidUploadKey/index.html890=== PAUSE TestIsValidUploadKey/index.html891=== RUN TestIsValidUploadKey/narinfo_key,_nar_type892=== PAUSE TestIsValidUploadKey/narinfo_key,_nar_type893=== RUN TestIsValidUploadKey/nar_key,_narinfo_type894=== PAUSE TestIsValidUploadKey/nar_key,_narinfo_type895=== RUN TestIsValidUploadKey/listing_key,_narinfo_type896=== PAUSE TestIsValidUploadKey/listing_key,_narinfo_type897=== RUN TestIsValidUploadKey/traversal898=== PAUSE TestIsValidUploadKey/traversal899=== RUN TestIsValidUploadKey/traversal_nar900=== PAUSE TestIsValidUploadKey/traversal_nar901=== RUN TestIsValidUploadKey/absolute902=== PAUSE TestIsValidUploadKey/absolute903=== RUN TestIsValidUploadKey/empty_key904=== PAUSE TestIsValidUploadKey/empty_key905=== RUN TestIsValidUploadKey/unknown_type906=== PAUSE TestIsValidUploadKey/unknown_type907=== CONT TestReadRedirectUsesPublicS3URL9082026/10/25 17:16:08 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9092026/10/25 17:16:08 ERROR Failed to get multipart upload error="no rows in result set" upload_id=does-not-exist object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst910--- PASS: TestCompleteMultipartUnregistered (6.27s)911=== CONT TestReadProxyRangeRequest9122026/10/25 17:16:10 WARN Authentication failed token_preview=wrongtoken token_length=10 reason="static API token mismatch"913--- PASS: TestService_AuthMiddleware (7.73s)914=== CONT TestReadRedirectKeepsNarinfoProxied915=== NAME TestNARDeduplicationMetadataUploadBug916 metadata_upload_test.go:48: First store path: /private/var/tb/4/scratch/69a84526bfbe447a/build/TestNARDeduplicationMetadataUploadBug1400569568/001/store/krdcwv77wyy0y236phgcg5605pd4gdlk-file1.txt9172026/10/25 17:16:10 INFO Received uploads request method=POST path=/api/pending_closures9182026/10/25 17:16:10 INFO Received push request method=POST path=/api/pushes9192026/10/25 17:16:11 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)9202026/10/25 17:16:11 INFO Uploading krdcwv77wyy0y236phgcg5605pd4gdlk-file1.txt (160B)921--- PASS: TestCreatePendingClosure_SmallNARUsesSimplePUT (8.71s)922=== CONT TestReadRedirectNar9232026/10/25 17:16:11 WARN Failed to register uploaded object key=krdcwv77wyy0y236phgcg5605pd4gdlk.ls error="server returned 404: 404 page not found\n"9242026/10/25 17:16:11 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign9252026/10/25 17:16:11 WARN Failed to register uploaded object key=nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst error="server returned 404: 404 page not found\n"9262026/10/25 17:16:11 INFO Signed narinfos id=1 count=19272026/10/25 17:16:11 INFO Uploading 1 narinfos9282026/10/25 17:16:11 INFO Received complete push request method=POST path=/api/pushes/1/complete9292026/10/25 17:16:11 WARN Failed to register uploaded object key=krdcwv77wyy0y236phgcg5605pd4gdlk.narinfo error="server returned 404: 404 page not found\n"9302026/10/25 17:16:11 INFO Completed push id=1 objects=3 duration=57.559292ms9312026/10/25 17:16:11 INFO Upload complete. (525ms)932=== NAME TestNARDeduplicationMetadataUploadBug933 metadata_upload_test.go:54: Retrieved narinfo from S3:934 StorePath: /private/var/tb/4/scratch/69a84526bfbe447a/build/TestNARDeduplicationMetadataUploadBug1400569568/001/store/krdcwv77wyy0y236phgcg5605pd4gdlk-file1.txt935 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst936 Compression: zstd937 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf938 NarSize: 160939 References: 940 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf941 metadata_upload_test.go:55: Retrieved .ls file from S3 (compressed size: 77 bytes)942 metadata_upload_test.go:55: Decompressed .ls content (64 bytes):943 {"version":1,"root":{"type":"regular","size":44,"narOffset":96}}9442026/10/25 17:16:11 INFO Received uploads request method=POST path=/api/pending_closures945 metadata_upload_test.go:64: Second store path (same content): /private/var/tb/4/scratch/69a84526bfbe447a/build/TestNARDeduplicationMetadataUploadBug1400569568/001/store/8jmvv2kbyifmcmqds05czyll1n42r9kv-file2.txt946--- PASS: TestDeduplicatedObjectsRecordedAsPending (9.38s)947=== CONT TestReadProxyDisabled9482026/10/25 17:16:11 INFO Received push request method=POST path=/api/pushes9492026/10/25 17:16:11 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)9502026/10/25 17:16:11 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign9512026/10/25 17:16:11 WARN Failed to register uploaded object key=8jmvv2kbyifmcmqds05czyll1n42r9kv.ls error="server returned 404: 404 page not found\n"9522026/10/25 17:16:11 INFO Signed narinfos id=2 count=19532026/10/25 17:16:11 INFO Uploading 1 narinfos9542026/10/25 17:16:12 INFO Received complete push request method=POST path=/api/pushes/2/complete9552026/10/25 17:16:12 WARN Failed to register uploaded object key=8jmvv2kbyifmcmqds05czyll1n42r9kv.narinfo error="server returned 404: 404 page not found\n"9562026/10/25 17:16:12 INFO Completed push id=2 objects=3 duration=2.79325ms9572026/10/25 17:16:12 INFO Upload complete. (264ms)958=== NAME TestNARDeduplicationMetadataUploadBug959 metadata_upload_test.go:76: Retrieved narinfo from S3:960 StorePath: /private/var/tb/4/scratch/69a84526bfbe447a/build/TestNARDeduplicationMetadataUploadBug1400569568/001/store/8jmvv2kbyifmcmqds05czyll1n42r9kv-file2.txt961 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst962 Compression: zstd963 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf964 NarSize: 160965 References: 966 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf967 metadata_upload_test.go:77: Retrieved .ls file from S3 (compressed size: 62 bytes)968 metadata_upload_test.go:77: Decompressed .ls content (49 bytes):969 {"version":1,"root":{"type":"regular","size":44}}9702026/10/25 17:16:12 INFO Received uploads request method=POST path=/api/pending_closures971--- PASS: TestNARDeduplicationMetadataUploadBug (9.99s)972=== CONT TestReadProxyRootRedirectsToIndexHTML9732026/10/25 17:16:12 INFO Received push request method=POST path=/api/pushes9742026/10/25 17:16:12 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign9752026/10/25 17:16:12 INFO Signed narinfos id=1 count=19762026/10/25 17:16:12 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign9772026/10/25 17:16:12 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign9782026/10/25 17:16:12 ERROR Failed to sign narinfos signer="index 1" error="signing key cannot be nil"9792026/10/25 17:16:12 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign9802026/10/25 17:16:12 ERROR Failed to sign narinfos signer=niks3-test-1 error="signer failed"9812026/10/25 17:16:12 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign9822026/10/25 17:16:12 ERROR Signer returned unexpected signature count signer=niks3-test-1 got=0 want=19832026/10/25 17:16:12 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign9842026/10/25 17:16:12 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9852026/10/25 17:16:12 ERROR Signer returned unexpected object key signer=niks3-test-1 object_key=unexpected.narinfo986--- PASS: TestPush_SignsNarinfosOfItsPendingObjects (10.53s)987=== CONT TestReadProxyConditionalGet9882026/10/25 17:16:13 INFO Received uploads request method=POST path=/api/pending_closures9892026/10/25 17:16:13 INFO Received uploads request method=POST path=/api/pending_closures9902026/10/25 17:16:13 INFO Aborted multipart uploads count=0 kept=09912026/10/25 17:16:13 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=09922026/10/25 17:16:14 INFO Vacuumed table table=pending_closures9932026/10/25 17:16:14 INFO Vacuumed table table=pending_objects9942026/10/25 17:16:14 INFO Vacuumed table table=multipart_uploads9952026/10/25 17:16:14 INFO Vacuumed table table=closures9962026/10/25 17:16:14 INFO Vacuumed table table=objects9972026/10/25 17:16:14 INFO Aborted multipart uploads count=0 kept=09982026/10/25 17:16:14 WARN Force mode enabled - objects will be deleted immediately without grace period9992026/10/25 17:16:14 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=010002026/10/25 17:16:14 INFO Vacuumed table table=pending_closures10012026/10/25 17:16:14 INFO Received uploads request method=POST path=/api/pending_closures10022026/10/25 17:16:14 INFO Vacuumed table table=pending_objects10032026/10/25 17:16:14 INFO Vacuumed table table=multipart_uploads10042026/10/25 17:16:14 INFO Vacuumed table table=closures10052026/10/25 17:16:14 INFO Vacuumed table table=objects1006--- PASS: TestPushDedupSurvivesConcurrentGC (12.21s)1007=== CONT TestReadProxyOutlastsServerWriteTimeout10082026/10/25 17:16:15 INFO Received complete multipart upload request method=POST path=/api/multipart/complete10092026/10/25 17:16:15 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified key does not exist." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=MzdjYjEyMTktOGRjYi00ZjYxLWI0OTQtOWZmYTJlN2NkODI4LjdlNGM0OTYxLTM2NzktNDdkNS1hNTNkLThkNGFkNGVjYTE1MngxNzkyOTQ4NTc0NTM0NTk2MDAw10102026/10/25 17:16:15 INFO Received uploads request method=POST path=/api/pending_closures10112026/10/25 17:16:15 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=MzdjYjEyMTktOGRjYi00ZjYxLWI0OTQtOWZmYTJlN2NkODI4LjdlNGM0OTYxLTM2NzktNDdkNS1hNTNkLThkNGFkNGVjYTE1MngxNzkyOTQ4NTc0NTM0NTk2MDAw parts=11012--- PASS: TestCompleteMultipartUpload_ErrorButObjectExists (12.87s)1013=== CONT TestReadProxyHead10142026/10/25 17:16:15 INFO Registered completed upload object_key=nar/jjjjjjjjjjjjjjjjjjjjjjjjjjjjjj0100000000000000000000.nar.zst10152026/10/25 17:16:15 INFO Received uploads request method=POST path=/api/pending_closures1016--- PASS: TestPresignedUploadRegisteredBeforeCommit (13.05s)1017=== CONT TestReadProxyInvalidPath10182026/10/25 17:16:15 INFO Received uploads request method=POST path=/api/pending_closures10192026/10/25 17:16:15 INFO Received uploads request method=POST path=/api/pending_closures10202026/10/25 17:16:15 INFO Received uploads request method=POST path=/api/pending_closures10212026/10/25 17:16:16 INFO Received uploads request method=POST path=/api/pending_closures10222026/10/25 17:16:17 WARN Rate limiter enabled after throttle name=s3-test rate=510232026/10/25 17:16:17 WARN S3 rate limit hit operation="complete multipart upload" error="Please reduce your request rate."1024=== NAME TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle1025 throttle_test.go:213: Proxy stats: total=13, throttled=10, completeMultipart=101026 throttle_test.go:215: Rate limiter: enabled=true, rate=5.001027--- PASS: TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle (14.90s)1028=== CONT TestReadProxy40410292026/10/25 17:16:17 INFO Received push request method=POST path=/api/pushes10302026/10/25 17:16:17 INFO Received complete multipart upload request method=POST path=/api/multipart/complete10312026/10/25 17:16:18 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst upload_id=MzdjYjEyMTktOGRjYi00ZjYxLWI0OTQtOWZmYTJlN2NkODI4LjZmYTM2NzBhLTAwMjMtNDc5YS05NzZlLTI1MjkyZDUzNDlkMXgxNzkyOTQ4NTczOTMyMTE1MDAw parts=1010322026/10/25 17:16:18 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete1033--- PASS: TestPush_OverlappingRootsStoreOneRowPerKey (15.67s)1034=== CONT TestReadProxyNarStreaming10352026/10/25 17:16:18 INFO Completed upload id=1 objects=2 duration=45.628334ms10362026/10/25 17:16:18 INFO Received uploads request method=POST path=/api/pending_closures10372026/10/25 17:16:18 INFO Received uploads request method=POST path=/api/pending_closures10382026/10/25 17:16:18 INFO Object in database but missing from S3 key=dadb44fdadb44fdadb44fdadb44f0000.narinfo10392026/10/25 17:16:18 WARN Found objects in DB but missing from S3, will re-upload count=11040--- PASS: TestService_verifyS3Integrity (15.84s)1041=== CONT TestReadProxyContentNegotiation10422026/10/25 17:16:18 INFO Received cleanup request method=DELETE path=/api/pending_closures10432026/10/25 17:16:18 INFO Aborted multipart uploads count=0 kept=010442026/10/25 17:16:18 INFO Received uploads request method=POST path=/api/pending_closures10452026/10/25 17:16:18 INFO Received cleanup request method=DELETE path=/api/pending_closures10462026/10/25 17:16:18 INFO Aborted multipart uploads count=1 kept=010472026/10/25 17:16:19 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete10482026-10-25 17:16:19.076 UTC [38884] ERROR: Closure does not exist: id=110492026-10-25 17:16:19.076 UTC [38884] CONTEXT: PL/pgSQL function commit_pending_closure(bigint) line 13 at RAISE10502026-10-25 17:16:19.076 UTC [38884] STATEMENT: -- name: CommitPendingClosure :one1051 SELECT commit_pending_closure($1::bigint)::bigint1052 1053--- PASS: TestService_cleanupPendingClosuresHandler (16.74s)1054=== CONT TestReadProxyNarinfoAlreadyDecompressed10552026/10/25 17:16:19 INFO Received push request method=POST path=/api/pushes10562026/10/25 17:16:19 INFO Received complete push request method=POST path=/api/pushes/1/complete10572026/10/25 17:16:19 INFO Completed push id=1 objects=4 duration=73.84825ms10582026/10/25 17:16:19 INFO Received push request method=POST path=/api/pushes10592026/10/25 17:16:20 INFO Aborted multipart uploads count=0 kept=010602026/10/25 17:16:20 WARN Force mode enabled - objects will be deleted immediately without grace period10612026/10/25 17:16:20 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=010622026/10/25 17:16:20 INFO Vacuumed table table=pending_closures10632026/10/25 17:16:20 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1064=== RUN TestPush_RejectsBadRequests/root_not_in_objects1065=== PAUSE TestPush_RejectsBadRequests/root_not_in_objects1066=== RUN TestPush_RejectsBadRequests/no_roots10672026/10/25 17:16:20 INFO Vacuumed table table=pending_objects1068=== PAUSE TestPush_RejectsBadRequests/no_roots1069=== RUN TestPush_RejectsBadRequests/no_objects1070=== PAUSE TestPush_RejectsBadRequests/no_objects1071=== RUN TestPush_RejectsBadRequests/bad_root1072=== PAUSE TestPush_RejectsBadRequests/bad_root1073=== CONT TestReadProxyNarinfo10742026/10/25 17:16:20 INFO Vacuumed table table=multipart_uploads10752026/10/25 17:16:20 INFO Completed multipart upload object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst upload_id=MzdjYjEyMTktOGRjYi00ZjYxLWI0OTQtOWZmYTJlN2NkODI4LmQxZDAyNjZjLTIxM2ItNGRiMi04MTU5LTI3OGM5ZWZlMzEwM3gxNzkyOTQ4NTc2MTA2MjIxMDAw parts=1010762026/10/25 17:16:20 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete10772026/10/25 17:16:20 INFO Vacuumed table table=closures10782026/10/25 17:16:20 INFO Completed upload id=1 objects=2 duration=263.760167ms10792026/10/25 17:16:20 INFO Received get closure request method=GET path=/api/closures/0000000000000000000000000000000010802026/10/25 17:16:20 INFO Received uploads request method=POST path=/api/pending_closures10812026/10/25 17:16:20 INFO Starting cleanup of old closures method=DELETE path=/api/closures10822026/10/25 17:16:20 INFO Aborted multipart uploads count=0 kept=010832026/10/25 17:16:20 INFO Vacuumed table table=objects10842026/10/25 17:16:20 INFO Received complete push request method=POST path=/api/pushes/2/complete10852026/10/25 17:16:20 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=010862026/10/25 17:16:20 INFO Completed push id=2 objects=4 duration=18.262125ms1087--- PASS: TestPush_SkippedKeySurvivesGCBeforeCommit (18.43s)1088=== CONT TestIsValidCachePath1089=== RUN TestIsValidCachePath/narinfo1090=== PAUSE TestIsValidCachePath/narinfo1091=== RUN TestIsValidCachePath/narinfo_all_nix_base32_chars1092=== PAUSE TestIsValidCachePath/narinfo_all_nix_base32_chars1093=== RUN TestIsValidCachePath/nar_zst10942026/10/25 17:16:20 INFO Vacuumed table table=pending_closures1095=== PAUSE TestIsValidCachePath/nar_zst1096=== RUN TestIsValidCachePath/nar_xz1097=== PAUSE TestIsValidCachePath/nar_xz1098=== RUN TestIsValidCachePath/nar_bz21099=== PAUSE TestIsValidCachePath/nar_bz21100=== RUN TestIsValidCachePath/nar_uncompressed1101=== PAUSE TestIsValidCachePath/nar_uncompressed1102=== RUN TestIsValidCachePath/ls1103=== PAUSE TestIsValidCachePath/ls1104=== RUN TestIsValidCachePath/log1105=== PAUSE TestIsValidCachePath/log1106=== RUN TestIsValidCachePath/realisation11072026/10/25 17:16:21 INFO Vacuumed table table=pending_objects1108=== PAUSE TestIsValidCachePath/realisation1109=== RUN TestIsValidCachePath/nix-cache-info1110=== PAUSE TestIsValidCachePath/nix-cache-info1111=== RUN TestIsValidCachePath/index.html1112=== PAUSE TestIsValidCachePath/index.html1113=== RUN TestIsValidCachePath/traversal_parent1114=== PAUSE TestIsValidCachePath/traversal_parent1115=== RUN TestIsValidCachePath/traversal_in_middle1116=== PAUSE TestIsValidCachePath/traversal_in_middle1117=== RUN TestIsValidCachePath/invalid_char_e1118=== PAUSE TestIsValidCachePath/invalid_char_e1119=== RUN TestIsValidCachePath/invalid_char_u1120=== PAUSE TestIsValidCachePath/invalid_char_u1121=== RUN TestIsValidCachePath/random_path1122=== PAUSE TestIsValidCachePath/random_path1123=== RUN TestIsValidCachePath/empty1124=== PAUSE TestIsValidCachePath/empty1125=== RUN TestIsValidCachePath/leading_slash1126=== PAUSE TestIsValidCachePath/leading_slash1127=== RUN TestIsValidCachePath/wrong_extension1128=== PAUSE TestIsValidCachePath/wrong_extension1129=== RUN TestIsValidCachePath/short_hash1130=== PAUSE TestIsValidCachePath/short_hash1131=== CONT TestParseSingleRange1132=== RUN TestParseSingleRange/none11332026/10/25 17:16:21 INFO Received push request method=POST path=/api/pushes1134=== PAUSE TestParseSingleRange/none1135=== RUN TestParseSingleRange/unknown_unit11362026/10/25 17:16:21 INFO Vacuumed table table=multipart_uploads1137=== PAUSE TestParseSingleRange/unknown_unit1138=== RUN TestParseSingleRange/multi-range_ignored1139=== PAUSE TestParseSingleRange/multi-range_ignored1140=== RUN TestParseSingleRange/malformed_no_dash1141=== PAUSE TestParseSingleRange/malformed_no_dash1142=== RUN TestParseSingleRange/malformed_both_empty1143=== PAUSE TestParseSingleRange/malformed_both_empty1144=== RUN TestParseSingleRange/malformed_end_before_start1145=== PAUSE TestParseSingleRange/malformed_end_before_start1146=== RUN TestParseSingleRange/closed1147=== PAUSE TestParseSingleRange/closed1148=== RUN TestParseSingleRange/open-ended1149=== PAUSE TestParseSingleRange/open-ended1150=== RUN TestParseSingleRange/end_clamped_to_size1151=== PAUSE TestParseSingleRange/end_clamped_to_size11522026/10/25 17:16:21 INFO Vacuumed table table=closures1153=== RUN TestParseSingleRange/suffix1154=== PAUSE TestParseSingleRange/suffix1155=== RUN TestParseSingleRange/suffix_exceeds_size1156=== PAUSE TestParseSingleRange/suffix_exceeds_size1157=== RUN TestParseSingleRange/single_byte1158=== PAUSE TestParseSingleRange/single_byte1159=== RUN TestParseSingleRange/start_past_EOF1160=== PAUSE TestParseSingleRange/start_past_EOF1161=== RUN TestParseSingleRange/start_far_past_EOF1162=== PAUSE TestParseSingleRange/start_far_past_EOF1163=== CONT TestPresentNotReportedWhileGCDeletesClosure1164=== RUN TestPresentNotReportedWhileGCDeletesClosure/stale1165=== PAUSE TestPresentNotReportedWhileGCDeletesClosure/stale1166=== RUN TestPresentNotReportedWhileGCDeletesClosure/fresh1167=== PAUSE TestPresentNotReportedWhileGCDeletesClosure/fresh1168=== CONT TestPresentRefreshesOnlyStaleClosures11692026/10/25 17:16:21 INFO Vacuumed table table=objects11702026/10/25 17:16:21 INFO Received get closure request method=GET path=/api/closures/000000000000000000000000000000001171--- PASS: TestService_createPendingClosureHandler (19.02s)1172=== CONT TestPresentReportsOnlyClosureRoots11732026-10-25 17:16:21.488 UTC [38977] ERROR: could not obtain lock on row in relation "closures"11742026-10-25 17:16:21.488 UTC [38977] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT11752026-10-25 17:16:21.492 UTC [38977] ERROR: could not obtain lock on row in relation "closures"11762026-10-25 17:16:21.492 UTC [38977] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT11772026-10-25 17:16:21.497 UTC [38977] ERROR: could not obtain lock on row in relation "closures"11782026-10-25 17:16:21.497 UTC [38977] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT11792026-10-25 17:16:21.522 UTC [38977] ERROR: could not obtain lock on row in relation "closures"11802026-10-25 17:16:21.522 UTC [38977] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT11812026-10-25 17:16:21.532 UTC [38977] ERROR: could not obtain lock on row in relation "closures"11822026-10-25 17:16:21.532 UTC [38977] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT1183--- PASS: TestPush_RootsAreLockedInByteOrder (19.22s)1184=== CONT TestCreatePin_ReservedPins11852026/10/25 17:16:21 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11862026/10/25 17:16:21 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:51867/oidc11872026/10/25 17:16:21 INFO Received uploads request method=POST path=/api/pending_closures11882026/10/25 17:16:21 INFO Completed multipart upload object_key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhh0100000000000000000000.nar.zst upload_id=MzdjYjEyMTktOGRjYi00ZjYxLWI0OTQtOWZmYTJlN2NkODI4LjM0ZjkxMjJmLWUzMzEtNDE4My04ZmQxLTUwZGU0OTU3YzQzZXgxNzkyOTQ4NTc2ODg3MDAxMDAw parts=1211892026/10/25 17:16:21 INFO Received uploads request method=POST path=/api/pending_closures1190--- PASS: TestCompletedNarNotReofferedAcrossClosures (19.48s)1191=== CONT TestOrphanedObjectsGCStressTest11922026/10/25 17:16:22 INFO Received uploads request method=POST path=/api/pending_closures1193--- PASS: TestService_Rustfstest (20.13s)1194=== CONT TestOrphanedObjectsGC11952026/10/25 17:16:23 INFO Received push request method=POST path=/api/pushes11962026-10-25 17:16:23.722 UTC [38995] ERROR: Push does not exist: id=111972026-10-25 17:16:23.722 UTC [38995] CONTEXT: PL/pgSQL function commit_push(bigint) line 11 at RAISE11982026-10-25 17:16:23.722 UTC [38995] STATEMENT: SELECT commit_push($1)1199--- PASS: TestPush_CompleteWaitsForCleanupOfThePush (21.32s)1200=== CONT TestObjectStatsUpdatedOncePerCommit12012026/10/25 17:16:23 INFO Received push request method=POST path=/api/pushes12022026/10/25 17:16:24 INFO Received complete push request method=POST path=/api/pushes/1/complete12032026/10/25 17:16:24 INFO Completed push id=1 objects=4 duration=98.682833ms1204--- PASS: TestPush_RepeatedRootCommitsOnce (21.76s)1205=== CONT TestClientSharedPathCommittedMidPush12062026/10/25 17:16:24 INFO Received push request method=POST path=/api/pushes12072026/10/25 17:16:24 INFO Received complete push request method=POST path=/api/pushes/1/complete12082026/10/25 17:16:24 INFO Completed push id=1 objects=6 duration=82.5375ms1209--- PASS: TestPush_CompleteCommitsEveryRoot (22.42s)1210=== CONT TestObjectStatsTrigger1211--- PASS: TestReadRedirectUsesPublicS3URL (22.65s)1212=== CONT TestPendingCleanupUsesOneCutoff12132026/10/25 17:16:25 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1214--- PASS: TestReadProxyRangeRequest (16.86s)1215=== CONT TestGCMetrics12162026/10/25 17:16:25 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=MzdjYjEyMTktOGRjYi00ZjYxLWI0OTQtOWZmYTJlN2NkODI4LjQyNTQzMTk4LWQ1ZjktNGFmNy05NzBlLTYzM2QyOWUwNGRhNHgxNzkyOTQ4NTgxOTMxMTczMDAw parts=1212172026/10/25 17:16:25 INFO Received uploads request method=POST path=/api/pending_closures12182026/10/25 17:16:25 INFO Received uploads request method=POST path=/api/pending_closures1219--- PASS: TestReadRedirectKeepsNarinfoProxied (15.77s)1220=== CONT TestMultipartUploadAbortedWhenCancelledBeforeRecorded1221--- PASS: TestReadRedirectNar (15.29s)1222=== CONT TestGCBugBareHashReferences1223--- PASS: TestReadProxyDisabled (15.00s)1224=== CONT TestMultipartCleanup1225--- PASS: TestReadProxyRootRedirectsToIndexHTML (14.77s)1226=== CONT TestServerTLSConfig1227=== RUN TestServerTLSConfig/no_client_CA1228=== PAUSE TestServerTLSConfig/no_client_CA1229=== RUN TestServerTLSConfig/missing_CA_file1230=== PAUSE TestServerTLSConfig/missing_CA_file1231=== RUN TestServerTLSConfig/not_a_PEM_file1232=== PAUSE TestServerTLSConfig/not_a_PEM_file1233=== CONT TestService_NativeMTLS1234--- PASS: TestReadProxyConditionalGet (14.65s)1235=== CONT TestMetricsCommit12362026/10/25 17:16:27 INFO Received complete multipart upload request method=POST path=/api/multipart/complete12372026/10/25 17:16:27 WARN Failed to abort redundant multipart upload, keeping its row object_key=nar/gggggggggggggggggggggggggggggg0200000000000000000000.nar.zst upload_id=MzdjYjEyMTktOGRjYi00ZjYxLWI0OTQtOWZmYTJlN2NkODI4LjU2ZWM2MGU4LTc1NzktNDlmMy04MGE1LWM3MjRkYTVkZjc1MngxNzkyOTQ4NTg1NjY1NTE4MDAw error="Get \"http://127.0.0.1:1/bucket22/?location=\": dial tcp 127.0.0.1:1: connect: connection refused"12382026/10/25 17:16:27 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0200000000000000000000.nar.zst upload_id=MzdjYjEyMTktOGRjYi00ZjYxLWI0OTQtOWZmYTJlN2NkODI4LjY0NjJhYmJjLWEwOTctNGMwMS1hMjUyLWEyMDViMWEyMzhhZXgxNzkyOTQ4NTg1NjA3NTM3MDAw parts=1212392026/10/25 17:16:27 INFO Received cleanup request method=DELETE path=/api/pending_closures12402026/10/25 17:16:27 INFO Aborted multipart uploads count=1 kept=01241--- PASS: TestRedundantMultipartUpload (25.59s)1242=== CONT TestMetricsInventory1243--- PASS: TestReadProxyHead (12.93s)1244=== CONT TestGCAdvisoryLockBlocksConcurrentRun1245--- PASS: TestReadProxyInvalidPath (12.96s)1246=== CONT TestLeadEndsOnShutdown1247--- PASS: TestReadProxyNarStreaming (10.54s)1248=== CONT TestLeadIncumbentAnnouncesAtOnce1249--- PASS: TestReadProxyContentNegotiation (11.10s)1250=== CONT TestCacheConfigHandler1251=== RUN TestCacheConfigHandler/full_config,_no_issuer1252=== PAUSE TestCacheConfigHandler/full_config,_no_issuer1253=== RUN TestCacheConfigHandler/no_cache_url_configured1254=== PAUSE TestCacheConfigHandler/no_cache_url_configured1255=== RUN TestCacheConfigHandler/no_signing_keys1256=== PAUSE TestCacheConfigHandler/no_signing_keys1257=== RUN TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1258=== PAUSE TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1259=== CONT TestClientWithDependencies1260--- PASS: TestReadProxy404 (12.11s)1261=== CONT TestClientMultipleUploads1262--- PASS: TestReadProxyNarinfoAlreadyDecompressed (10.38s)1263=== CONT TestClientIntegration12642026/10/25 17:16:29 ERROR Failed to decode narinfo key=3hcdxyjf9yiq7qf3i4548drb6sjmwa1v.narinfo limit=16777216 error=<nil>1265--- PASS: TestReadProxyNarinfo (9.40s)1266=== CONT TestClientErrorHandling1267=== RUN TestClientErrorHandling/InvalidStorePath1268=== PAUSE TestClientErrorHandling/InvalidStorePath1269=== RUN TestClientErrorHandling/InvalidAuthToken1270=== PAUSE TestClientErrorHandling/InvalidAuthToken1271=== RUN TestClientErrorHandling/ServerNotAvailable1272=== PAUSE TestClientErrorHandling/ServerNotAvailable1273=== CONT TestClientCADerivations1274--- PASS: TestPresentReportsOnlyClosureRoots (8.50s)1275=== CONT TestCacheStatsHandler1276--- PASS: TestPresentRefreshesOnlyStaleClosures (8.74s)1277=== CONT TestLeadElectsOneAndHandsOver12782026/10/25 17:16:30 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux12792026/10/25 17:16:30 WARN Refused reserved pin name=worker-x86_64-linux12802026/10/25 17:16:30 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux12812026/10/25 17:16:30 INFO Received create pin request method=POST path=/api/pins/my-app12822026/10/25 17:16:30 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux1283--- PASS: TestCreatePin_ReservedPins (8.63s)1284=== CONT TestDeleteClosuresRacingPins1285--- PASS: TestObjectStatsUpdatedOncePerCommit (7.91s)1286=== CONT TestConnectWaitsForAPeerMigration12872026/10/25 17:16:31 INFO Received push request method=POST path=/api/pushes12882026/10/25 17:16:31 INFO Uploading 2 paths to 127.0.0.1 (0 already cached)12892026/10/25 17:16:31 INFO Uploading p6axhxm5xn5212jk8sxxxskv2z91gah3-shared-dep (136B)12902026/10/25 17:16:31 INFO Uploading 8vl82xfz0jq84m7273lv1sgwp3wxdfna-top (264B)12912026/10/25 17:16:31 WARN Failed to register uploaded object key=8vl82xfz0jq84m7273lv1sgwp3wxdfna.ls error="server returned 404: 404 page not found\n"12922026/10/25 17:16:31 WARN Failed to register uploaded object key=nar/0hqfvr6rj3b3dhw5aasw8vylf1bnz8kdbxwpgmaqm6giqrnppm7y.nar.zst error="server returned 404: 404 page not found\n"12932026/10/25 17:16:31 WARN Failed to register uploaded object key=p6axhxm5xn5212jk8sxxxskv2z91gah3.ls error="server returned 404: 404 page not found\n"12942026/10/25 17:16:31 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign12952026/10/25 17:16:31 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"12962026/10/25 17:16:31 INFO Signed narinfos id=1 count=21297--- PASS: TestObjectStatsTrigger (6.98s)1298=== CONT TestClientFallsBackToClosures12992026/10/25 17:16:31 INFO Uploading 2 narinfos13002026/10/25 17:16:31 INFO Received complete push request method=POST path=/api/pushes/1/complete13012026/10/25 17:16:31 WARN Failed to register uploaded object key=8vl82xfz0jq84m7273lv1sgwp3wxdfna.narinfo error="server returned 404: 404 page not found\n"13022026/10/25 17:16:31 WARN Failed to register uploaded object key=p6axhxm5xn5212jk8sxxxskv2z91gah3.narinfo error="server returned 404: 404 page not found\n"13032026/10/25 17:16:31 INFO Completed push id=1 objects=6 duration=46.158292ms13042026/10/25 17:16:31 INFO Upload complete. (330ms)1305=== NAME TestClientSharedPathCommittedMidPush1306 client_integration_test.go:680: Retrieved narinfo from S3:1307 StorePath: /private/var/tb/4/scratch/69a84526bfbe447a/build/TestClientSharedPathCommittedMidPush2040726031/001/store/p6axhxm5xn5212jk8sxxxskv2z91gah3-shared-dep1308 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1309 Compression: zstd1310 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821311 NarSize: 1361312 References: 1313 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1314 client_integration_test.go:680: Retrieved narinfo from S3:1315 StorePath: /private/var/tb/4/scratch/69a84526bfbe447a/build/TestClientSharedPathCommittedMidPush2040726031/001/store/8vl82xfz0jq84m7273lv1sgwp3wxdfna-top1316 URL: nar/0hqfvr6rj3b3dhw5aasw8vylf1bnz8kdbxwpgmaqm6giqrnppm7y.nar.zst1317 Compression: zstd1318 NarHash: sha256:0hqfvr6rj3b3dhw5aasw8vylf1bnz8kdbxwpgmaqm6giqrnppm7y1319 NarSize: 2641320 References: /private/var/tb/4/scratch/69a84526bfbe447a/build/TestClientSharedPathCommittedMidPush2040726031/001/store/p6axhxm5xn5212jk8sxxxskv2z91gah3-shared-dep1321 CA: text:sha256:01ypm14m8lc5i9h8zs0hmg0zs6ys20an5nd785wnmjkabk5lisi31322--- PASS: TestClientSharedPathCommittedMidPush (7.93s)1323=== CONT TestResolveDBConnectionString1324=== RUN TestResolveDBConnectionString/flag_wins1325=== PAUSE TestResolveDBConnectionString/flag_wins1326=== RUN TestResolveDBConnectionString/file_when_flag_empty13272026/10/25 17:16:32 INFO Received uploads request method=POST path=/api/pending_closures1328--- PASS: TestReadProxyOutlastsServerWriteTimeout (17.57s)1329=== CONT TestClientPushesUseOnePush1330=== PAUSE TestResolveDBConnectionString/file_when_flag_empty1331=== RUN TestResolveDBConnectionString/missing_file_is_an_error1332=== PAUSE TestResolveDBConnectionString/missing_file_is_an_error1333=== RUN TestResolveDBConnectionString/PGHOST_allows_empty1334=== PAUSE TestResolveDBConnectionString/PGHOST_allows_empty1335=== RUN TestResolveDBConnectionString/nothing_configured1336=== PAUSE TestResolveDBConnectionString/nothing_configured1337=== CONT TestConcurrentCommitsSharingObjectsDoNotDeadlock13382026/10/25 17:16:32 INFO Received uploads request method=POST path=/api/pending_closures13392026/10/25 17:16:32 INFO Received cleanup request method=DELETE path=/api/pending_closures13402026/10/25 17:16:32 INFO Aborted multipart uploads count=0 kept=013412026/10/25 17:16:32 WARN Force mode enabled - objects will be deleted immediately without grace period13422026/10/25 17:16:32 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=013432026/10/25 17:16:32 INFO Vacuumed table table=pending_closures13442026/10/25 17:16:32 INFO Vacuumed table table=pending_objects13452026/10/25 17:16:32 INFO Vacuumed table table=multipart_uploads13462026/10/25 17:16:32 INFO Vacuumed table table=closures13472026/10/25 17:16:32 INFO Vacuumed table table=objects1348--- PASS: TestGCMetrics (7.34s)1349=== CONT TestPinProtectsFromGC1350=== NAME TestOrphanedObjectsGC1351 orphaned_objects_gc_test.go:287: GC Test Summary:1352 orphaned_objects_gc_test.go:288: - Kept: 2 objects from closure A1353 orphaned_objects_gc_test.go:289: - Deleted: 2 objects from closure B1354 orphaned_objects_gc_test.go:290: - Deleted: 6 orphaned chain objects (X1->X2->X3)1355 orphaned_objects_gc_test.go:291: - Deleted: 2 orphaned single objects (Y)1356 orphaned_objects_gc_test.go:292: - Total deleted: 10 objects1357--- PASS: TestOrphanedObjectsGC (10.45s)1358=== CONT TestService_AuthMiddleware_OIDC13592026/10/25 17:16:33 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:52018/oidc13602026/10/25 17:16:33 INFO Received uploads request method=POST path=/api/pending_closures1361--- PASS: TestMultipartUploadAbortedWhenCancelledBeforeRecorded (7.37s)1362=== CONT TestService_ReadScope_PublicByDefault1363--- PASS: TestGCBugBareHashReferences (7.36s)1364=== CONT TestService_RequireScope_OIDC13652026/10/25 17:16:33 INFO Received uploads request method=POST path=/api/pending_closures13662026/10/25 17:16:33 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:52030/oidc13672026/10/25 17:16:33 INFO Received cleanup request method=DELETE path=/api/pending_closures13682026/10/25 17:16:33 WARN Failed to abort upload, keeping its closure key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst error="Get \"http://127.0.0.1:1/bucket54/?location=\": dial tcp 127.0.0.1:1: connect: connection refused" code=""13692026/10/25 17:16:33 INFO Aborted multipart uploads count=0 kept=113702026/10/25 17:16:33 INFO Received cleanup request method=DELETE path=/api/pending_closures13712026/10/25 17:16:34 INFO Aborted multipart uploads count=1 kept=01372--- PASS: TestMultipartCleanup (7.26s)1373=== CONT TestGCEndsOnShutdown1374=== RUN TestGCEndsOnShutdown/before_the_run1375=== PAUSE TestGCEndsOnShutdown/before_the_run1376=== RUN TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete1377=== PAUSE TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete1378=== RUN TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark1379=== PAUSE TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark1380=== CONT TestGCTaskStore_PhaseUpdates1381--- PASS: TestGCTaskStore_PhaseUpdates (0.00s)1382=== CONT TestGCTaskStore_CompletedAllowsNewTask1383--- PASS: TestGCTaskStore_CompletedAllowsNewTask (0.00s)1384=== CONT TestGenerateLandingPage1385--- PASS: TestGenerateLandingPage (0.00s)1386=== CONT TestService_readinessHandler13872026/10/25 17:16:34 WARN mTLS auth: subject not in bound subjects subject="CN=reader"13882026/10/25 17:16:34 WARN mTLS auth: subject not in bound subjects subject="CN=reader"1389--- PASS: TestService_NativeMTLS (6.98s)1390=== CONT TestService_healthCheckHandler13912026/10/25 17:16:34 INFO Received push request method=POST path=/api/pushes13922026/10/25 17:16:34 INFO Received complete push request method=POST path=/api/pushes/1/complete13932026/10/25 17:16:34 INFO Completed push id=1 objects=4 duration=48.972ms13942026/10/25 17:16:34 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete13952026/10/25 17:16:34 INFO Completed upload id=2 objects=2 duration=1.461292ms1396--- PASS: TestMetricsCommit (7.12s)1397=== CONT TestGracefulShutdownDrainsInflight13982026/10/25 17:16:34 INFO Starting HTTP server address=127.0.0.1:5203913992026/10/25 17:16:34 INFO Shutdown signal received, draining in-flight requests timeout=10s1400--- PASS: TestGracefulShutdownDrainsInflight (0.08s)1401=== CONT TestGCTaskStore_Fail1402--- PASS: TestGCTaskStore_Fail (0.00s)1403=== CONT TestGCTaskStore_GetReturnsLatest1404--- PASS: TestGCTaskStore_GetReturnsLatest (0.00s)1405=== CONT TestGCTaskStore_GetEmpty1406--- PASS: TestGCTaskStore_GetEmpty (0.00s)1407=== CONT TestGCTaskStore_ConflictDifferentParams1408--- PASS: TestGCTaskStore_ConflictDifferentParams (0.00s)1409=== CONT TestGCTaskStore_DeduplicateSameParams1410--- PASS: TestGCTaskStore_DeduplicateSameParams (0.00s)1411=== CONT TestGCTaskStore_StartNew1412--- PASS: TestGCTaskStore_StartNew (0.00s)1413=== CONT TestSweepSkipsRowsLockedByPush1414--- PASS: TestMetricsInventory (6.92s)1415=== CONT TestSweepRechecksPendingAfterLocking14162026/10/25 17:16:35 ERROR failed to check GC advisory lock error="query pg_locks: failed to connect to `user=_tribuchetbld4 database=niks3`: /nonexistent/.s.PGSQL.5432 (/nonexistent): dial error: dial unix /nonexistent/.s.PGSQL.5432: connect: no such file or directory"1417--- PASS: TestGCAdvisoryLockBlocksConcurrentRun (7.02s)1418=== CONT TestGetExistingObjectsLocksRows14192026/10/25 17:16:35 INFO lead: acquired remote=192.0.2.1:123414202026/10/25 17:16:36 INFO lead: acquired remote=192.0.2.1:123414212026/10/25 17:16:36 INFO lead: released remote=192.0.2.1:12341422--- PASS: TestLeadIncumbentAnnouncesAtOnce (7.34s)1423=== CONT TestCommitRacingPendingCleanupKeepsObjects14242026/10/25 17:16:36 INFO lead: released remote=192.0.2.1:12341425--- PASS: TestLeadEndsOnShutdown (8.26s)1426=== CONT TestRegisterCompletedObjectNeedsPendingRow1427=== NAME TestClientMultipleUploads1428 client_integration_test.go:358: Created store path 0: /private/var/tb/4/scratch/69a84526bfbe447a/build/TestClientMultipleUploads2835811444/001/store/c7ipzx4v63ba75594vjkp64fn1x2fm3q-test-file-0.txt1429 client_integration_test.go:358: Created store path 1: /private/var/tb/4/scratch/69a84526bfbe447a/build/TestClientMultipleUploads2835811444/001/store/m82amcxgnckrsn1bhlkm6lx02zi3pldh-test-file-1.txt1430 client_integration_test.go:358: Created store path 2: /private/var/tb/4/scratch/69a84526bfbe447a/build/TestClientMultipleUploads2835811444/001/store/i8yj85vqsyn8d7q54wdd1jszy0jilw3m-test-file-2.txt14312026/10/25 17:16:37 INFO Received push request method=POST path=/api/pushes14322026/10/25 17:16:37 INFO Uploading 3 paths to 127.0.0.1 (0 already cached)14332026/10/25 17:16:37 INFO Uploading i8yj85vqsyn8d7q54wdd1jszy0jilw3m-test-file-2.txt (160B)14342026/10/25 17:16:37 INFO Uploading c7ipzx4v63ba75594vjkp64fn1x2fm3q-test-file-0.txt (160B)14352026/10/25 17:16:37 INFO Uploading m82amcxgnckrsn1bhlkm6lx02zi3pldh-test-file-1.txt (160B)14362026/10/25 17:16:37 WARN Failed to register uploaded object key=m82amcxgnckrsn1bhlkm6lx02zi3pldh.ls error="server returned 404: 404 page not found\n"14372026/10/25 17:16:37 WARN Failed to register uploaded object key=nar/13p9pqi0ga6fx2apcwls9hjnv7nmf740ggpn5zvfzdsp5vz2bbg4.nar.zst error="server returned 404: 404 page not found\n"14382026/10/25 17:16:37 WARN Failed to register uploaded object key=i8yj85vqsyn8d7q54wdd1jszy0jilw3m.ls error="server returned 404: 404 page not found\n"14392026/10/25 17:16:37 WARN Failed to register uploaded object key=nar/1823g6vx4q5zqvr73m7lkq1wpk40fin7bsc792di430yk7sg4lka.nar.zst error="server returned 404: 404 page not found\n"14402026/10/25 17:16:37 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign14412026/10/25 17:16:37 WARN Failed to register uploaded object key=c7ipzx4v63ba75594vjkp64fn1x2fm3q.ls error="server returned 404: 404 page not found\n"14422026/10/25 17:16:37 WARN Failed to register uploaded object key=nar/0ahq3izw3h0b0c08p3xdfclh758fwxnp85ccvflasb4vnfsv50ri.nar.zst error="server returned 404: 404 page not found\n"14432026/10/25 17:16:37 INFO Signed narinfos id=1 count=314442026/10/25 17:16:37 INFO Uploading 3 narinfos14452026/10/25 17:16:37 WARN Failed to register uploaded object key=c7ipzx4v63ba75594vjkp64fn1x2fm3q.narinfo error="server returned 404: 404 page not found\n"14462026/10/25 17:16:37 WARN Failed to register uploaded object key=m82amcxgnckrsn1bhlkm6lx02zi3pldh.narinfo error="server returned 404: 404 page not found\n"14472026/10/25 17:16:37 INFO Received complete push request method=POST path=/api/pushes/1/complete14482026/10/25 17:16:37 WARN Failed to register uploaded object key=i8yj85vqsyn8d7q54wdd1jszy0jilw3m.narinfo error="server returned 404: 404 page not found\n"14492026/10/25 17:16:37 INFO Completed push id=1 objects=9 duration=29.909125ms14502026/10/25 17:16:37 INFO Upload complete. (334ms)1451 client_integration_test.go:369: Uploaded 3 paths in 373.324875ms1452=== NAME TestClientWithDependencies1453 client_integration_test.go:613: Built derivation: /private/var/tb/4/scratch/69a84526bfbe447a/build/TestClientWithDependencies3150064229/001/store/cwcs5zgmvxj796zgfb038as1rd70gs7i-test-script1454 client_integration_test.go:615: Found 1 dependencies (including self)1455--- PASS: TestClientMultipleUploads (8.05s)1456=== CONT TestPushWaitsForSweepHoldingRow1457=== NAME TestClientIntegration1458 client_integration_test.go:286: Created store path: /private/var/tb/4/scratch/69a84526bfbe447a/build/TestClientIntegration3451525429/002/store/v0139a2ccfpgk0vvbhxj2nmbwz1bdhhp-test-file.txt14592026/10/25 17:16:37 INFO Received push request method=POST path=/api/pushes14602026/10/25 17:16:37 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)14612026/10/25 17:16:37 INFO Uploading cwcs5zgmvxj796zgfb038as1rd70gs7i-test-script (136B)14622026/10/25 17:16:37 INFO Received push request method=POST path=/api/pushes14632026/10/25 17:16:37 WARN Failed to register uploaded object key=nar/1s7yghixzpinyqm7g59kyn3sav81pmnsdi5v63m6x4r2vacy907j.nar.zst error="server returned 404: 404 page not found\n"14642026/10/25 17:16:37 WARN Failed to register uploaded object key=cwcs5zgmvxj796zgfb038as1rd70gs7i.ls error="server returned 404: 404 page not found\n"14652026/10/25 17:16:37 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)14662026/10/25 17:16:37 INFO Uploading v0139a2ccfpgk0vvbhxj2nmbwz1bdhhp-test-file.txt (152B)14672026/10/25 17:16:37 WARN Failed to register uploaded object key=log/2z0lgy498fkj3mcp6vxsjf758qb69rn2-test-script.drv error="server returned 404: 404 page not found\n"14682026/10/25 17:16:37 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign14692026/10/25 17:16:37 INFO Signed narinfos id=1 count=114702026/10/25 17:16:37 INFO Uploading 1 narinfos14712026/10/25 17:16:37 WARN Failed to register uploaded object key=v0139a2ccfpgk0vvbhxj2nmbwz1bdhhp.ls error="server returned 404: 404 page not found\n"14722026/10/25 17:16:37 INFO Received complete push request method=POST path=/api/pushes/1/complete14732026/10/25 17:16:37 WARN Failed to register uploaded object key=cwcs5zgmvxj796zgfb038as1rd70gs7i.narinfo error="server returned 404: 404 page not found\n"14742026/10/25 17:16:37 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign14752026/10/25 17:16:37 WARN Failed to register uploaded object key=nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst error="server returned 404: 404 page not found\n"14762026/10/25 17:16:37 INFO Signed narinfos id=1 count=114772026/10/25 17:16:37 INFO Uploading 1 narinfos14782026/10/25 17:16:37 INFO Completed push id=1 objects=4 duration=32.328709ms14792026/10/25 17:16:37 INFO Upload complete. (364ms)1480=== NAME TestClientWithDependencies1481 client_integration_test.go:617: Skipping nix copy test - isolated store (/private/var/tb/4/scratch/69a84526bfbe447a/build/TestClientWithDependencies3150064229/001/store) requires matching store prefix14822026/10/25 17:16:37 INFO Received complete push request method=POST path=/api/pushes/1/complete14832026/10/25 17:16:37 WARN Failed to register uploaded object key=v0139a2ccfpgk0vvbhxj2nmbwz1bdhhp.narinfo error="server returned 404: 404 page not found\n"14842026/10/25 17:16:37 INFO Completed push id=1 objects=3 duration=45.946208ms14852026/10/25 17:16:37 INFO Upload complete. (386ms)14862026/10/25 17:16:37 INFO All 1 paths already cached1487=== NAME TestClientIntegration1488 client_integration_test.go:312: Retrieved narinfo from S3:1489 StorePath: /private/var/tb/4/scratch/69a84526bfbe447a/build/TestClientIntegration3451525429/002/store/v0139a2ccfpgk0vvbhxj2nmbwz1bdhhp-test-file.txt1490 URL: nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst1491 Compression: zstd1492 NarHash: sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11493 NarSize: 1521494 References: 1495 CA: fixed:r:sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11496--- PASS: TestClientWithDependencies (8.64s)1497=== CONT TestCreatePendingClosureVerifyS3FailureReleasesConnection1498=== NAME TestClientIntegration1499 client_integration_test.go:313: Retrieved .ls file from S3 (compressed size: 77 bytes)1500 client_integration_test.go:313: Decompressed .ls content (64 bytes):1501 {"version":1,"root":{"type":"regular","size":39,"narOffset":96}}1502 client_integration_test.go:316: Testing garbage collection...15032026/10/25 17:16:38 INFO Starting cleanup of old closures method=DELETE path=/api/closures15042026/10/25 17:16:38 INFO Garbage collection started15052026/10/25 17:16:38 INFO Aborted multipart uploads count=0 kept=015062026/10/25 17:16:38 WARN Force mode enabled - objects will be deleted immediately without grace period1507--- PASS: TestCacheStatsHandler (8.22s)1508=== CONT TestFailedS3DeleteKeepsTombstone1509=== NAME TestClientCADerivations1510 client_ca_test.go:136: Built CA derivation: /private/var/tb/4/scratch/69a84526bfbe447a/build/TestClientCADerivations2130051151/001/store/6fz68qvfs5idm3ba4p9q0f9m2bwcf5ni-ca-test15112026/10/25 17:16:38 INFO Aborted multipart uploads count=1 kept=01512 client_ca_test.go:139: Found 1 dependencies (including self)15132026/10/25 17:16:38 INFO lead: acquired remote=192.0.2.1:123415142026/10/25 17:16:38 INFO Received cleanup request method=DELETE path=/api/pending_closures15152026/10/25 17:16:38 INFO Aborted multipart uploads count=1 kept=01516--- PASS: TestPendingCleanupUsesOneCutoff (13.37s)1517=== CONT TestForceGCDuringPushOffersSweptObject1518=== RUN TestForceGCDuringPushOffersSweptObject/before_pending_rows1519=== PAUSE TestForceGCDuringPushOffersSweptObject/before_pending_rows1520=== RUN TestForceGCDuringPushOffersSweptObject/after_presence_check1521=== PAUSE TestForceGCDuringPushOffersSweptObject/after_presence_check1522=== CONT TestTombstonedObjectOfferedWithoutWaiting15232026/10/25 17:16:38 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=015242026/10/25 17:16:38 INFO Received push request method=POST path=/api/pushes15252026/10/25 17:16:38 INFO Vacuumed table table=pending_closures15262026/10/25 17:16:38 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)15272026/10/25 17:16:38 INFO Uploading 6fz68qvfs5idm3ba4p9q0f9m2bwcf5ni-ca-test (144B)15282026/10/25 17:16:38 INFO Vacuumed table table=pending_objects15292026/10/25 17:16:38 INFO Vacuumed table table=multipart_uploads15302026/10/25 17:16:38 WARN Failed to register uploaded object key=nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst error="server returned 404: 404 page not found\n"15312026/10/25 17:16:38 WARN Failed to register uploaded object key=6fz68qvfs5idm3ba4p9q0f9m2bwcf5ni.ls error="server returned 404: 404 page not found\n"15322026/10/25 17:16:38 INFO Vacuumed table table=closures15332026/10/25 17:16:38 WARN Failed to register uploaded object key=log/zsj2500pqha5w0rrnyl7gfh5bpaf24vg-ca-test.drv error="server returned 404: 404 page not found\n"15342026/10/25 17:16:38 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign15352026/10/25 17:16:38 INFO Signed narinfos id=1 count=115362026/10/25 17:16:38 INFO Uploading 1 narinfos15372026/10/25 17:16:38 INFO Vacuumed table table=objects15382026/10/25 17:16:38 INFO Received complete push request method=POST path=/api/pushes/1/complete15392026/10/25 17:16:38 WARN Failed to register uploaded object key=6fz68qvfs5idm3ba4p9q0f9m2bwcf5ni.narinfo error="server returned 404: 404 page not found\n"15402026/10/25 17:16:38 INFO Completed push id=1 objects=4 duration=64.694625ms15412026/10/25 17:16:38 INFO Upload complete. (436ms)1542=== NAME TestClientCADerivations1543 client_ca_test.go:180: Narinfo contains CA field: StorePath: /private/var/tb/4/scratch/69a84526bfbe447a/build/TestClientCADerivations2130051151/001/store/6fz68qvfs5idm3ba4p9q0f9m2bwcf5ni-ca-test1544 URL: nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst1545 Compression: zstd1546 NarHash: sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1547 NarSize: 1441548 References: 1549 Deriver: /private/var/tb/4/scratch/69a84526bfbe447a/build/TestClientCADerivations2130051151/001/store/zsj2500pqha5w0rrnyl7gfh5bpaf24vg-ca-test.drv1550 CA: fixed:r:sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1551 client_ca_test.go:185: Checking for realisation files in S3...1552 client_ca_test.go:207: No realisation files uploaded - this is expected for locally built CA derivations1553 client_ca_test.go:208: Locally built CA derivations don't have DrvOutput IDs until they're substituted from a cache1554 client_ca_test.go:258: nix copy output: error: binary cache 's3://bucket64?endpoint=http://localhost:51426®ion=eu-west-1' is for Nix stores with prefix '/nix/store', not '/private/var/tb/4/scratch/69a84526bfbe447a/build/TestClientCADerivations2130051151/001/store'1555 client_ca_test.go:259: nix copy failed (might be expected with isolated stores): exit status 11556--- PASS: TestClientCADerivations (9.39s)1557=== CONT TestGCSweepDeliversEachKeyOnce15582026/10/25 17:16:39 INFO lead: released remote=192.0.2.1:123415592026/10/25 17:16:39 INFO lead: acquired remote=192.0.2.1:123415602026/10/25 17:16:39 INFO Received uploads request method=POST path=/api/pending_closures15612026/10/25 17:16:40 INFO Received uploads request method=POST path=/api/pending_closures15622026/10/25 17:16:40 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)15632026/10/25 17:16:40 INFO Uploading inppcnj4lyhvfkn40050r9fxxkmfny8n-a (256B)15642026/10/25 17:16:40 INFO Uploading 21gv8b2py01k8yl9xvxag3my5302jyqa-shared-dep (136B)15652026/10/25 17:16:40 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=01566=== NAME TestClientIntegration1567 client_integration_test.go:323: Objects in database after GC:1568 client_integration_test.go:323: Successfully deleted all objects with GC --force15692026/10/25 17:16:40 WARN Failed to register uploaded object key=nar/1k25zdncd0qa9qssi7dz190gs6rib66gbnnnkcwmgbg8p0b93ila.nar.zst error="server returned 404: 404 page not found\n"15702026/10/25 17:16:40 WARN Failed to register uploaded object key=6fk2c15nj1bhilsda0r5gkvx8j4w7aks.ls error="server returned 404: 404 page not found\n"15712026/10/25 17:16:40 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"15722026/10/25 17:16:40 WARN Failed to register uploaded object key=21gv8b2py01k8yl9xvxag3my5302jyqa.ls error="server returned 404: 404 page not found\n"15732026/10/25 17:16:40 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign15742026/10/25 17:16:40 WARN Failed to register uploaded object key=inppcnj4lyhvfkn40050r9fxxkmfny8n.ls error="server returned 404: 404 page not found\n"15752026/10/25 17:16:40 INFO Signed narinfos id=1 count=215762026/10/25 17:16:40 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign15772026/10/25 17:16:40 INFO Signed narinfos id=2 count=215782026/10/25 17:16:40 INFO Uploading 4 narinfos15792026/10/25 17:16:40 WARN Failed to register uploaded object key=6fk2c15nj1bhilsda0r5gkvx8j4w7aks.narinfo error="server returned 404: 404 page not found\n"15802026/10/25 17:16:40 WARN Failed to register uploaded object key=21gv8b2py01k8yl9xvxag3my5302jyqa.narinfo error="server returned 404: 404 page not found\n"15812026/10/25 17:16:40 WARN Failed to register uploaded object key=inppcnj4lyhvfkn40050r9fxxkmfny8n.narinfo error="server returned 404: 404 page not found\n"1582--- PASS: TestClientIntegration (10.73s)1583=== CONT TestGCSweepSkipsPendingObjects15842026/10/25 17:16:40 INFO Received push request method=POST path=/api/pushes15852026/10/25 17:16:40 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete15862026/10/25 17:16:40 WARN Failed to register uploaded object key=21gv8b2py01k8yl9xvxag3my5302jyqa.narinfo error="server returned 404: 404 page not found\n"15872026/10/25 17:16:40 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)15882026/10/25 17:16:40 INFO Uploading pjp1vs0ydqam0xjkg8s8f4r7jq5sg5hy-a (256B)15892026/10/25 17:16:40 INFO Uploading x35xzb6r3jj3msrajhbgakahzdgcihjs-shared-dep (136B)15902026/10/25 17:16:40 INFO Completed upload id=1 objects=6 duration=25.135541ms15912026/10/25 17:16:40 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete15922026/10/25 17:16:40 INFO Completed upload id=2 objects=6 duration=1.013958ms15932026/10/25 17:16:40 INFO Upload complete. (446ms)1594=== NAME TestClientFallsBackToClosures1595 client_pushes_test.go:112: Retrieved narinfo from S3:1596 StorePath: /private/var/tb/4/scratch/69a84526bfbe447a/build/TestClientFallsBackToClosures1445388935/001/store/21gv8b2py01k8yl9xvxag3my5302jyqa-shared-dep1597 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1598 Compression: zstd1599 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821600 NarSize: 1361601 References: 1602 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1603 client_pushes_test.go:112: Retrieved narinfo from S3:1604 StorePath: /private/var/tb/4/scratch/69a84526bfbe447a/build/TestClientFallsBackToClosures1445388935/001/store/inppcnj4lyhvfkn40050r9fxxkmfny8n-a1605 URL: nar/1k25zdncd0qa9qssi7dz190gs6rib66gbnnnkcwmgbg8p0b93ila.nar.zst1606 Compression: zstd1607 NarHash: sha256:1k25zdncd0qa9qssi7dz190gs6rib66gbnnnkcwmgbg8p0b93ila1608 NarSize: 2561609 References: /private/var/tb/4/scratch/69a84526bfbe447a/build/TestClientFallsBackToClosures1445388935/001/store/21gv8b2py01k8yl9xvxag3my5302jyqa-shared-dep1610 CA: text:sha256:0mvdw32g2ksa386yv25d5yhrk4w36j87mqlgc2iqbsj2xhdb202m1611 client_pushes_test.go:112: Retrieved narinfo from S3:1612 StorePath: /private/var/tb/4/scratch/69a84526bfbe447a/build/TestClientFallsBackToClosures1445388935/001/store/6fk2c15nj1bhilsda0r5gkvx8j4w7aks-b16132026/10/25 17:16:40 WARN Failed to register uploaded object key=dm55pid9dmm82q4gqy7lbvm6bcnpahpq.ls error="server returned 404: 404 page not found\n"1614 URL: nar/1k25zdncd0qa9qssi7dz190gs6rib66gbnnnkcwmgbg8p0b93ila.nar.zst1615 Compression: zstd1616 NarHash: sha256:1k25zdncd0qa9qssi7dz190gs6rib66gbnnnkcwmgbg8p0b93ila1617 NarSize: 2561618 References: /private/var/tb/4/scratch/69a84526bfbe447a/build/TestClientFallsBackToClosures1445388935/001/store/21gv8b2py01k8yl9xvxag3my5302jyqa-shared-dep1619 CA: text:sha256:0mvdw32g2ksa386yv25d5yhrk4w36j87mqlgc2iqbsj2xhdb202m16202026/10/25 17:16:40 WARN Failed to register uploaded object key=nar/0v28sj1s02fay38hviy8067vdazs8mrlmhrb5mcmigq1ahy3nf3v.nar.zst error="server returned 404: 404 page not found\n"16212026/10/25 17:16:40 WARN Failed to register uploaded object key=pjp1vs0ydqam0xjkg8s8f4r7jq5sg5hy.ls error="server returned 404: 404 page not found\n"16222026/10/25 17:16:40 WARN Failed to register uploaded object key=x35xzb6r3jj3msrajhbgakahzdgcihjs.ls error="server returned 404: 404 page not found\n"16232026/10/25 17:16:40 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign16242026/10/25 17:16:40 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"16252026/10/25 17:16:40 INFO Signed narinfos id=1 count=316262026/10/25 17:16:40 INFO Uploading 3 narinfos16272026/10/25 17:16:40 WARN Failed to register uploaded object key=dm55pid9dmm82q4gqy7lbvm6bcnpahpq.narinfo error="server returned 404: 404 page not found\n"16282026/10/25 17:16:40 INFO Received complete push request method=POST path=/api/pushes/1/complete16292026/10/25 17:16:40 WARN Failed to register uploaded object key=x35xzb6r3jj3msrajhbgakahzdgcihjs.narinfo error="server returned 404: 404 page not found\n"1630--- PASS: TestClientFallsBackToClosures (8.71s)1631=== CONT TestService_ReadAuthMiddleware16322026/10/25 17:16:40 WARN Failed to register uploaded object key=pjp1vs0ydqam0xjkg8s8f4r7jq5sg5hy.narinfo error="server returned 404: 404 page not found\n"1633--- PASS: TestConnectWaitsForAPeerMigration (8.94s)1634=== CONT TestService_AuthMiddleware_MTLSProxyHeader16352026/10/25 17:16:40 INFO Completed push id=1 objects=8 duration=42.850667ms16362026/10/25 17:16:40 INFO Upload complete. (396ms)1637=== NAME TestClientPushesUseOnePush1638 client_pushes_test.go:97: Retrieved narinfo from S3:1639 StorePath: /private/var/tb/4/scratch/69a84526bfbe447a/build/TestClientPushesUseOnePush415574951/001/store/x35xzb6r3jj3msrajhbgakahzdgcihjs-shared-dep1640 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1641 Compression: zstd1642 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821643 NarSize: 1361644 References: 1645 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1646 client_pushes_test.go:97: Retrieved narinfo from S3:1647 StorePath: /private/var/tb/4/scratch/69a84526bfbe447a/build/TestClientPushesUseOnePush415574951/001/store/pjp1vs0ydqam0xjkg8s8f4r7jq5sg5hy-a1648 URL: nar/0v28sj1s02fay38hviy8067vdazs8mrlmhrb5mcmigq1ahy3nf3v.nar.zst1649 Compression: zstd1650 NarHash: sha256:0v28sj1s02fay38hviy8067vdazs8mrlmhrb5mcmigq1ahy3nf3v1651 NarSize: 2561652 References: /private/var/tb/4/scratch/69a84526bfbe447a/build/TestClientPushesUseOnePush415574951/001/store/x35xzb6r3jj3msrajhbgakahzdgcihjs-shared-dep1653 CA: text:sha256:18iaaqqrrk03kvp2amwbfj63yzr3l5qlfkh4dasbmvjhz03ipgvy1654 client_pushes_test.go:97: Retrieved narinfo from S3:1655 StorePath: /private/var/tb/4/scratch/69a84526bfbe447a/build/TestClientPushesUseOnePush415574951/001/store/dm55pid9dmm82q4gqy7lbvm6bcnpahpq-b1656 URL: nar/0v28sj1s02fay38hviy8067vdazs8mrlmhrb5mcmigq1ahy3nf3v.nar.zst1657 Compression: zstd1658 NarHash: sha256:0v28sj1s02fay38hviy8067vdazs8mrlmhrb5mcmigq1ahy3nf3v1659 NarSize: 2561660 References: /private/var/tb/4/scratch/69a84526bfbe447a/build/TestClientPushesUseOnePush415574951/001/store/x35xzb6r3jj3msrajhbgakahzdgcihjs-shared-dep1661 CA: text:sha256:18iaaqqrrk03kvp2amwbfj63yzr3l5qlfkh4dasbmvjhz03ipgvy1662--- PASS: TestClientPushesUseOnePush (8.55s)1663=== CONT TestService_AuthMiddleware_MTLSBoundSubjects16642026/10/25 17:16:40 INFO lead: released remote=192.0.2.1:12341665--- PASS: TestLeadElectsOneAndHandsOver (10.72s)1666=== CONT TestProxyWriteTimeout/narinfo1667=== CONT TestProxyWriteTimeout/unknown_size1668=== CONT TestProxyWriteTimeout/10_GiB_nar1669=== CONT TestProxyWriteTimeout/1_GiB_nar1670--- PASS: TestProxyWriteTimeout (0.00s)1671 --- PASS: TestProxyWriteTimeout/narinfo (0.00s)1672 --- PASS: TestProxyWriteTimeout/unknown_size (0.00s)1673 --- PASS: TestProxyWriteTimeout/10_GiB_nar (0.00s)1674 --- PASS: TestProxyWriteTimeout/1_GiB_nar (0.00s)1675=== CONT TestPendingClosureWriteTimeout/empty1676=== CONT TestPendingClosureWriteTimeout/670k_objects1677=== CONT TestPendingClosureWriteTimeout/400_objects1678=== CONT TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline1679=== RUN TestService_AuthMiddleware_OIDC/valid_OIDC_token1680=== PAUSE TestService_AuthMiddleware_OIDC/valid_OIDC_token1681=== RUN TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1682=== PAUSE TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1683=== RUN TestService_AuthMiddleware_OIDC/malformed_token_rejected1684=== PAUSE TestService_AuthMiddleware_OIDC/malformed_token_rejected1685=== RUN TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1686=== PAUSE TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1687=== CONT TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key16882026/10/25 17:16:40 INFO Received request for more parts method=POST path=/1689=== CONT TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key16902026/10/25 17:16:40 INFO Received complete multipart upload request method=POST path=/1691=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal16922026/10/25 17:16:40 INFO Received uploads request method=POST path=/1693=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info16942026/10/25 17:16:40 INFO Received uploads request method=POST path=/1695--- PASS: TestUploadHandlersRejectInvalidKeys (0.07s)1696 --- PASS: TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key (0.00s)1697 --- PASS: TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key (0.01s)1698 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal (0.00s)1699 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info (0.00s)1700=== CONT TestUploadHandlersRejectOversizedBody/create_pending_closure17012026/10/25 17:16:40 INFO Received uploads request method=POST path=/1702=== NAME TestPinProtectsFromGC1703 client_integration_test.go:731: Pinned store path: /private/var/tb/4/scratch/69a84526bfbe447a/build/TestPinProtectsFromGC1421379223/001/store/ka39s9523n3n19s9zl3fzr1n7wgbq760-pinned-file.txt1704 client_integration_test.go:732: Unpinned store path: /private/var/tb/4/scratch/69a84526bfbe447a/build/TestPinProtectsFromGC1421379223/001/store/l5170fbyq7clabz08gv12np3qdzksxjw-unpinned-file.txt17052026/10/25 17:16:40 INFO Received push request method=POST path=/api/pushes17062026/10/25 17:16:41 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)17072026/10/25 17:16:41 INFO Uploading ka39s9523n3n19s9zl3fzr1n7wgbq760-pinned-file.txt (128B)17082026/10/25 17:16:41 WARN Failed to register uploaded object key=ka39s9523n3n19s9zl3fzr1n7wgbq760.ls error="server returned 404: 404 page not found\n"17092026/10/25 17:16:41 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign17102026/10/25 17:16:41 WARN Failed to register uploaded object key=nar/0qmhsg42pqsz7x6hh02j8gznnac3yi3qpjhrqbwvz88i194jbb5s.nar.zst error="server returned 404: 404 page not found\n"17112026/10/25 17:16:41 INFO Signed narinfos id=1 count=117122026/10/25 17:16:41 INFO Uploading 1 narinfos1713--- PASS: TestService_ReadScope_PublicByDefault (7.87s)1714=== CONT TestUploadHandlersRejectOversizedBody/request_more_parts17152026/10/25 17:16:41 INFO Received request for more parts method=POST path=/1716=== CONT TestUploadHandlersRejectOversizedBody/complete_multipart17172026/10/25 17:16:41 INFO Received complete push request method=POST path=/api/pushes/1/complete17182026/10/25 17:16:41 WARN Failed to register uploaded object key=ka39s9523n3n19s9zl3fzr1n7wgbq760.narinfo error="server returned 404: 404 page not found\n"1719=== CONT TestIsValidUploadKey/narinfo17202026/10/25 17:16:41 INFO Received complete multipart upload request method=POST path=/1721=== CONT TestIsValidUploadKey/realisation_plus_in_output1722=== CONT TestIsValidUploadKey/unknown_type1723=== CONT TestIsValidUploadKey/empty_key1724=== CONT TestIsValidUploadKey/absolute1725=== CONT TestIsValidUploadKey/traversal_nar1726=== CONT TestIsValidUploadKey/traversal1727=== CONT TestIsValidUploadKey/listing_key,_narinfo_type1728=== CONT TestIsValidUploadKey/nar_key,_narinfo_type1729=== CONT TestIsValidUploadKey/narinfo_key,_nar_type1730=== CONT TestIsValidUploadKey/index.html1731=== CONT TestIsValidUploadKey/nix-cache-info1732=== CONT TestIsValidUploadKey/build_log_home-manager_file1733=== CONT TestIsValidUploadKey/realisation1734=== CONT TestIsValidUploadKey/build_log_equals1735=== CONT TestIsValidUploadKey/build_log_question_mark1736=== CONT TestIsValidUploadKey/build_log_plus_in_name1737=== CONT TestIsValidUploadKey/nar_plain1738=== CONT TestIsValidUploadKey/build_log1739=== CONT TestIsValidUploadKey/listing1740=== CONT TestIsValidUploadKey/nar_xz1741=== CONT TestIsValidUploadKey/nar_zst1742--- PASS: TestIsValidUploadKey (0.09s)1743 --- PASS: TestIsValidUploadKey/narinfo (0.00s)1744 --- PASS: TestIsValidUploadKey/realisation_plus_in_output (0.00s)1745 --- PASS: TestIsValidUploadKey/unknown_type (0.00s)1746 --- PASS: TestIsValidUploadKey/empty_key (0.00s)1747 --- PASS: TestIsValidUploadKey/absolute (0.00s)1748 --- PASS: TestIsValidUploadKey/traversal_nar (0.00s)1749 --- PASS: TestIsValidUploadKey/traversal (0.00s)1750 --- PASS: TestIsValidUploadKey/listing_key,_narinfo_type (0.00s)1751 --- PASS: TestIsValidUploadKey/nar_key,_narinfo_type (0.00s)1752 --- PASS: TestIsValidUploadKey/narinfo_key,_nar_type (0.00s)1753 --- PASS: TestIsValidUploadKey/index.html (0.00s)1754 --- PASS: TestIsValidUploadKey/nix-cache-info (0.00s)1755 --- PASS: TestIsValidUploadKey/build_log_home-manager_file (0.00s)1756 --- PASS: TestIsValidUploadKey/realisation (0.00s)1757 --- PASS: TestIsValidUploadKey/build_log_equals (0.00s)1758 --- PASS: TestIsValidUploadKey/build_log_question_mark (0.00s)1759 --- PASS: TestIsValidUploadKey/build_log_plus_in_name (0.00s)1760 --- PASS: TestIsValidUploadKey/nar_plain (0.00s)1761 --- PASS: TestIsValidUploadKey/build_log (0.00s)1762 --- PASS: TestIsValidUploadKey/listing (0.00s)1763 --- PASS: TestIsValidUploadKey/nar_xz (0.00s)1764 --- PASS: TestIsValidUploadKey/nar_zst (0.00s)1765=== CONT TestPush_RejectsBadRequests/root_not_in_objects17662026/10/25 17:16:41 INFO Received push request method=POST path=/api/pushes1767=== CONT TestPush_RejectsBadRequests/no_objects17682026/10/25 17:16:41 INFO Received push request method=POST path=/api/pushes1769=== CONT TestPush_RejectsBadRequests/bad_root17702026/10/25 17:16:41 INFO Received push request method=POST path=/api/pushes1771=== CONT TestPush_RejectsBadRequests/no_roots17722026/10/25 17:16:41 INFO Received push request method=POST path=/api/pushes1773--- PASS: TestPush_RejectsBadRequests (17.96s)1774 --- PASS: TestPush_RejectsBadRequests/root_not_in_objects (0.00s)1775 --- PASS: TestPush_RejectsBadRequests/no_objects (0.00s)1776 --- PASS: TestPush_RejectsBadRequests/bad_root (0.00s)1777 --- PASS: TestPush_RejectsBadRequests/no_roots (0.00s)1778=== CONT TestIsValidCachePath/narinfo1779=== CONT TestIsValidCachePath/index.html1780=== CONT TestIsValidCachePath/short_hash1781=== CONT TestIsValidCachePath/wrong_extension1782=== CONT TestIsValidCachePath/leading_slash1783=== CONT TestIsValidCachePath/empty1784=== CONT TestIsValidCachePath/random_path1785=== CONT TestIsValidCachePath/invalid_char_u1786=== CONT TestIsValidCachePath/invalid_char_e1787=== CONT TestIsValidCachePath/traversal_in_middle1788=== CONT TestIsValidCachePath/traversal_parent1789=== CONT TestIsValidCachePath/nar_uncompressed1790=== CONT TestIsValidCachePath/nix-cache-info1791=== CONT TestIsValidCachePath/realisation1792=== CONT TestIsValidCachePath/log1793=== CONT TestIsValidCachePath/ls1794=== CONT TestIsValidCachePath/nar_xz1795=== CONT TestIsValidCachePath/nar_bz21796=== CONT TestIsValidCachePath/nar_zst1797=== CONT TestIsValidCachePath/narinfo_all_nix_base32_chars1798--- PASS: TestIsValidCachePath (0.22s)1799 --- PASS: TestIsValidCachePath/narinfo (0.00s)1800 --- PASS: TestIsValidCachePath/index.html (0.00s)1801 --- PASS: TestIsValidCachePath/short_hash (0.00s)1802 --- PASS: TestIsValidCachePath/wrong_extension (0.00s)1803 --- PASS: TestIsValidCachePath/leading_slash (0.00s)1804 --- PASS: TestIsValidCachePath/empty (0.00s)1805 --- PASS: TestIsValidCachePath/random_path (0.00s)1806 --- PASS: TestIsValidCachePath/invalid_char_u (0.00s)1807 --- PASS: TestIsValidCachePath/invalid_char_e (0.00s)1808 --- PASS: TestIsValidCachePath/traversal_in_middle (0.00s)1809 --- PASS: TestIsValidCachePath/traversal_parent (0.00s)1810 --- PASS: TestIsValidCachePath/nar_uncompressed (0.00s)1811 --- PASS: TestIsValidCachePath/nix-cache-info (0.00s)1812 --- PASS: TestIsValidCachePath/realisation (0.00s)1813 --- PASS: TestIsValidCachePath/log (0.00s)1814 --- PASS: TestIsValidCachePath/ls (0.00s)1815 --- PASS: TestIsValidCachePath/nar_xz (0.00s)1816 --- PASS: TestIsValidCachePath/nar_bz2 (0.00s)1817 --- PASS: TestIsValidCachePath/nar_zst (0.00s)1818 --- PASS: TestIsValidCachePath/narinfo_all_nix_base32_chars (0.00s)1819=== CONT TestParseSingleRange/none1820=== CONT TestPresentNotReportedWhileGCDeletesClosure/stale1821=== CONT TestParseSingleRange/start_far_past_EOF1822=== CONT TestParseSingleRange/start_past_EOF1823=== CONT TestParseSingleRange/single_byte1824=== CONT TestParseSingleRange/suffix_exceeds_size1825=== CONT TestParseSingleRange/suffix1826--- PASS: TestUploadHandlersRejectOversizedBody (0.08s)1827 --- PASS: TestUploadHandlersRejectOversizedBody/create_pending_closure (0.32s)1828 --- PASS: TestUploadHandlersRejectOversizedBody/request_more_parts (0.02s)1829 --- PASS: TestUploadHandlersRejectOversizedBody/complete_multipart (0.03s)1830=== CONT TestParseSingleRange/end_clamped_to_size1831=== CONT TestParseSingleRange/open-ended1832=== CONT TestParseSingleRange/closed18332026/10/25 17:16:41 INFO Completed push id=1 objects=3 duration=35.217791ms1834=== CONT TestParseSingleRange/malformed_end_before_start1835=== CONT TestParseSingleRange/malformed_both_empty1836=== CONT TestParseSingleRange/malformed_no_dash1837=== CONT TestParseSingleRange/multi-range_ignored1838=== CONT TestParseSingleRange/unknown_unit1839--- PASS: TestParseSingleRange (0.22s)1840 --- PASS: TestParseSingleRange/none (0.00s)1841 --- PASS: TestParseSingleRange/start_far_past_EOF (0.00s)1842 --- PASS: TestParseSingleRange/start_past_EOF (0.00s)1843 --- PASS: TestParseSingleRange/single_byte (0.00s)1844 --- PASS: TestParseSingleRange/suffix_exceeds_size (0.00s)1845 --- PASS: TestParseSingleRange/suffix (0.00s)1846 --- PASS: TestParseSingleRange/end_clamped_to_size (0.00s)1847 --- PASS: TestParseSingleRange/open-ended (0.00s)1848 --- PASS: TestParseSingleRange/closed (0.00s)1849 --- PASS: TestParseSingleRange/malformed_end_before_start (0.00s)1850 --- PASS: TestParseSingleRange/malformed_both_empty (0.00s)1851 --- PASS: TestParseSingleRange/malformed_no_dash (0.00s)1852 --- PASS: TestParseSingleRange/multi-range_ignored (0.00s)1853 --- PASS: TestParseSingleRange/unknown_unit (0.00s)1854=== CONT TestPresentNotReportedWhileGCDeletesClosure/fresh18552026/10/25 17:16:41 INFO Upload complete. (291ms)18562026/10/25 17:16:41 INFO Received push request method=POST path=/api/pushes18572026/10/25 17:16:41 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)18582026/10/25 17:16:41 INFO Uploading l5170fbyq7clabz08gv12np3qdzksxjw-unpinned-file.txt (128B)18592026/10/25 17:16:41 WARN Failed to register uploaded object key=l5170fbyq7clabz08gv12np3qdzksxjw.ls error="server returned 404: 404 page not found\n"18602026/10/25 17:16:41 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign18612026/10/25 17:16:41 WARN Failed to register uploaded object key=nar/0gh0wdnr6gmk4r5sfzzh12isnl14rgmkrwy1ws41hpsrlndclg5h.nar.zst error="server returned 404: 404 page not found\n"18622026/10/25 17:16:41 INFO Signed narinfos id=2 count=118632026/10/25 17:16:41 INFO Uploading 1 narinfos1864--- PASS: TestConcurrentCommitsSharingObjectsDoNotDeadlock (9.21s)1865=== CONT TestServerTLSConfig/no_client_CA1866=== CONT TestServerTLSConfig/not_a_PEM_file1867=== CONT TestServerTLSConfig/missing_CA_file1868--- PASS: TestServerTLSConfig (0.01s)1869 --- PASS: TestServerTLSConfig/no_client_CA (0.00s)1870 --- PASS: TestServerTLSConfig/not_a_PEM_file (0.03s)1871 --- PASS: TestServerTLSConfig/missing_CA_file (0.00s)1872=== CONT TestCacheConfigHandler/full_config,_no_issuer1873=== CONT TestCacheConfigHandler/no_signing_keys1874=== CONT TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1875=== CONT TestCacheConfigHandler/no_cache_url_configured18762026/10/25 17:16:41 INFO Received complete push request method=POST path=/api/pushes/2/complete18772026/10/25 17:16:41 WARN Failed to register uploaded object key=l5170fbyq7clabz08gv12np3qdzksxjw.narinfo error="server returned 404: 404 page not found\n"1878--- PASS: TestCacheConfigHandler (0.01s)1879 --- PASS: TestCacheConfigHandler/full_config,_no_issuer (0.00s)1880 --- PASS: TestCacheConfigHandler/no_signing_keys (0.00s)1881 --- PASS: TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator (0.00s)1882 --- PASS: TestCacheConfigHandler/no_cache_url_configured (0.00s)1883=== CONT TestClientErrorHandling/InvalidStorePath18842026/10/25 17:16:41 INFO Completed push id=2 objects=3 duration=701.75µs18852026/10/25 17:16:41 INFO Upload complete. (240ms)1886=== RUN TestService_RequireScope_OIDC/builder_may_write1887=== PAUSE TestService_RequireScope_OIDC/builder_may_write1888=== RUN TestService_RequireScope_OIDC/builder_may_not_admin1889=== PAUSE TestService_RequireScope_OIDC/builder_may_not_admin1890=== RUN TestService_RequireScope_OIDC/ops_may_admin1891=== PAUSE TestService_RequireScope_OIDC/ops_may_admin1892=== RUN TestService_RequireScope_OIDC/ops_may_not_write1893=== PAUSE TestService_RequireScope_OIDC/ops_may_not_write1894=== RUN TestService_RequireScope_OIDC/reader_may_not_write1895=== PAUSE TestService_RequireScope_OIDC/reader_may_not_write1896=== RUN TestService_RequireScope_OIDC/static_token_may_admin1897=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin1898=== RUN TestService_RequireScope_OIDC/static_token_may_write1899=== PAUSE TestService_RequireScope_OIDC/static_token_may_write1900=== RUN TestService_RequireScope_OIDC/reader_may_read1901=== PAUSE TestService_RequireScope_OIDC/reader_may_read1902=== RUN TestService_RequireScope_OIDC/writer_implies_read1903=== PAUSE TestService_RequireScope_OIDC/writer_implies_read1904=== RUN TestService_RequireScope_OIDC/anonymous_may_not_read1905=== PAUSE TestService_RequireScope_OIDC/anonymous_may_not_read1906=== RUN TestService_RequireScope_OIDC/reader_may_read_with_netrc1907=== PAUSE TestService_RequireScope_OIDC/reader_may_read_with_netrc1908=== RUN TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1909=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1910=== RUN TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read1911=== PAUSE TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read1912=== RUN TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1913=== PAUSE TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1914=== CONT TestClientErrorHandling/ServerNotAvailable19152026/10/25 17:16:41 INFO Starting cleanup of old closures method=DELETE path=/api/closures19162026/10/25 17:16:41 INFO Garbage collection started19172026/10/25 17:16:41 INFO Aborted multipart uploads count=0 kept=019182026/10/25 17:16:41 WARN Force mode enabled - objects will be deleted immediately without grace period19192026/10/25 17:16:41 WARN readiness check failed error="closed pool"1920--- PASS: TestService_readinessHandler (7.84s)1921=== CONT TestClientErrorHandling/InvalidAuthToken19222026/10/25 17:16:41 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/present19232026/10/25 17:16:42 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=019242026/10/25 17:16:42 WARN Request failed, retrying attempt=2 backoff=199.974104ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present19252026/10/25 17:16:42 INFO Vacuumed table table=pending_closures19262026/10/25 17:16:42 INFO Vacuumed table table=pending_objects19272026/10/25 17:16:42 INFO Vacuumed table table=multipart_uploads19282026/10/25 17:16:42 INFO Vacuumed table table=closures19292026/10/25 17:16:42 INFO Vacuumed table table=objects19302026/10/25 17:16:42 WARN Request failed, retrying attempt=3 backoff=434.090731ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present1931--- PASS: TestService_healthCheckHandler (8.12s)1932=== CONT TestResolveDBConnectionString/flag_wins1933=== CONT TestResolveDBConnectionString/PGHOST_allows_empty1934=== CONT TestResolveDBConnectionString/nothing_configured1935=== CONT TestResolveDBConnectionString/missing_file_is_an_error1936=== CONT TestResolveDBConnectionString/file_when_flag_empty1937=== CONT TestGCEndsOnShutdown/before_the_run1938--- PASS: TestResolveDBConnectionString (0.07s)1939 --- PASS: TestResolveDBConnectionString/flag_wins (0.00s)1940 --- PASS: TestResolveDBConnectionString/PGHOST_allows_empty (0.00s)1941 --- PASS: TestResolveDBConnectionString/nothing_configured (0.00s)1942 --- PASS: TestResolveDBConnectionString/missing_file_is_an_error (0.00s)1943 --- PASS: TestResolveDBConnectionString/file_when_flag_empty (0.00s)19442026/10/25 17:16:42 INFO Aborted multipart uploads count=0 kept=019452026/10/25 17:16:42 WARN Request failed, retrying attempt=4 backoff=765.297143ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present19462026/10/25 17:16:42 WARN Force mode enabled - objects will be deleted immediately without grace period19472026/10/25 17:16:42 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=019482026/10/25 17:16:42 INFO Vacuumed table table=pending_closures19492026/10/25 17:16:42 INFO Vacuumed table table=pending_objects19502026/10/25 17:16:42 INFO Vacuumed table table=multipart_uploads19512026/10/25 17:16:42 INFO Vacuumed table table=closures19522026/10/25 17:16:42 INFO Vacuumed table table=objects19532026/10/25 17:16:42 INFO Aborted multipart uploads count=0 kept=019542026/10/25 17:16:42 WARN Force mode enabled - objects will be deleted immediately without grace period19552026/10/25 17:16:43 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=019562026/10/25 17:16:43 INFO Vacuumed table table=pending_closures19572026/10/25 17:16:43 INFO Vacuumed table table=pending_objects19582026/10/25 17:16:43 INFO Vacuumed table table=multipart_uploads19592026/10/25 17:16:43 INFO Vacuumed table table=closures19602026/10/25 17:16:43 INFO Aborted multipart uploads count=0 kept=019612026/10/25 17:16:43 INFO Vacuumed table table=objects1962--- PASS: TestSweepSkipsRowsLockedByPush (8.33s)1963=== CONT TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark19642026/10/25 17:16:43 WARN Force mode enabled - objects will be deleted immediately without grace period19652026/10/25 17:16:43 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=019662026/10/25 17:16:43 INFO Vacuumed table table=pending_closures19672026/10/25 17:16:43 INFO Vacuumed table table=pending_objects19682026/10/25 17:16:43 INFO Vacuumed table table=multipart_uploads19692026/10/25 17:16:43 INFO Vacuumed table table=closures19702026/10/25 17:16:43 INFO Vacuumed table table=objects1971--- PASS: TestSweepRechecksPendingAfterLocking (8.38s)1972=== CONT TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete1973--- PASS: TestGetExistingObjectsLocksRows (8.09s)1974=== CONT TestForceGCDuringPushOffersSweptObject/before_pending_rows19752026/10/25 17:16:43 WARN Request failed, retrying attempt=5 backoff=1.446264307s error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present19762026/10/25 17:16:43 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=019772026/10/25 17:16:43 INFO Received create pin request method=POST path=/api/pins/myapp19782026/10/25 17:16:43 INFO Created/updated pin name=myapp store_path=/private/var/tb/4/scratch/69a84526bfbe447a/build/TestPinProtectsFromGC1421379223/001/store/ka39s9523n3n19s9zl3fzr1n7wgbq760-pinned-file.txt narinfo_key=ka39s9523n3n19s9zl3fzr1n7wgbq760.narinfo19792026/10/25 17:16:43 INFO Starting cleanup of old closures method=DELETE path=/api/closures19802026/10/25 17:16:43 INFO Garbage collection started19812026/10/25 17:16:43 INFO Aborted multipart uploads count=0 kept=019822026/10/25 17:16:43 WARN Force mode enabled - objects will be deleted immediately without grace period19832026/10/25 17:16:43 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=019842026/10/25 17:16:43 INFO Vacuumed table table=pending_closures19852026/10/25 17:16:43 INFO Vacuumed table table=pending_objects19862026/10/25 17:16:43 INFO Vacuumed table table=multipart_uploads19872026/10/25 17:16:43 INFO Vacuumed table table=closures19882026/10/25 17:16:43 INFO Vacuumed table table=objects19892026/10/25 17:16:44 INFO Aborted multipart uploads count=0 kept=019902026/10/25 17:16:44 WARN Force mode enabled - objects will be deleted immediately without grace period19912026/10/25 17:16:44 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=019922026/10/25 17:16:44 INFO Vacuumed table table=pending_closures19932026/10/25 17:16:44 INFO Vacuumed table table=pending_objects19942026/10/25 17:16:44 INFO Vacuumed table table=multipart_uploads1995--- PASS: TestRegisterCompletedObjectNeedsPendingRow (7.41s)1996=== CONT TestForceGCDuringPushOffersSweptObject/after_presence_check19972026/10/25 17:16:44 INFO Vacuumed table table=closures19982026/10/25 17:16:44 INFO Vacuumed table table=objects1999--- PASS: TestCommitRacingPendingCleanupKeepsObjects (8.13s)2000=== CONT TestService_AuthMiddleware_OIDC/valid_OIDC_token2001=== CONT TestService_AuthMiddleware_OIDC/malformed_token_rejected20022026/10/25 17:16:44 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]2003=== CONT TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2004=== CONT TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected20052026/10/25 17:16:44 WARN Authentication failed token_preview=eyJhbGciOi...rdTiViVZfg token_length=701 oidc_error="no rule matched: claim \"repository_owner\" value [otherorg] not in allowed patterns [myorg]" oidc_provider=test tried_providers=[test]2006=== CONT TestService_RequireScope_OIDC/builder_may_write2007=== CONT TestService_RequireScope_OIDC/writer_implies_read2008--- PASS: TestService_AuthMiddleware_OIDC (7.84s)2009 --- PASS: TestService_AuthMiddleware_OIDC/valid_OIDC_token (0.00s)2010 --- PASS: TestService_AuthMiddleware_OIDC/malformed_token_rejected (0.00s)2011 --- PASS: TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured (0.00s)2012 --- PASS: TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected (0.00s)2013=== CONT TestService_RequireScope_OIDC/reader_may_read2014=== CONT TestService_RequireScope_OIDC/static_token_may_write2015=== CONT TestService_RequireScope_OIDC/static_token_may_admin2016=== CONT TestService_RequireScope_OIDC/reader_may_not_write2017=== CONT TestService_RequireScope_OIDC/ops_may_not_write2018--- PASS: TestDeleteClosuresRacingPins (13.90s)2019=== CONT TestService_RequireScope_OIDC/ops_may_admin2020=== CONT TestService_RequireScope_OIDC/builder_may_not_admin2021=== CONT TestService_RequireScope_OIDC/static_token_may_admin_with_netrc2022=== CONT TestService_RequireScope_OIDC/empty_netrc_password_may_not_read2023=== CONT TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read20242026/10/25 17:16:44 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]2025=== CONT TestService_RequireScope_OIDC/anonymous_may_not_read2026=== CONT TestService_RequireScope_OIDC/reader_may_read_with_netrc2027--- PASS: TestService_RequireScope_OIDC (7.77s)2028 --- PASS: TestService_RequireScope_OIDC/builder_may_write (0.00s)2029 --- PASS: TestService_RequireScope_OIDC/writer_implies_read (0.00s)2030 --- PASS: TestService_RequireScope_OIDC/reader_may_read (0.00s)2031 --- PASS: TestService_RequireScope_OIDC/static_token_may_write (0.00s)2032 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin (0.00s)2033 --- PASS: TestService_RequireScope_OIDC/reader_may_not_write (0.00s)2034 --- PASS: TestService_RequireScope_OIDC/ops_may_not_write (0.00s)2035 --- PASS: TestService_RequireScope_OIDC/ops_may_admin (0.00s)2036 --- PASS: TestService_RequireScope_OIDC/builder_may_not_admin (0.00s)2037 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin_with_netrc (0.00s)2038 --- PASS: TestService_RequireScope_OIDC/empty_netrc_password_may_not_read (0.00s)2039 --- PASS: TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read (0.00s)2040 --- PASS: TestService_RequireScope_OIDC/anonymous_may_not_read (0.00s)2041 --- PASS: TestService_RequireScope_OIDC/reader_may_read_with_netrc (0.00s)2042=== NAME TestOrphanedObjectsGCStressTest2043 orphaned_objects_gc_test.go:422: Created 10 active closures, 5 to-delete closures, 20 orphaned chains2044 orphaned_objects_gc_test.go:440: Marked 210 objects for deletion20452026/10/25 17:16:44 INFO Received uploads request method=POST path=/api/pending_closures20462026/10/25 17:16:44 INFO Received uploads request method=POST path=/api/pending_closures2047--- PASS: TestCreatePendingClosureVerifyS3FailureReleasesConnection (6.85s)20482026/10/25 17:16:44 INFO Received uploads request method=POST path=/api/pending_closures2049--- PASS: TestPushWaitsForSweepHoldingRow (7.43s)2050--- PASS: TestTombstonedObjectOfferedWithoutWaiting (6.37s)20512026/10/25 17:16:44 WARN Request failed, retrying attempt=1 backoff=100ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config20522026/10/25 17:16:45 WARN Request failed, retrying attempt=2 backoff=199.833413ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config20532026/10/25 17:16:45 INFO Received uploads request method=POST path=/api/pending_closures20542026/10/25 17:16:45 WARN Request failed, retrying attempt=3 backoff=420.351343ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config20552026/10/25 17:16:45 INFO Aborted multipart uploads count=0 kept=020562026/10/25 17:16:45 WARN Force mode enabled - objects will be deleted immediately without grace period20572026/10/25 17:16:45 ERROR failed to remove object object=nar/dddddddddddddddddddddddddddddddddddddddddddddddddddd.nar.zst error="Access Denied."20582026/10/25 17:16:45 ERROR failed to remove object object=dddddddddddddddddddddddddddddddd.narinfo error="Access Denied."2059--- PASS: TestFailedS3DeleteKeepsTombstone (7.32s)20602026/10/25 17:16:45 INFO Aborted multipart uploads count=0 kept=02061=== NAME TestPinProtectsFromGC2062 client_integration_test.go:840: Pin successfully protected closure from garbage collection20632026/10/25 17:16:45 WARN Force mode enabled - objects will be deleted immediately without grace period20642026/10/25 17:16:45 WARN Request failed, retrying attempt=4 backoff=778.289649ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config20652026/10/25 17:16:45 INFO Received uploads request method=POST path=/api/pending_closures2066--- PASS: TestPinProtectsFromGC (12.94s)20672026/10/25 17:16:45 INFO Aborted multipart uploads count=0 kept=020682026/10/25 17:16:45 WARN Force mode enabled - objects will be deleted immediately without grace period20692026/10/25 17:16:45 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=020702026/10/25 17:16:45 INFO Vacuumed table table=pending_closures20712026/10/25 17:16:46 INFO Vacuumed table table=pending_objects20722026/10/25 17:16:46 INFO Vacuumed table table=multipart_uploads20732026/10/25 17:16:46 INFO Vacuumed table table=closures20742026/10/25 17:16:46 INFO Vacuumed table table=objects2075--- PASS: TestGCSweepSkipsPendingObjects (5.86s)20762026/10/25 17:16:46 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=020772026/10/25 17:16:46 INFO Vacuumed table table=pending_closures20782026/10/25 17:16:46 INFO Vacuumed table table=pending_objects20792026/10/25 17:16:46 INFO Vacuumed table table=multipart_uploads20802026/10/25 17:16:46 INFO Vacuumed table table=closures20812026/10/25 17:16:46 INFO Vacuumed table table=objects2082--- PASS: TestGCSweepDeliversEachKeyOnce (7.03s)2083--- PASS: TestService_ReadAuthMiddleware (5.61s)2084--- PASS: TestService_AuthMiddleware_MTLSProxyHeader (5.86s)20852026/10/25 17:16:46 WARN Request failed, retrying attempt=5 backoff=1.754912318s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config20862026/10/25 17:16:46 INFO Received uploads request method=POST path=/api/pending_closures20872026/10/25 17:16:46 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted,O=Other"20882026/10/25 17:16:46 WARN mTLS auth: bound subjects configured but subject DN unavailable20892026/10/25 17:16:46 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted"2090--- PASS: TestService_AuthMiddleware_MTLSBoundSubjects (6.17s)2091--- PASS: TestPendingClosureWriteTimeout (0.06s)2092 --- PASS: TestPendingClosureWriteTimeout/empty (0.00s)2093 --- PASS: TestPendingClosureWriteTimeout/670k_objects (0.00s)2094 --- PASS: TestPendingClosureWriteTimeout/400_objects (0.00s)2095 --- PASS: TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline (6.75s)2096--- PASS: TestPresentNotReportedWhileGCDeletesClosure (0.00s)2097 --- PASS: TestPresentNotReportedWhileGCDeletesClosure/fresh (6.41s)2098 --- PASS: TestPresentNotReportedWhileGCDeletesClosure/stale (6.65s)20992026/10/25 17:16:47 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"21002026/10/25 17:16:48 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"21012026/10/25 17:16:48 INFO Aborted multipart uploads count=0 kept=021022026/10/25 17:16:48 WARN Force mode enabled - objects will be deleted immediately without grace period21032026/10/25 17:16:48 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"21042026-10-25 17:16:48.258 UTC [39270] ERROR: canceling statement due to user request21052026-10-25 17:16:48.258 UTC [39270] STATEMENT: -- name: MarkStaleObjects :execrows2106 WITH RECURSIVE ct AS (2107 SELECT timezone('UTC', now()) AS now2108 ),2109 closure_reach AS (2110 -- Start with all closure keys2111 SELECT o.key, o.refs2112 FROM objects o2113 INNER JOIN closures c ON o.key = c.key2114 UNION2115 -- Recursively add all referenced objects2116 SELECT o.key, o.refs2117 FROM objects o2118 INNER JOIN closure_reach cr ON o.key = ANY(cr.refs)2119 ),2120 reachable_objects AS (2121 SELECT DISTINCT key FROM closure_reach2122 ),2123 stale_objects AS (2124 SELECT o.key2125 FROM objects AS o, ct2126 WHERE2127 NOT EXISTS (2128 SELECT 12129 FROM reachable_objects ro2130 WHERE ro.key = o.key2131 )2132 AND NOT EXISTS (2133 SELECT 12134 FROM pending_objects AS po2135 WHERE po.key = o.key2136 )2137 AND o.deleted_at IS NULL -- Only mark fresh objects2138 ORDER BY o.key COLLATE "C" -- lock in key order, like commit_pending_closure2139 FOR UPDATE2140 )2141 UPDATE objects2142 SET2143 deleted_at = ct.now,2144 first_deleted_at = COALESCE(first_deleted_at, ct.now)2145 FROM stale_objects, ct2146 WHERE objects.key = stale_objects.key2147 21482026/10/25 17:16:48 WARN Request failed, retrying attempt=1 backoff=100ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21492026/10/25 17:16:48 WARN Request failed, retrying attempt=2 backoff=195.812682ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21502026/10/25 17:16:48 INFO Received uploads request method=POST path=/api/pending_closures21512026/10/25 17:16:48 INFO Aborted multipart uploads count=0 kept=021522026/10/25 17:16:48 WARN Force mode enabled - objects will be deleted immediately without grace period21532026/10/25 17:16:48 WARN Request failed, retrying attempt=3 backoff=391.401426ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21542026/10/25 17:16:48 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=021552026/10/25 17:16:48 INFO Vacuumed table table=pending_closures21562026/10/25 17:16:48 INFO Vacuumed table table=pending_objects21572026/10/25 17:16:48 INFO Vacuumed table table=multipart_uploads21582026/10/25 17:16:48 INFO Vacuumed table table=closures21592026/10/25 17:16:48 INFO Aborted multipart uploads count=0 kept=021602026/10/25 17:16:48 WARN Force mode enabled - objects will be deleted immediately without grace period21612026/10/25 17:16:48 INFO Vacuumed table table=objects21622026/10/25 17:16:48 ERROR failed to remove object object=nar/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa.nar.zst error="Post \"http://localhost:51426/bucket99/?delete=\": context canceled"2163--- PASS: TestGCEndsOnShutdown (0.00s)2164 --- PASS: TestGCEndsOnShutdown/before_the_run (5.72s)2165 --- PASS: TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark (5.14s)2166 --- PASS: TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete (5.43s)21672026/10/25 17:16:48 WARN Request failed, retrying attempt=4 backoff=767.116505ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21682026/10/25 17:16:48 INFO Received uploads request method=POST path=/api/pending_closures21692026/10/25 17:16:48 INFO Aborted multipart uploads count=0 kept=021702026/10/25 17:16:48 WARN Force mode enabled - objects will be deleted immediately without grace period21712026/10/25 17:16:48 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=021722026/10/25 17:16:49 INFO Vacuumed table table=pending_closures21732026/10/25 17:16:49 INFO Vacuumed table table=pending_objects21742026/10/25 17:16:49 INFO Vacuumed table table=multipart_uploads21752026/10/25 17:16:49 INFO Vacuumed table table=closures21762026/10/25 17:16:49 INFO Vacuumed table table=objects2177--- PASS: TestForceGCDuringPushOffersSweptObject (0.01s)2178 --- PASS: TestForceGCDuringPushOffersSweptObject/before_pending_rows (5.50s)2179 --- PASS: TestForceGCDuringPushOffersSweptObject/after_presence_check (4.95s)21802026/10/25 17:16:49 WARN Request failed, retrying attempt=5 backoff=1.753127042s 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:16:51 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:16:51 WARN Request failed, retrying attempt=2 backoff=214.702782ms 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:16:51 WARN Request failed, retrying attempt=3 backoff=384.780319ms 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:16:52 WARN Request failed, retrying attempt=4 backoff=743.576655ms 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:16:52 WARN Request failed, retrying attempt=5 backoff=1.521305253s 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.00s)2187 --- PASS: TestClientErrorHandling/InvalidStorePath (6.12s)2188 --- PASS: TestClientErrorHandling/InvalidAuthToken (6.16s)2189 --- PASS: TestClientErrorHandling/ServerNotAvailable (13.15s)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 (36.89s)2196PASS2197{"timestamp":"2026-10-25T17:16:58.791082Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:51825","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(11)"}21982026-10-25 17:16:58.926 UTC [38580] LOG: received smart shutdown request21992026-10-25 17:16:58.927 UTC [38580] LOG: background worker "logical replication launcher" (PID 38590) exited with exit code 122002026-10-25 17:16:58.956 UTC [38585] LOG: shutting down22012026-10-25 17:16:58.956 UTC [38585] LOG: checkpoint starting: shutdown immediate22022026-10-25 17:17:00.465 UTC [38585] LOG: checkpoint complete: wrote 11663 buffers (71.2%), wrote 4 SLRU buffers; 0 WAL file(s) added, 0 removed, 31 recycled; write=0.665 s, sync=0.801 s, total=1.509 s; sync files=34049, longest=0.013 s, average=0.001 s; distance=502118 kB, estimate=502118 kB; lsn=0/201E6850, redo lsn=0/201E685022032026-10-25 17:17:00.477 UTC [38580] 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_Expired2244=== CONT TestValidateToken_BoundClaimsMismatch2245=== CONT TestValidateToken_KubernetesServiceAccount2246=== CONT TestPins_ReservedForMatchingRule2247=== CONT TestPins_TopLevelShorthand2248=== CONT TestValidateToken_ValidToken2249=== CONT TestValidateToken_NoMatchingProvider2250=== CONT TestValidateToken_MultipleProviders2251=== CONT TestNewValidator_KubernetesRequiresCA2252=== CONT TestValidateToken_WrongAudience2253=== CONT TestValidateToken_BoundSubjectMismatch2254=== CONT TestGlobMatch2255=== RUN TestGlobMatch/foo_foo2256=== PAUSE TestGlobMatch/foo_foo2257=== RUN TestGlobMatch/foo_bar2258=== PAUSE TestGlobMatch/foo_bar2259=== RUN TestGlobMatch/*_2260=== PAUSE TestGlobMatch/*_2261=== RUN TestGlobMatch/*_anything2262=== PAUSE TestGlobMatch/*_anything2263=== RUN TestGlobMatch/foo*_foo2264=== PAUSE TestGlobMatch/foo*_foo2265=== RUN TestGlobMatch/foo*_foobar2266=== PAUSE TestGlobMatch/foo*_foobar2267=== RUN TestGlobMatch/foo*_bar2268=== PAUSE TestGlobMatch/foo*_bar2269=== RUN TestGlobMatch/*bar_bar2270=== PAUSE TestGlobMatch/*bar_bar2271=== RUN TestGlobMatch/*bar_foobar2272=== PAUSE TestGlobMatch/*bar_foobar2273=== RUN TestGlobMatch/*bar_foo2274=== PAUSE TestGlobMatch/*bar_foo2275=== RUN TestGlobMatch/foo*bar_foobar2276=== PAUSE TestGlobMatch/foo*bar_foobar2277=== RUN TestGlobMatch/foo*bar_foo123bar2278=== PAUSE TestGlobMatch/foo*bar_foo123bar2279=== RUN TestGlobMatch/foo*bar_foobarbaz2280=== PAUSE TestGlobMatch/foo*bar_foobarbaz2281=== RUN TestGlobMatch/*/*_foo/bar2282=== PAUSE TestGlobMatch/*/*_foo/bar2283=== RUN TestGlobMatch/*/*_foo2284=== PAUSE TestGlobMatch/*/*_foo2285=== RUN TestGlobMatch/refs/heads/*_refs/heads/main2286=== PAUSE TestGlobMatch/refs/heads/*_refs/heads/main2287=== RUN TestGlobMatch/refs/heads/*_refs/tags/v1.02288=== PAUSE TestGlobMatch/refs/heads/*_refs/tags/v1.02289=== RUN TestGlobMatch/refs/*/main_refs/heads/main2290=== PAUSE TestGlobMatch/refs/*/main_refs/heads/main2291=== RUN TestGlobMatch/fo?_foo2292=== PAUSE TestGlobMatch/fo?_foo2293=== RUN TestGlobMatch/fo?_fo2294=== PAUSE TestGlobMatch/fo?_fo2295=== RUN TestGlobMatch/fo?_fooo2296=== PAUSE TestGlobMatch/fo?_fooo2297=== RUN TestGlobMatch/?oo_foo2298=== PAUSE TestGlobMatch/?oo_foo2299=== RUN TestGlobMatch/?oo_boo2300=== PAUSE TestGlobMatch/?oo_boo2301=== RUN TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2302=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2303=== RUN TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2304=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2305=== CONT TestGlobMatch/foo_foo2306=== CONT TestScopes_Rules2307=== CONT TestGlobMatch/*/*_foo/bar2308=== CONT TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2309=== CONT TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2310=== CONT TestGlobMatch/?oo_boo2311=== CONT TestGlobMatch/?oo_foo2312=== CONT TestGlobMatch/fo?_fooo2313=== CONT TestGlobMatch/fo?_fo2314=== CONT TestGlobMatch/fo?_foo2315=== CONT TestGlobMatch/refs/*/main_refs/heads/main2316=== CONT TestGlobMatch/refs/heads/*_refs/tags/v1.02317=== CONT TestGlobMatch/refs/heads/*_refs/heads/main2318=== CONT TestGlobMatch/*/*_foo2319=== CONT TestGlobMatch/*bar_bar2320=== CONT TestGlobMatch/foo*bar_foobarbaz2321=== CONT TestGlobMatch/foo*bar_foo123bar2322=== CONT TestGlobMatch/foo*bar_foobar2323=== CONT TestGlobMatch/*bar_foo2324=== CONT TestGlobMatch/*bar_foobar2325=== CONT TestGlobMatch/foo*_foo2326=== CONT TestGlobMatch/foo*_bar2327=== CONT TestGlobMatch/foo*_foobar2328=== CONT TestGlobMatch/*_2329=== CONT TestGlobMatch/*_anything2330=== CONT TestGlobMatch/foo_bar2331--- PASS: TestGlobMatch (0.00s)2332 --- PASS: TestGlobMatch/foo_foo (0.00s)2333 --- PASS: TestGlobMatch/*/*_foo/bar (0.00s)2334 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main (0.00s)2335 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main (0.00s)2336 --- PASS: TestGlobMatch/?oo_boo (0.00s)2337 --- PASS: TestGlobMatch/?oo_foo (0.00s)2338 --- PASS: TestGlobMatch/fo?_fooo (0.00s)2339 --- PASS: TestGlobMatch/fo?_fo (0.00s)2340 --- PASS: TestGlobMatch/fo?_foo (0.00s)2341 --- PASS: TestGlobMatch/refs/*/main_refs/heads/main (0.00s)2342 --- PASS: TestGlobMatch/refs/heads/*_refs/tags/v1.0 (0.00s)2343 --- PASS: TestGlobMatch/refs/heads/*_refs/heads/main (0.00s)2344 --- PASS: TestGlobMatch/*/*_foo (0.00s)2345 --- PASS: TestGlobMatch/*bar_bar (0.00s)2346 --- PASS: TestGlobMatch/foo*bar_foobarbaz (0.00s)2347 --- PASS: TestGlobMatch/foo*bar_foo123bar (0.00s)2348 --- PASS: TestGlobMatch/foo*bar_foobar (0.00s)2349 --- PASS: TestGlobMatch/*bar_foo (0.00s)2350 --- PASS: TestGlobMatch/*bar_foobar (0.00s)2351 --- PASS: TestGlobMatch/foo*_foo (0.00s)2352 --- PASS: TestGlobMatch/foo*_bar (0.00s)2353 --- PASS: TestGlobMatch/foo*_foobar (0.00s)2354 --- PASS: TestGlobMatch/*_ (0.00s)2355 --- PASS: TestGlobMatch/*_anything (0.00s)2356 --- PASS: TestGlobMatch/foo_bar (0.00s)2357=== CONT TestPins_ConfigValidation2358--- PASS: TestPins_ConfigValidation (0.00s)2359=== CONT TestValidateToken_KubernetesIssuerFromOwnToken2360=== CONT TestScopes_LegacyProviderDefaultsToWrite2361=== CONT TestScopes_ConfigValidation2362--- PASS: TestScopes_ConfigValidation (0.00s)23632026/10/25 17:17:02 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:52306/oidc2364--- PASS: TestValidateToken_BoundSubjectMismatch (0.06s)23652026/10/25 17:17:02 INFO OIDC provider initialized name=kubernetes issuer=https://127.0.0.1:5230823662026/10/25 17:17:02 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:52310/oidc2367--- PASS: TestValidateToken_KubernetesServiceAccount (0.10s)2368--- PASS: TestPins_ReservedForMatchingRule (0.10s)23692026/10/25 17:17:02 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:52313/oidc2370--- PASS: TestValidateToken_BoundClaimsMismatch (0.12s)23712026/10/25 17:17:02 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:52315/oidc23722026/10/25 17:17:02 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:52319/oidc2373--- PASS: TestValidateToken_WrongAudience (0.11s)23742026/10/25 17:17:02 http: TLS handshake error from 127.0.0.1:52318: read tcp 127.0.0.1:52316->127.0.0.1:52318: use of closed network connection2375--- PASS: TestNewValidator_KubernetesRequiresCA (0.12s)2376--- PASS: TestValidateToken_ValidToken (0.13s)23772026/10/25 17:17:02 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:52312/oidc23782026/10/25 17:17:02 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:52323/oidc2379--- PASS: TestValidateToken_NoMatchingProvider (0.14s)2380--- PASS: TestValidateToken_Expired (0.14s)23812026/10/25 17:17:02 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:52325/oidc2382--- PASS: TestScopes_Rules (0.16s)23832026/10/25 17:17:02 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:52328/oidc23842026/10/25 17:17:02 INFO OIDC provider initialized name=kubernetes issuer=https://oidc.eks.invalid/id/ABC1232385--- PASS: TestPins_TopLevelShorthand (0.19s)2386--- PASS: TestValidateToken_KubernetesIssuerFromOwnToken (0.17s)23872026/10/25 17:17:02 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:52332/oidc2388--- PASS: TestScopes_LegacyProviderDefaultsToWrite (0.17s)23892026/10/25 17:17:02 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:52331/oidc23902026/10/25 17:17:02 INFO OIDC provider initialized name=provider2 issuer=http://127.0.0.1:52334/oidc2391--- PASS: TestValidateToken_MultipleProviders (0.24s)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:17:06 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=== CONT TestFailedPathPrunedByLaterClosure2443--- PASS: TestSendPathsEmpty (0.00s)2444=== CONT TestDrainIsolatesPoisonPath2445=== CONT TestQueueRemoveLargeClosure2446=== CONT TestQueueConcurrentWriters2447=== CONT TestQueueFetchRemoveLifecycle2448=== CONT TestQueueRetryMovesToBack2449=== CONT TestQueueFetchBatchLimit2450=== CONT TestQueueRemove2451=== CONT TestQueueDeduplication2452=== CONT TestQueueEnqueueAndFetch2453=== CONT TestWorkerPrunesClosureDeps2454=== CONT TestWorkerKeepsPathItCannotStat2455=== CONT TestWorkerRemoveFailureIsNotProgress2456=== CONT TestDrainTimeout2457=== CONT TestWorkerUploadsAndRemoves2458=== CONT TestWorkerSkipsGCdPaths2459=== CONT TestDrainGivesUpWhenServerDown2460--- PASS: TestQueueEnqueueAndFetch (0.01s)24612026/10/25 17:17:06 INFO Upload queue status pending=224622026/10/25 17:17:06 INFO Upload queue status pending=224632026/10/25 17:17:06 INFO Uploading batch count=22464--- PASS: TestQueueFetchBatchLimit (0.01s)24652026/10/25 17:17:06 INFO Upload queue status pending=324662026/10/25 17:17:06 INFO Uploading batch count=124672026/10/25 17:17:06 ERROR Upload failed error="upload failed" count=124682026/10/25 17:17:06 WARN Store path no longer exists (garbage collected?), removing from queue path=/private/var/tb/4/scratch/69a84526bfbe447a/build/TestWorkerSkipsGCdPaths568921616/002/nonexistent2469--- PASS: TestQueueDeduplication (0.01s)24702026/10/25 17:17:06 INFO Uploading batch count=12471--- PASS: TestQueueRemove (0.01s)24722026/10/25 17:17:06 WARN Cannot stat store path, will retry later path=/private/var/tb/4/scratch/69a84526bfbe447a/build/TestWorkerKeepsPathItCannotStat228216583/002/locked/aaa error="stat /private/var/tb/4/scratch/69a84526bfbe447a/build/TestWorkerKeepsPathItCannotStat228216583/002/locked/aaa: permission denied"24732026/10/25 17:17:06 INFO Uploading batch count=124742026/10/25 17:17:06 ERROR Upload failed error="upload failed" count=124752026/10/25 17:17:06 INFO Uploading batch count=224762026/10/25 17:17:06 WARN Cannot stat store path, will retry later path=/private/var/tb/4/scratch/69a84526bfbe447a/build/TestWorkerKeepsPathItCannotStat228216583/002/locked/aaa error="stat /private/var/tb/4/scratch/69a84526bfbe447a/build/TestWorkerKeepsPathItCannotStat228216583/002/locked/aaa: permission denied"24772026/10/25 17:17:06 ERROR Upload failed error="upload failed" count=224782026/10/25 17:17:06 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/4/scratch/69a84526bfbe447a/build/TestDrainGivesUpWhenServerDown2978625444/002/a24792026/10/25 17:17:06 INFO Upload queue status pending=224802026/10/25 17:17:06 INFO Uploading batch count=124812026/10/25 17:17:06 INFO Uploading batch count=224822026/10/25 17:17:06 WARN Store path no longer exists (garbage collected?), removing from queue path=/private/var/tb/4/scratch/69a84526bfbe447a/build/TestWorkerRemoveFailureIsNotProgress739702169/002/nonexistent24832026/10/25 17:17:06 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=124842026/10/25 17:17:06 WARN Store path no longer exists (garbage collected?), removing from queue path=/private/var/tb/4/scratch/69a84526bfbe447a/build/TestWorkerRemoveFailureIsNotProgress739702169/002/nonexistent24852026/10/25 17:17:06 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=124862026/10/25 17:17:06 WARN Store path no longer exists (garbage collected?), removing from queue path=/private/var/tb/4/scratch/69a84526bfbe447a/build/TestWorkerRemoveFailureIsNotProgress739702169/002/nonexistent24872026/10/25 17:17:06 WARN Cannot stat store path, will retry later path=/private/var/tb/4/scratch/69a84526bfbe447a/build/TestWorkerKeepsPathItCannotStat228216583/002/locked/aaa error="stat /private/var/tb/4/scratch/69a84526bfbe447a/build/TestWorkerKeepsPathItCannotStat228216583/002/locked/aaa: permission denied"24882026/10/25 17:17:06 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=124892026/10/25 17:17:06 ERROR Drain finished with paths left in queue remaining=12490--- PASS: TestQueueFetchRemoveLifecycle (0.01s)24912026/10/25 17:17:06 INFO Uploading batch count=424922026/10/25 17:17:06 ERROR Upload failed error="upload failed" count=424932026/10/25 17:17:06 ERROR Drain finished with paths left in queue remaining=124942026/10/25 17:17:06 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/4/scratch/69a84526bfbe447a/build/TestDrainGivesUpWhenServerDown2978625444/002/b24952026/10/25 17:17:06 INFO Uploading batch count=124962026/10/25 17:17:06 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/4/scratch/69a84526bfbe447a/build/TestDrainIsolatesPoisonPath391548148/002/bbb24972026/10/25 17:17:06 INFO Uploading batch count=224982026/10/25 17:17:06 ERROR Upload failed error="upload failed" count=224992026/10/25 17:17:06 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/4/scratch/69a84526bfbe447a/build/TestDrainGivesUpWhenServerDown2978625444/002/c2500--- PASS: TestQueueRetryMovesToBack (0.01s)2501--- PASS: TestWorkerRemoveFailureIsNotProgress (0.01s)25022026/10/25 17:17:06 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/4/scratch/69a84526bfbe447a/build/TestDrainGivesUpWhenServerDown2978625444/002/d25032026/10/25 17:17:06 INFO Uploading batch count=125042026/10/25 17:17:06 INFO Uploading batch count=125052026/10/25 17:17:06 ERROR Upload failed error="upload failed" count=125062026/10/25 17:17:06 INFO Uploading batch count=225072026/10/25 17:17:06 ERROR Upload failed error="upload failed" count=225082026/10/25 17:17:06 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/4/scratch/69a84526bfbe447a/build/TestDrainGivesUpWhenServerDown2978625444/002/e25092026/10/25 17:17:06 INFO Uploading batch count=125102026/10/25 17:17:06 ERROR Upload failed error="upload failed" count=12511--- PASS: TestWorkerKeepsPathItCannotStat (0.01s)25122026/10/25 17:17:06 INFO Uploading batch count=125132026/10/25 17:17:06 ERROR Upload failed error="upload failed" count=125142026/10/25 17:17:06 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/4/scratch/69a84526bfbe447a/build/TestDrainGivesUpWhenServerDown2978625444/002/f25152026/10/25 17:17:06 ERROR Drain finished with paths left in queue remaining=1025162026/10/25 17:17:06 ERROR Drain finished with paths left in queue remaining=12517--- PASS: TestFailedPathPrunedByLaterClosure (0.02s)2518--- PASS: TestDrainIsolatesPoisonPath (0.02s)2519--- PASS: TestDrainGivesUpWhenServerDown (0.01s)2520--- PASS: TestWorkerSkipsGCdPaths (0.03s)2521--- PASS: TestWorkerUploadsAndRemoves (0.03s)2522--- PASS: TestWorkerPrunesClosureDeps (0.03s)2523--- PASS: TestQueueRemoveLargeClosure (0.04s)2524--- PASS: TestQueueConcurrentWriters (0.16s)25252026/10/25 17:17:06 ERROR Upload failed error="context deadline exceeded" count=225262026/10/25 17:17:06 ERROR Drain finished with paths left in queue remaining=42527--- PASS: TestDrainTimeout (0.22s)25282026/10/25 17:17:07 INFO Uploading batch count=125292026/10/25 17:17:07 INFO Uploading batch count=125302026/10/25 17:17:07 INFO Uploading batch count=125312026/10/25 17:17:07 ERROR Upload failed error="upload failed" count=125322026/10/25 17:17:07 INFO Uploading batch count=125332026/10/25 17:17:07 ERROR Upload failed error="upload failed" count=125342026/10/25 17:17:07 INFO Uploading batch count=125352026/10/25 17:17:07 ERROR Upload failed error="upload failed" count=125362026/10/25 17:17:07 INFO Uploading batch count=125372026/10/25 17:17:07 ERROR Upload failed error="upload failed" count=125382026/10/25 17:17:07 ERROR Drain finished with paths left in queue remaining=12539--- PASS: TestRunNotBlockedByPoisonHead (1.04s)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 TestSignBatch2573=== CONT TestSignErrors2574=== CONT TestSign2575=== CONT TestGenerateFingerprint2576=== CONT TestParseSigningKey2577=== RUN TestGenerateFingerprint/basic_with_references2578=== PAUSE TestGenerateFingerprint/basic_with_references2579=== CONT TestExternalSignerRejectsInvalidPublicKey2580=== CONT TestNilKeyPublicKey2581--- PASS: TestNilKeyPublicKey (0.00s)2582=== CONT TestExternalSignerProgramErrorKeepsProcess2583=== CONT TestExternalSignerErrors2584=== RUN TestExternalSignerErrors/wrong_shape2585=== RUN TestGenerateFingerprint/no_references2586=== PAUSE TestGenerateFingerprint/no_references2587=== CONT TestExternalSignerClose2588=== RUN TestParseSigningKey/valid_32-byte_key2589=== PAUSE TestParseSigningKey/valid_32-byte_key2590=== RUN TestParseSigningKey/valid_32-byte_key_with_different_name2591=== PAUSE TestParseSigningKey/valid_32-byte_key_with_different_name2592=== RUN TestParseSigningKey/no_colon2593=== PAUSE TestParseSigningKey/no_colon2594=== RUN TestParseSigningKey/empty_name2595=== PAUSE TestParseSigningKey/empty_name2596=== RUN TestParseSigningKey/invalid_base642597=== PAUSE TestParseSigningKey/invalid_base642598=== RUN TestParseSigningKey/wrong_length2599=== PAUSE TestParseSigningKey/wrong_length2600=== CONT TestParseSigningKey/valid_32-byte_key2601=== CONT TestExternalSignerRestartsAfterCrash2602=== CONT TestParseSigningKey/empty_name2603=== CONT TestParseSigningKey/wrong_length2604=== CONT TestParseSigningKey/no_colon2605=== CONT TestParseSigningKey/invalid_base642606=== RUN TestExternalSignerRejectsInvalidPublicKey/#002607=== PAUSE TestExternalSignerRejectsInvalidPublicKey/#002608=== PAUSE TestExternalSignerErrors/wrong_shape2609=== RUN TestGenerateFingerprint/unsorted_references_get_sorted2610=== CONT TestParseSigningKey/valid_32-byte_key_with_different_name2611=== CONT TestExternalSignerWrongPublicKey2612=== RUN TestExternalSignerRejectsInvalidPublicKey/no-colon2613=== PAUSE TestExternalSignerRejectsInvalidPublicKey/no-colon2614=== RUN TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2615=== PAUSE TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2616=== RUN TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2617=== RUN TestExternalSignerErrors/exit_on_request2618=== PAUSE TestGenerateFingerprint/unsorted_references_get_sorted2619=== PAUSE TestExternalSignerErrors/exit_on_request2620=== RUN TestGenerateFingerprint/invalid_nar_hash_prefix2621=== PAUSE TestGenerateFingerprint/invalid_nar_hash_prefix2622=== PAUSE TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2623=== RUN TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2624=== RUN TestExternalSignerErrors/invalid_JSON2625=== PAUSE TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2626=== RUN TestGenerateFingerprint/invalid_nar_hash_length2627=== PAUSE TestExternalSignerErrors/invalid_JSON2628=== CONT TestExternalSignerRejectsInvalidPublicKey/#002629=== CONT TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2630=== CONT TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2631=== RUN TestExternalSignerErrors/null2632=== CONT TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2633=== PAUSE TestExternalSignerErrors/null2634=== CONT TestExternalSignerRejectsInvalidPublicKey/no-colon2635=== RUN TestExternalSignerErrors/missing_signatures2636=== PAUSE TestGenerateFingerprint/invalid_nar_hash_length2637=== PAUSE TestExternalSignerErrors/missing_signatures2638=== RUN TestGenerateFingerprint/invalid_store_path_prefix2639--- PASS: TestExternalSignerRejectsInvalidPublicKey (0.00s)2640 --- PASS: TestExternalSignerRejectsInvalidPublicKey/#00 (0.00s)2641 --- PASS: TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA= (0.00s)2642 --- PASS: TestExternalSignerRejectsInvalidPublicKey/test-key:YQ== (0.00s)2643 --- PASS: TestExternalSignerRejectsInvalidPublicKey/test-key:invalid! (0.00s)2644 --- PASS: TestExternalSignerRejectsInvalidPublicKey/no-colon (0.00s)2645=== RUN TestExternalSignerErrors/unrequested_key2646=== PAUSE TestExternalSignerErrors/unrequested_key2647=== RUN TestExternalSignerErrors/wrong_id2648=== PAUSE TestExternalSignerErrors/wrong_id2649=== RUN TestExternalSignerErrors/wrong_signatures_shape2650=== PAUSE TestGenerateFingerprint/invalid_store_path_prefix2651=== PAUSE TestExternalSignerErrors/wrong_signatures_shape2652=== RUN TestExternalSignerErrors/too_few_signatures2653=== RUN TestGenerateFingerprint/invalid_reference_prefix2654=== PAUSE TestExternalSignerErrors/too_few_signatures2655=== RUN TestExternalSignerErrors/missing_signature_name2656=== PAUSE TestExternalSignerErrors/missing_signature_name2657=== PAUSE TestGenerateFingerprint/invalid_reference_prefix2658=== RUN TestExternalSignerErrors/invalid_signature_base642659=== CONT TestGenerateFingerprint/invalid_nar_hash_length2660=== CONT TestGenerateFingerprint/invalid_nar_hash_prefix2661=== PAUSE TestExternalSignerErrors/invalid_signature_base642662=== CONT TestGenerateFingerprint/no_references2663=== RUN TestExternalSignerErrors/exit_at_startup2664=== PAUSE TestExternalSignerErrors/exit_at_startup2665=== RUN TestExternalSignerErrors/null_signatures2666=== CONT TestGenerateFingerprint/invalid_reference_prefix2667=== CONT TestGenerateFingerprint/invalid_store_path_prefix2668=== CONT TestGenerateFingerprint/basic_with_references2669=== CONT TestGenerateFingerprint/unsorted_references_get_sorted2670--- PASS: TestGenerateFingerprint (0.00s)2671 --- PASS: TestGenerateFingerprint/invalid_nar_hash_length (0.00s)2672 --- PASS: TestGenerateFingerprint/invalid_nar_hash_prefix (0.00s)2673 --- PASS: TestGenerateFingerprint/no_references (0.00s)2674 --- PASS: TestGenerateFingerprint/invalid_reference_prefix (0.00s)2675 --- PASS: TestGenerateFingerprint/invalid_store_path_prefix (0.00s)2676 --- PASS: TestGenerateFingerprint/basic_with_references (0.00s)2677 --- PASS: TestGenerateFingerprint/unsorted_references_get_sorted (0.00s)2678=== PAUSE TestExternalSignerErrors/null_signatures2679=== RUN TestExternalSignerErrors/wrong_signature_name2680=== PAUSE TestExternalSignerErrors/wrong_signature_name2681=== RUN TestExternalSignerErrors/wrong_signature_length2682=== PAUSE TestExternalSignerErrors/wrong_signature_length2683=== RUN TestExternalSignerErrors/program_error2684=== PAUSE TestExternalSignerErrors/program_error2685=== CONT TestExternalSignerErrors/wrong_shape2686=== CONT TestExternalSignerErrors/wrong_signatures_shape2687=== CONT TestExternalSignerErrors/wrong_signature_name2688=== CONT TestExternalSignerErrors/missing_signature_name2689=== CONT TestExternalSignerErrors/null_signatures2690=== CONT TestExternalSignerErrors/too_few_signatures2691=== CONT TestExternalSignerErrors/wrong_signature_length2692=== CONT TestExternalSignerErrors/invalid_signature_base642693=== CONT TestExternalSignerErrors/missing_signatures2694=== CONT TestExternalSignerErrors/program_error2695=== CONT TestExternalSignerErrors/wrong_id2696=== CONT TestExternalSignerErrors/exit_at_startup2697=== CONT TestExternalSignerErrors/invalid_JSON2698=== RUN TestSignErrors/nil_key2699=== PAUSE TestSignErrors/nil_key2700=== RUN TestSignErrors/nil_narinfo2701=== PAUSE TestSignErrors/nil_narinfo2702=== RUN TestSignErrors/invalid_narinfo2703=== PAUSE TestSignErrors/invalid_narinfo2704=== RUN TestSignErrors/canceled2705=== PAUSE TestSignErrors/canceled2706=== CONT TestExternalSignerErrors/unrequested_key2707--- PASS: TestSign (0.00s)2708=== CONT TestExternalSignerErrors/exit_on_request2709=== CONT TestSignErrors/invalid_narinfo2710=== CONT TestSignErrors/canceled2711=== CONT TestSignErrors/nil_narinfo2712--- PASS: TestParseSigningKey (0.00s)2713 --- PASS: TestParseSigningKey/empty_name (0.00s)2714 --- PASS: TestParseSigningKey/wrong_length (0.00s)2715 --- PASS: TestParseSigningKey/no_colon (0.00s)2716 --- PASS: TestParseSigningKey/invalid_base64 (0.00s)2717 --- PASS: TestParseSigningKey/valid_32-byte_key (0.00s)2718 --- PASS: TestParseSigningKey/valid_32-byte_key_with_different_name (0.00s)2719--- PASS: TestSignBatch (0.00s)2720=== CONT TestExternalSignerErrors/null2721=== CONT TestSignErrors/nil_key2722--- PASS: TestSignErrors (0.00s)2723 --- PASS: TestSignErrors/invalid_narinfo (0.00s)2724 --- PASS: TestSignErrors/canceled (0.00s)2725 --- PASS: TestSignErrors/nil_narinfo (0.00s)2726 --- PASS: TestSignErrors/nil_key (0.00s)2727--- PASS: TestExternalSigner (0.23s)2728--- PASS: TestExternalSignerCancellation (0.42s)2729--- PASS: TestExternalSignerWrongPublicKey (0.76s)2730--- PASS: TestExternalSignerProgramErrorKeepsProcess (2.04s)2731--- PASS: TestExternalSignerClose (2.85s)2732--- PASS: TestExternalSignerRestartsAfterCrash (3.60s)2733/private/var/tb/4/scratch/69a84526bfbe447a/build/TestExternalSignerRestartsAfterCrash67632296/001/sign program: line 7: /private/var/tb/4/scratch/69a84526bfbe447a/build/TestExternalSignerRestartsAfterCrash67632296/001/sign program.starts: No such file or directory2734--- PASS: TestExternalSignerErrors (0.00s)2735 --- PASS: TestExternalSignerErrors/unrequested_key (0.58s)2736 --- PASS: TestExternalSignerErrors/wrong_signature_name (0.94s)2737 --- PASS: TestExternalSignerErrors/missing_signatures (1.12s)2738 --- PASS: TestExternalSignerErrors/null_signatures (1.31s)2739 --- PASS: TestExternalSignerErrors/wrong_signatures_shape (1.49s)2740 --- PASS: TestExternalSignerErrors/exit_on_request (1.67s)2741 --- PASS: TestExternalSignerErrors/wrong_id (1.85s)2742 --- PASS: TestExternalSignerErrors/program_error (2.45s)2743 --- PASS: TestExternalSignerErrors/wrong_signature_length (2.69s)2744 --- PASS: TestExternalSignerErrors/invalid_signature_base64 (3.03s)2745 --- PASS: TestExternalSignerErrors/wrong_shape (3.21s)2746 --- PASS: TestExternalSignerErrors/too_few_signatures (3.40s)2747 --- PASS: TestExternalSignerErrors/missing_signature_name (3.76s)2748 --- PASS: TestExternalSignerErrors/exit_at_startup (3.94s)2749 --- PASS: TestExternalSignerErrors/invalid_JSON (4.12s)2750 --- PASS: TestExternalSignerErrors/null (4.30s)2751PASS2752Running OpenBao signer tests...2753=== RUN TestSign2754=== PAUSE TestSign2755=== RUN TestSignErrors2756=== PAUSE TestSignErrors2757=== RUN TestServe2758=== PAUSE TestServe2759=== RUN TestServeRejectsGarbage2760=== PAUSE TestServeRejectsGarbage2761=== CONT TestSign2762=== CONT TestServe2763=== CONT TestServeRejectsGarbage2764=== CONT TestSignErrors2765=== RUN TestSignErrors/invalid_json2766--- PASS: TestServeRejectsGarbage (0.00s)2767=== PAUSE TestSignErrors/invalid_json2768=== RUN TestSignErrors/no_prefix2769=== PAUSE TestSignErrors/no_prefix2770=== RUN TestSignErrors/invalid_base642771=== PAUSE TestSignErrors/invalid_base642772=== RUN TestSignErrors/http_error2773=== PAUSE TestSignErrors/http_error2774=== CONT TestSignErrors/invalid_json2775=== CONT TestSignErrors/invalid_base642776=== CONT TestSignErrors/http_error2777=== CONT TestSignErrors/no_prefix2778--- PASS: TestServe (0.00s)2779--- PASS: TestSign (0.00s)2780--- PASS: TestSignErrors (0.00s)2781 --- PASS: TestSignErrors/http_error (0.00s)2782 --- PASS: TestSignErrors/invalid_json (0.00s)2783 --- PASS: TestSignErrors/no_prefix (0.00s)2784 --- PASS: TestSignErrors/invalid_base64 (0.00s)2785PASS