From eaf04261dcb860706b213d0d243b6418a06dfd37 Mon Sep 17 00:00:00 2001 From: spbsoluble <1661003+spbsoluble@users.noreply.github.com> Date: Wed, 14 Oct 2026 09:09:05 -0700 Subject: [PATCH 1/3] test(v2): opt-in place-order latency / enroll-sync exposure experiment (issue 0090) --- .../IntegrationTestFixture.cs | 2 + .../V2PlaceOrderLatencyExperimentTests.cs | 707 ++++++++++++++++++ 2 files changed, 709 insertions(+) create mode 100644 CERTInext.IntegrationTests/V2PlaceOrderLatencyExperimentTests.cs diff --git a/CERTInext.IntegrationTests/IntegrationTestFixture.cs b/CERTInext.IntegrationTests/IntegrationTestFixture.cs index abebc1a..fda7fa6 100644 --- a/CERTInext.IntegrationTests/IntegrationTestFixture.cs +++ b/CERTInext.IntegrationTests/IntegrationTestFixture.cs @@ -52,6 +52,8 @@ public sealed class IntegrationTestFixture : IDisposable "CERTINEXT_V2_LIFECYCLE_WILDCARD_DV", "CERTINEXT_V2_LIFECYCLE_RENEW_REISSUE", "CERTINEXT_V2_LIFECYCLE_FRESH_DCV", + // Issue 0090 V2 place-order latency experiment (places real sandbox orders). + "CERTINEXT_V2_LATENCY_EXPERIMENT", }; // --------------------------------------------------------------------------- diff --git a/CERTInext.IntegrationTests/V2PlaceOrderLatencyExperimentTests.cs b/CERTInext.IntegrationTests/V2PlaceOrderLatencyExperimentTests.cs new file mode 100644 index 0000000..9cce56f --- /dev/null +++ b/CERTInext.IntegrationTests/V2PlaceOrderLatencyExperimentTests.cs @@ -0,0 +1,707 @@ +// Copyright 2026 Keyfactor +// +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. + +using System; +using System.Collections.Concurrent; +using System.Collections.Generic; +using System.Diagnostics; +using System.Globalization; +using System.IO; +using System.Linq; +using System.Reflection; +using System.Text; +using System.Text.RegularExpressions; +using System.Threading; +using System.Threading.Tasks; +using Keyfactor.AnyGateway.Extensions; +using Keyfactor.Extensions.CAPlugin.CERTInext.API.V2; +using Keyfactor.Extensions.CAPlugin.CERTInext.Client; +using Keyfactor.PKI.Enums.EJBCA; +using Org.BouncyCastle.Asn1.X509; +using Org.BouncyCastle.Crypto.Generators; +using Org.BouncyCastle.Crypto; +using Org.BouncyCastle.Pkcs; +using Org.BouncyCastle.Security; +using Xunit; +using Xunit.Abstractions; + +namespace Keyfactor.Extensions.CAPlugin.CERTInext.IntegrationTests +{ + /// + /// Measurement experiment (issue 0090, V2 side): does the V2 API hold order placement open + /// the way V1 GenerateOrderSSL does in production (response returned 19 s / 100 s after + /// the order already exists and is issued), and how long is the window between "order visible + /// to a CA Sync" and "plugin Enroll returns the CARequestID to the gateway"? + /// + /// V2 order placement is three calls: POST create (returns orderId, order sits in + /// pending-csr), PUT /csr, then GET track (+ download / pickup poll). The plugin's real + /// Enroll is driven end to end; a wraps the real client + /// and timestamps every plugin-to-CA call, so the numbers are the plugin's own call pattern. + /// Two independent clients run beside it: + /// + /// a listing poller (the call Synchronize makes: /reports/orders) every ~1.5 s, + /// which finds the order by its unique domain BEFORE the place response returns; + /// an order tracker (GET track) every ~1 s, started the instant the place response lands. + /// + /// Opt-in: CERTINEXT_V2_LATENCY_EXPERIMENT=1 as a REAL environment variable. + /// Optional: CERTINEXT_V2_LATENCY_COUNT (default 7, max 12), + /// CERTINEXT_V2_LATENCY_SPACING_SECONDS (default 30), + /// CERTINEXT_V2_LATENCY_DOMAIN_MODE (unique = fresh subdomain of + /// CERTINEXT_DCV_DOMAIN per order [default]; reuse = CERTINEXT_DCV_DOMAIN itself). + /// Credentials come from ~/.env_certinext_v2. Raw CSV goes to experiment-results/. + /// No order numbers or timings are tied to personal data; emails are never printed. + /// + public class V2PlaceOrderLatencyExperimentTests : IClassFixture + { + private const string OptInFlag = "CERTINEXT_V2_LATENCY_EXPERIMENT"; + private const int MaxOrders = 12; + private static readonly TimeSpan ListPollInterval = TimeSpan.FromSeconds(1.5); + private static readonly TimeSpan TrackPollInterval = TimeSpan.FromSeconds(1.0); + private const int MaxListPollsInFlight = 2; + + private readonly IntegrationTestFixture _fixture; + private readonly ITestOutputHelper _output; + private readonly Stopwatch _clock = Stopwatch.StartNew(); + + private readonly string _apiUrl; + private readonly string _clientId; + private readonly string _clientSecret; + private readonly string _productCode; + private readonly string _baseDomain; + private readonly string _requestorName; + private readonly string _requestorEmail; + private readonly string _groupNumber; + private readonly bool _v2Enabled; + + public V2PlaceOrderLatencyExperimentTests(IntegrationTestFixture fixture, ITestOutputHelper output) + { + _fixture = fixture; + _output = output; + + var env = V2EnvHelper.LoadAndPromote(); + _apiUrl = V2EnvHelper.GetEnv(env, "CERTINEXT_API_URL"); + _clientId = V2EnvHelper.GetEnv(env, "CERTINEXT_CLIENT_ID"); + _clientSecret = V2EnvHelper.GetEnv(env, "CERTINEXT_CLIENT_SECRET"); + _productCode = V2EnvHelper.GetEnv(env, "CERTINEXT_PRODUCT_CODE", "842"); + _baseDomain = V2EnvHelper.GetEnv(env, "CERTINEXT_DCV_DOMAIN", string.Empty); + _requestorName = V2EnvHelper.GetEnv(env, "CERTINEXT_REQUESTOR_NAME", "Keyfactor Integration Test"); + _requestorEmail = V2EnvHelper.GetEnv(env, "CERTINEXT_REQUESTOR_EMAIL", "test@example.com"); + _groupNumber = V2EnvHelper.GetEnv(env, "CERTINEXT_GROUP_NUMBER", string.Empty); + _v2Enabled = !string.IsNullOrWhiteSpace(V2EnvHelper.GetEnv(env, "CERTINEXT_USE_V2_API")) + && !string.IsNullOrWhiteSpace(_apiUrl) + && !string.IsNullOrWhiteSpace(_clientId) + && !string.IsNullOrWhiteSpace(_clientSecret); + } + + private double Now => _clock.Elapsed.TotalSeconds; + + private static readonly Regex EmailRx = new(@"[A-Za-z0-9._%+\-]+@[A-Za-z0-9.\-]+\.[A-Za-z]{2,}", RegexOptions.Compiled); + + /// Strips anything email-shaped and caps length; used for every line that leaves the test. + private static string Scrub(string s) + { + if (string.IsNullOrEmpty(s)) return s ?? string.Empty; + s = EmailRx.Replace(s, ""); + return s.Length > 400 ? s.Substring(0, 400) + "..." : s; + } + + private static string Describe(Exception ex) => Scrub($"{ex.GetType().Name}: {ex.Message}"); + + private void W(string s) => _output.WriteLine(Scrub(s)); + + // --------------------------------------------------------------------------- + // Timing proxy: wraps the real client, timestamps every plugin-to-CA call + // --------------------------------------------------------------------------- + + public sealed class CallRecord + { + public string Name; + public double Start; + public double End; + public string Error; + public double DurationMs => (End - Start) * 1000.0; + } + + /// DispatchProxy over recording start/end of every async call. + public class TimingClientProxy : DispatchProxy + { + internal ICERTInextClient Inner; + internal Func Clock; + internal ConcurrentQueue Calls = new(); + internal Action OnResult; + + protected override object Invoke(MethodInfo targetMethod, object[] args) + { + double start = Clock(); + object ret; + try + { + ret = targetMethod.Invoke(Inner, args); + } + catch (TargetInvocationException tie) + { + Calls.Enqueue(new CallRecord { Name = targetMethod.Name, Start = start, End = Clock(), Error = Describe(tie.InnerException ?? tie) }); + throw tie.InnerException ?? tie; + } + + if (ret is Task t) + { + Type rt = targetMethod.ReturnType; + if (rt.IsGenericType && rt.GetGenericTypeDefinition() == typeof(Task<>)) + { + var m = typeof(TimingClientProxy).GetMethod(nameof(WrapTaskT), BindingFlags.NonPublic | BindingFlags.Instance) + ?.MakeGenericMethod(rt.GetGenericArguments()[0]); + return m?.Invoke(this, new object[] { t, targetMethod.Name, start }); + } + return WrapTask(t, targetMethod.Name, start); + } + return ret; // sync members and IAsyncEnumerable pass straight through, untimed + } + + private async Task WrapTask(Task t, string name, double start) + { + try { await t.ConfigureAwait(false); Calls.Enqueue(new CallRecord { Name = name, Start = start, End = Clock() }); } + catch (Exception ex) { Calls.Enqueue(new CallRecord { Name = name, Start = start, End = Clock(), Error = Describe(ex) }); throw; } + } + + private async Task WrapTaskT(Task t, string name, double start) + { + try + { + T r = await t.ConfigureAwait(false); + Calls.Enqueue(new CallRecord { Name = name, Start = start, End = Clock() }); + OnResult?.Invoke(name, r); + return r; + } + catch (Exception ex) + { + Calls.Enqueue(new CallRecord { Name = name, Start = start, End = Clock(), Error = Describe(ex) }); + throw; + } + } + } + + // --------------------------------------------------------------------------- + // Observations + // --------------------------------------------------------------------------- + + private sealed class TrackObs + { + public double Sent; + public double Recv; + public string Status; + public string Error; + } + + private sealed class ListObs + { + public double Start; + public double End; + public int Rows; + public string OrderNumber; + public string OrderStatus; + public string CertStatus; + public string Error; + public bool Matched => OrderNumber != null; + public string Combined => $"{OrderStatus}|{CertStatus}"; + } + + private sealed class Trial + { + public int Index; + public string Domain; + public string OrderId; + public DateTime T0Utc; + public double T0; + public double TPlaceResp = double.NaN; + public double TCsrResp = double.NaN; + public double TEnrollEnd = double.NaN; + public double PlaceMs = double.NaN, CsrMs = double.NaN, DownloadMs = double.NaN; + public List TrackCallMs = new(); + public string EnrollStatus = string.Empty; + public bool EnrollHasCert; + public string EnrollMessage = string.Empty; + public string CreateRespStatus = string.Empty; + public double FirstSeenList = double.NaN, FirstSeenListLower = double.NaN; + public string FirstSeenListStatus = string.Empty; + public double TrackFirstObsRecv = double.NaN; + public string TrackFirstObsStatus = string.Empty; + public string StatusAfterCsr = string.Empty; + public double TIssuedTrack = double.NaN, TIssuedTrackLower = double.NaN; + public double TIssuedList = double.NaN; + public string TrackSeq = string.Empty; + public string ListSeq = string.Empty; + public int ListPolls, ListErrors, TrackPolls, TrackErrors; + public double ListPollMedianS = double.NaN; + public string CleanupNote = string.Empty; + public string Error = string.Empty; + // One extra GET /certificate fired by the tracker the first time track reports 'issued' + // (while the CSR PUT may still be in flight): does 'issued' mean the cert is downloadable? + public double DlProbeAt = double.NaN, DlProbeMs = double.NaN; + public string DlProbeResult = string.Empty; + } + + // --------------------------------------------------------------------------- + // Helpers + // --------------------------------------------------------------------------- + + private static string F(double x) => double.IsNaN(x) ? "" : x.ToString("0.00", CultureInfo.InvariantCulture); + + private static double Median(IEnumerable xs) + { + var a = xs.Where(x => !double.IsNaN(x)).OrderBy(x => x).ToArray(); + if (a.Length == 0) return double.NaN; + return a.Length % 2 == 1 ? a[a.Length / 2] : (a[a.Length / 2 - 1] + a[a.Length / 2]) / 2.0; + } + + private static string RepoRoot() + { + var dir = new DirectoryInfo(AppContext.BaseDirectory); + while (dir != null && !File.Exists(Path.Combine(dir.FullName, "certinext-caplugin.sln"))) + dir = dir.Parent; + return dir?.FullName ?? Directory.GetCurrentDirectory(); + } + + /// RSA-2048 PKCS#10 CSR, BouncyCastle only. + private static string GenerateCsrPem(string commonName) + { + var keyGen = new RsaKeyPairGenerator(); + keyGen.Init(new KeyGenerationParameters(new SecureRandom(), 2048)); + var keyPair = keyGen.GenerateKeyPair(); + var csr = new Pkcs10CertificationRequest("SHA256withRSA", new X509Name($"CN={commonName}"), + keyPair.Public, null, keyPair.Private); + return "-----BEGIN CERTIFICATE REQUEST-----\n" + + Convert.ToBase64String(csr.GetEncoded(), Base64FormattingOptions.InsertLineBreaks) + + "\n-----END CERTIFICATE REQUEST-----"; + } + + private CERTInextConfig BuildConfig() => new CERTInextConfig + { + ApiUrl = _apiUrl, + UseV2Api = true, + OAuthClientId = _clientId, + OAuthClientSecret = _clientSecret, + RequestorName = _requestorName, + RequestorEmail = _requestorEmail, + RequestorIsdCode = "1", + RequestorMobileNumber = "0000000000", + SignerPlace = "Gateway Lab", + SignerIp = "127.0.0.1", + GroupNumber = _groupNumber, + PageSize = 100, + DcvEnabled = false + }; + + private static bool IsIssuedListing(ListObs o) => + o.CertStatus != null && + (o.CertStatus.IndexOf("Generated", StringComparison.OrdinalIgnoreCase) >= 0 + || o.CertStatus.IndexOf("Downloaded", StringComparison.OrdinalIgnoreCase) >= 0); + + private static bool IsIssuedTrack(string status) => + string.Equals(status, Constants.ApiV2.StatusIssued, StringComparison.OrdinalIgnoreCase); + + // --------------------------------------------------------------------------- + // The experiment + // --------------------------------------------------------------------------- + + [SkippableFact] + public async Task V2PlaceOrder_Latency_And_ExposureWindow_Experiment() + { + Skip.If(!_v2Enabled, "V2 credentials not configured in ~/.env_certinext_v2 (CERTINEXT_USE_V2_API, API_URL, CLIENT_ID, CLIENT_SECRET)."); + Skip.If(Environment.GetEnvironmentVariable(OptInFlag) != "1", + $"Opt-in: set {OptInFlag}=1 as a real environment variable (places live sandbox orders)."); + Skip.If(string.IsNullOrWhiteSpace(_baseDomain), "CERTINEXT_DCV_DOMAIN is required (base domain for test CNs)."); + + int count = int.TryParse(Environment.GetEnvironmentVariable("CERTINEXT_V2_LATENCY_COUNT"), out int c) ? c : 7; + count = Math.Max(1, Math.Min(MaxOrders, count)); + double spacing = double.TryParse(Environment.GetEnvironmentVariable("CERTINEXT_V2_LATENCY_SPACING_SECONDS"), + NumberStyles.Float, CultureInfo.InvariantCulture, out double sp) ? sp : 30; + bool reuse = string.Equals(Environment.GetEnvironmentVariable("CERTINEXT_V2_LATENCY_DOMAIN_MODE"), + "reuse", StringComparison.OrdinalIgnoreCase); + + string runId = DateTime.UtcNow.ToString("MMddHHmm", CultureInfo.InvariantCulture); + var cfg = BuildConfig(); + + // Independent clients: listing poller (stands in for the sync pod) and order tracker. + using var listClient = new CERTInextClient(cfg); + using var trackClient = new CERTInextClient(cfg); + using var realClient = new CERTInextClient(cfg); + using var cleanupClient = new CERTInextClient(cfg); + var cleanupPlugin = new CERTInextCAPlugin(cleanupClient, cfg); + + W($"V2 latency experiment run {runId}: product={_productCode}, mode={(reuse ? "reuse" : "unique")}, " + + $"count={count}, spacingS={F(spacing)}, pickupRetries={cfg.GetEffectivePickupRetries()}"); + + var trials = new List(); + double lastT0 = double.NegativeInfinity; + try + { + for (int i = 0; i < count; i++) + { + var t = new Trial + { + Index = i + 1, + Domain = reuse ? _baseDomain : $"v2lat-{runId}-{i + 1:D2}.{_baseDomain}".ToLowerInvariant() + }; + trials.Add(t); + + double wait = lastT0 + spacing - Now; + if (wait > 0) await Task.Delay(TimeSpan.FromSeconds(wait)); + + try + { + await RunTrialAsync(t, cfg, realClient, listClient, trackClient, reuse); + lastT0 = t.T0; + } + catch (Exception ex) + { + t.Error = (t.Error.Length > 0 ? t.Error + "; " : "") + "trial: " + Describe(ex); + lastT0 = t.T0 > 0 ? t.T0 : Now; + } + finally + { + t.CleanupNote = await CleanupAsync(cleanupPlugin, t.OrderId); + } + LogTrial(t); + } + } + finally + { + WriteCsv(runId, trials); + WriteSummary(trials); + } + } + + private async Task RunTrialAsync(Trial t, CERTInextConfig cfg, CERTInextClient realClient, + CERTInextClient listClient, CERTInextClient trackClient, bool reuse) + { + // Everything not under test happens before t0. + string csr = GenerateCsrPem(t.Domain); + string today = DateTime.UtcNow.ToString("yyyy-MM-dd", CultureInfo.InvariantCulture); + string tomorrow = DateTime.UtcNow.AddDays(1).ToString("yyyy-MM-dd", CultureInfo.InvariantCulture); + + // reuse mode: orders already on the base domain today are excluded from "mine". + var snapshot = new HashSet(StringComparer.Ordinal); + if (reuse) + { + await foreach (var e in listClient.ListOrdersV2Async(today, tomorrow, 100)) + if (string.Equals(e.DomainName, t.Domain, StringComparison.OrdinalIgnoreCase) && e.OrderNumber != null) + snapshot.Add(e.OrderNumber); + } + bool Mine(OrderReportEntryV2 e) => + string.Equals(e.DomainName, t.Domain, StringComparison.OrdinalIgnoreCase) + && e.OrderNumber != null && !snapshot.Contains(e.OrderNumber); + + var proxy = DispatchProxy.Create(); + var tp = (TimingClientProxy)(object)proxy; + tp.Inner = realClient; + tp.Clock = () => Now; + + var trackObs = new ConcurrentQueue(); + var listObs = new ConcurrentQueue(); + using var stopAll = new CancellationTokenSource(); + Task trackerTask = Task.CompletedTask; + string orderIdFromCreate = null; + + // The instant the place response lands, start tracking the order with the independent client. + tp.OnResult = (name, result) => + { + if (name == "PlaceOrderV2Async" && result is V2CreateOrderResponse cr && orderIdFromCreate == null) + { + orderIdFromCreate = cr.OrderId; + t.CreateRespStatus = cr.Status ?? string.Empty; + trackerTask = Task.Run(async () => + { + while (!stopAll.IsCancellationRequested) + { + var o = new TrackObs { Sent = Now }; + try + { + var s = await trackClient.TrackOrderV2Async(Constants.ApiV2.FamilySsl, cr.OrderId); + o.Status = s.Status; + } + catch (Exception ex) { o.Error = Describe(ex); } + o.Recv = Now; + trackObs.Enqueue(o); + if (o.Error == null && IsIssuedTrack(o.Status) && double.IsNaN(t.DlProbeAt)) + { + t.DlProbeAt = Now; + double p0 = Now; + try + { + var dl = await trackClient.DownloadCertificateV2Async(Constants.ApiV2.FamilySsl, cr.OrderId); + t.DlProbeResult = string.IsNullOrWhiteSpace(dl?.CertificatePem) ? "ok-empty" : "ok-with-certificate"; + } + catch (Exception ex) { t.DlProbeResult = "error: " + Describe(ex); } + t.DlProbeMs = (Now - p0) * 1000.0; + } + try { await Task.Delay(TrackPollInterval, stopAll.Token); } catch (OperationCanceledException) { } + } + }); + } + }; + + var inflight = new List(); + var listerTask = Task.Run(async () => + { + async Task PollOnce() + { + var o = new ListObs { Start = Now }; + try + { + await foreach (var e in listClient.ListOrdersV2Async(today, tomorrow, 100)) + { + o.Rows++; + if (Mine(e) && o.OrderNumber == null) + { + o.OrderNumber = e.OrderNumber; + o.OrderStatus = e.OrderStatus; + o.CertStatus = e.CertificateStatus; + } + } + } + catch (Exception ex) { o.Error = Describe(ex); } + o.End = Now; + listObs.Enqueue(o); + } + while (!stopAll.IsCancellationRequested) + { + inflight.RemoveAll(x => x.IsCompleted); + if (inflight.Count < MaxListPollsInFlight) inflight.Add(Task.Run(PollOnce)); + try { await Task.Delay(ListPollInterval, stopAll.Token); } catch (OperationCanceledException) { } + } + await Task.WhenAll(inflight); + }); + await Task.Delay(ListPollInterval); // listing poller is already running before t0 + + var plugin = new CERTInextCAPlugin(proxy, cfg); + var productInfo = new EnrollmentProductInfo + { + ProductID = _productCode, + ProductParameters = new Dictionary + { + [Constants.EnrollmentParam.ProductCode] = _productCode, + [Constants.EnrollmentParam.ProfileId] = _productCode, + } + }; + + t.T0Utc = DateTime.UtcNow; + t.T0 = Now; + EnrollmentResult result = null; + try + { + result = await plugin.Enroll( + csr: csr, + subject: $"CN={t.Domain}", + san: new Dictionary { ["dns"] = new[] { t.Domain } }, + productInfo: productInfo, + requestFormat: RequestFormat.PKCS10, + enrollmentType: EnrollmentType.New); + } + catch (Exception ex) + { + t.Error = "Enroll: " + Describe(ex); + } + t.TEnrollEnd = Now; + t.OrderId = result?.CARequestID ?? orderIdFromCreate; + if (result != null) + { + t.EnrollStatus = ((EndEntityStatus)result.Status).ToString(); + t.EnrollHasCert = !string.IsNullOrWhiteSpace(result.Certificate); + t.EnrollMessage = Scrub(result.StatusMessage ?? string.Empty); + } + + // Keep observing: until issued is seen by tracker, or 90 s after the enroll returned. + double deadline = t.TEnrollEnd + 90; + while (Now < deadline) + { + await Task.Delay(500); + bool issuedSeen = trackObs.Any(o => IsIssuedTrack(o.Status)); + if (issuedSeen && Now >= t.TEnrollEnd + 4) break; + if (orderIdFromCreate == null && Now >= t.TEnrollEnd + 6) break; // nothing was placed + } + stopAll.Cancel(); + try { await Task.WhenAll(trackerTask, listerTask); } catch { /* observation only */ } + + Analyze(t, tp, trackObs.OrderBy(o => o.Recv).ToList(), listObs.OrderBy(o => o.Start).ToList()); + } + + private void Analyze(Trial t, TimingClientProxy tp, List track, List lists) + { + var calls = tp.Calls.OrderBy(c => c.Start).ToList(); + var place = calls.FirstOrDefault(c => c.Name == "PlaceOrderV2Async"); + var csr = calls.FirstOrDefault(c => c.Name == "SubmitCsrV2Async"); + var dl = calls.FirstOrDefault(c => c.Name == "DownloadCertificateV2Async"); + if (place != null) { t.PlaceMs = place.DurationMs; t.TPlaceResp = place.End; if (place.Error != null) t.Error += "place: " + place.Error + "; "; } + if (csr != null) { t.CsrMs = csr.DurationMs; t.TCsrResp = csr.End; if (csr.Error != null) t.Error += "csr: " + csr.Error + "; "; } + if (dl != null) t.DownloadMs = dl.DurationMs; + t.TrackCallMs = calls.Where(c => c.Name == "TrackOrderV2Async").Select(c => c.DurationMs).ToList(); + + // Listing: first poll whose rows contained the order. + t.ListPolls = lists.Count; + t.ListErrors = lists.Count(l => l.Error != null); + t.ListPollMedianS = Median(lists.Select(l => l.End - l.Start)); + var firstSeen = lists.Where(l => l.Matched).OrderBy(l => l.End).FirstOrDefault(); + if (firstSeen != null) + { + t.FirstSeenList = firstSeen.End; + t.FirstSeenListLower = firstSeen.Start; + t.FirstSeenListStatus = Scrub(firstSeen.Combined); + } + var issuedList = lists.Where(l => l.Matched && IsIssuedListing(l)).OrderBy(l => l.End).FirstOrDefault(); + if (issuedList != null) t.TIssuedList = issuedList.End; + + var lseq = new List(); + foreach (var l in lists.Where(l => l.Matched).OrderBy(l => l.End)) + { + string s = Scrub(l.Combined); + if (lseq.Count == 0 || !lseq[^1].StartsWith(s + "@", StringComparison.Ordinal)) + lseq.Add($"{s}@{F(l.End - t.T0)}"); + } + t.ListSeq = string.Join("; ", lseq); + + // Tracker. + t.TrackPolls = track.Count; + t.TrackErrors = track.Count(o => o.Error != null); + var okObs = track.Where(o => o.Error == null).ToList(); + if (okObs.Count > 0) + { + t.TrackFirstObsRecv = okObs[0].Recv; + t.TrackFirstObsStatus = okObs[0].Status; + } + if (!double.IsNaN(t.TCsrResp)) + { + var afterCsr = okObs.FirstOrDefault(o => o.Recv >= t.TCsrResp); + if (afterCsr != null) t.StatusAfterCsr = afterCsr.Status + "@" + F(afterCsr.Recv - t.T0); + } + var issuedTrack = okObs.FirstOrDefault(o => IsIssuedTrack(o.Status)); + if (issuedTrack != null) { t.TIssuedTrack = issuedTrack.Recv; t.TIssuedTrackLower = issuedTrack.Sent; } + + var tseq = new List(); + foreach (var o in okObs) + if (tseq.Count == 0 || !tseq[^1].StartsWith(o.Status + "@", StringComparison.Ordinal)) + tseq.Add($"{o.Status}@{F(o.Recv - t.T0)}"); + t.TrackSeq = string.Join("; ", tseq); + foreach (var o in track.Where(o => o.Error != null).Take(2)) + t.Error += "track: " + o.Error + "; "; + } + + private void LogTrial(Trial t) + { + W($"trial {t.Index:D2} order={(string.IsNullOrEmpty(t.OrderId) ? "-" : t.OrderId)} " + + $"place={F(t.PlaceMs / 1000)}s csr={F(t.CsrMs / 1000)}s tracks=[{string.Join(",", t.TrackCallMs.Select(x => F(x / 1000)))}]s " + + $"download={F(t.DownloadMs / 1000)}s enrollWall={F(t.TEnrollEnd - t.T0)}s enroll={t.EnrollStatus} cert={t.EnrollHasCert} " + + $"createStatus={t.CreateRespStatus} firstSeenInListing={F(t.FirstSeenList - t.T0)}s({t.FirstSeenListStatus}) " + + $"placeResp={F(t.TPlaceResp - t.T0)}s csrResp={F(t.TCsrResp - t.T0)}s " + + $"dlProbe@{F(t.DlProbeAt - t.T0)}s={t.DlProbeResult} issuedTrack={F(t.TIssuedTrack - t.T0)}s issuedList={F(t.TIssuedList - t.T0)}s " + + $"trackSeq=[{t.TrackSeq}] listSeq=[{t.ListSeq}] cleanup={t.CleanupNote} {t.Error}"); + } + + private void WriteCsv(string runId, List trials) + { + try + { + string dir = Path.Combine(RepoRoot(), "experiment-results"); + Directory.CreateDirectory(dir); + string path = Path.Combine(dir, $"v2-placeorder-latency-{runId}.csv"); + var sb = new StringBuilder(); + sb.AppendLine("trial,domain,order_id,t0_utc,create_resp_status,place_ms,csr_ms,track_calls_ms,download_ms," + + "enroll_wall_s,enroll_status,enroll_has_cert,t_place_resp_s,t_csr_resp_s,t_enroll_end_s," + + "first_seen_listing_s,first_seen_listing_lower_s,first_seen_listing_status," + + "seen_in_listing_before_place_resp,seen_in_listing_before_csr_resp,exposure_seen_to_enroll_end_s," + + "track_first_obs_s,track_first_obs_status,status_after_csr," + + "t_issued_track_s,t_issued_track_lower_s,t_issued_listing_s," + + "issued_before_place_resp,issued_before_csr_resp,issued_before_enroll_end," + + "dl_probe_at_s,dl_probe_ms,dl_probe_result,track_seq,listing_seq,list_polls,list_poll_median_s,track_polls,list_errors,track_errors,cleanup,error"); + foreach (var t in trials) + { + string Rel(double x) => double.IsNaN(x) ? "" : F(x - t.T0); + string Q(string s) => "\"" + Scrub(s ?? "").Replace("\"", "'") + "\""; + bool seenBeforePlace = !double.IsNaN(t.FirstSeenList) && !double.IsNaN(t.TPlaceResp) && t.FirstSeenList < t.TPlaceResp; + bool seenBeforeCsr = !double.IsNaN(t.FirstSeenList) && !double.IsNaN(t.TCsrResp) && t.FirstSeenList < t.TCsrResp; + // Issued strictly before a response returned: use the observation's RECEIVE time vs that response's time. + bool issuedBeforePlace = !double.IsNaN(t.TIssuedList) && !double.IsNaN(t.TPlaceResp) && t.TIssuedList < t.TPlaceResp; + double issuedAny = double.IsNaN(t.TIssuedTrack) ? t.TIssuedList + : double.IsNaN(t.TIssuedList) ? t.TIssuedTrack : Math.Min(t.TIssuedTrack, t.TIssuedList); + bool issuedBeforeCsr = !double.IsNaN(issuedAny) && !double.IsNaN(t.TCsrResp) && issuedAny < t.TCsrResp; + bool issuedBeforeEnd = !double.IsNaN(issuedAny) && !double.IsNaN(t.TEnrollEnd) && issuedAny < t.TEnrollEnd; + double exposure = (!double.IsNaN(t.FirstSeenList) && !double.IsNaN(t.TEnrollEnd)) ? t.TEnrollEnd - t.FirstSeenList : double.NaN; + sb.AppendLine(string.Join(",", new[] + { + t.Index.ToString(CultureInfo.InvariantCulture), t.Domain, t.OrderId ?? "", t.T0Utc.ToString("o", CultureInfo.InvariantCulture), + t.CreateRespStatus, F(t.PlaceMs), F(t.CsrMs), Q(string.Join(";", t.TrackCallMs.Select(F))), F(t.DownloadMs), + F(t.TEnrollEnd - t.T0), t.EnrollStatus, t.EnrollHasCert ? "1" : "0", Rel(t.TPlaceResp), Rel(t.TCsrResp), Rel(t.TEnrollEnd), + Rel(t.FirstSeenList), Rel(t.FirstSeenListLower), Q(t.FirstSeenListStatus), + seenBeforePlace ? "1" : "0", seenBeforeCsr ? "1" : "0", F(exposure), + Rel(t.TrackFirstObsRecv), Q(t.TrackFirstObsStatus), Q(t.StatusAfterCsr), + Rel(t.TIssuedTrack), Rel(t.TIssuedTrackLower), Rel(t.TIssuedList), + issuedBeforePlace ? "1" : "0", issuedBeforeCsr ? "1" : "0", issuedBeforeEnd ? "1" : "0", + Rel(t.DlProbeAt), F(t.DlProbeMs), Q(t.DlProbeResult), + Q(t.TrackSeq), Q(t.ListSeq), t.ListPolls.ToString(CultureInfo.InvariantCulture), F(t.ListPollMedianS), + t.TrackPolls.ToString(CultureInfo.InvariantCulture), t.ListErrors.ToString(CultureInfo.InvariantCulture), + t.TrackErrors.ToString(CultureInfo.InvariantCulture), Q(t.CleanupNote), Q(t.Error) + })); + } + File.WriteAllText(path, sb.ToString()); + W($"CSV written: experiment-results/{Path.GetFileName(path)}"); + } + catch (Exception ex) + { + W($"CSV write failed: {Describe(ex)}"); + } + } + + private void WriteSummary(List trials) + { + var ok = trials.Where(t => !string.IsNullOrEmpty(t.OrderId)).ToList(); + W($"=== summary (seconds; min / median / max; n) over {ok.Count} placed orders ==="); + void Row(string name, Func get) + { + var xs = ok.Select(get).Where(x => !double.IsNaN(x)).ToArray(); + W(xs.Length == 0 ? $"{name,-22} n=0" + : $"{name,-22} {F(xs.Min())} / {F(Median(xs))} / {F(xs.Max())} (n={xs.Length})"); + } + Row("place (HTTP)", t => t.PlaceMs / 1000); + Row("csr submit (HTTP)", t => t.CsrMs / 1000); + Row("download (HTTP)", t => t.DownloadMs / 1000); + Row("enroll wall", t => t.TEnrollEnd - t.T0); + Row("first seen in listing", t => t.FirstSeenList - t.T0); + Row("issued (track)", t => t.TIssuedTrack - t.T0); + Row("issued (listing)", t => t.TIssuedList - t.T0); + Row("seen->enroll end", t => t.TEnrollEnd - t.FirstSeenList); + } + + /// Revoke if issued, otherwise cancel via the raw endpoint (single attempt). Never throws. + private async Task CleanupAsync(CERTInextCAPlugin plugin, string orderId) + { + if (string.IsNullOrWhiteSpace(orderId)) return "no order"; + try + { + var current = await plugin.GetSingleRecord(orderId); + if (current?.Status == (int)EndEntityStatus.GENERATED) + { + int r = await plugin.Revoke(orderId, hexSerialNumber: string.Empty, revocationReason: 4); + return $"revoked ({r})"; + } + await V2RawHttpHelpers.CancelSslOrderRawAsync(_apiUrl, _clientId, _clientSecret, orderId, + "V2 latency experiment cleanup — order not issued, cancelling."); + return $"cancelled (status was {current?.Status})"; + } + catch (Exception ex) + { + return "cleanup FAILED: " + Describe(ex); + } + } + } +} From 1e1cea62e84da5590ca7555db5e071b82206aed7 Mon Sep 17 00:00:00 2001 From: spbsoluble <1661003+spbsoluble@users.noreply.github.com> Date: Wed, 14 Oct 2026 09:09:05 -0700 Subject: [PATCH 2/3] docs(v2): 0090 V2 place-order latency results (13 sandbox orders) --- .../v2-placeorder-latency-10141548.csv | 2 + .../v2-placeorder-latency-10141551.csv | 2 + .../v2-placeorder-latency-10141552.csv | 5 ++ .../v2-placeorder-latency-10141556.csv | 5 ++ .../v2-placeorder-latency-10141601.csv | 4 ++ .../v2-placeorder-latency-summary.md | 49 +++++++++++++++++++ 6 files changed, 67 insertions(+) create mode 100644 experiment-results/v2-placeorder-latency-10141548.csv create mode 100644 experiment-results/v2-placeorder-latency-10141551.csv create mode 100644 experiment-results/v2-placeorder-latency-10141552.csv create mode 100644 experiment-results/v2-placeorder-latency-10141556.csv create mode 100644 experiment-results/v2-placeorder-latency-10141601.csv create mode 100644 experiment-results/v2-placeorder-latency-summary.md diff --git a/experiment-results/v2-placeorder-latency-10141548.csv b/experiment-results/v2-placeorder-latency-10141548.csv new file mode 100644 index 0000000..f886d7b --- /dev/null +++ b/experiment-results/v2-placeorder-latency-10141548.csv @@ -0,0 +1,2 @@ +trial,domain,order_id,t0_utc,create_resp_status,place_ms,csr_ms,track_calls_ms,download_ms,enroll_wall_s,enroll_status,enroll_has_cert,t_place_resp_s,t_csr_resp_s,t_enroll_end_s,first_seen_listing_s,first_seen_listing_lower_s,first_seen_listing_status,seen_in_listing_before_place_resp,seen_in_listing_before_csr_resp,exposure_seen_to_enroll_end_s,track_first_obs_s,track_first_obs_status,status_after_csr,t_issued_track_s,t_issued_track_lower_s,t_issued_listing_s,issued_before_place_resp,issued_before_csr_resp,issued_before_enroll_end,track_seq,listing_seq,list_polls,list_poll_median_s,track_polls,list_errors,track_errors,cleanup,error +1,v2lat-10141548-01.dcv-test.scrup.org,3544182867,2026-10-14T15:48:36.3313250Z,pending-approval,4387.38,3244.75,"120.71;121.24;119.17;118.29;137.02;112.14",,64.72,EXTERNALVALIDATION,0,5.73,8.98,64.72,4.62,4.50,"Order Accepted|Pending for Approver",1,1,60.10,6.67,"pending-approval","pending-approval@10.04",,,,0,0,0,"pending-approval@6.67","Order Accepted|Pending for Approver@4.62",105,0.12,132,0,0,"cancelled (status was 90)","" diff --git a/experiment-results/v2-placeorder-latency-10141551.csv b/experiment-results/v2-placeorder-latency-10141551.csv new file mode 100644 index 0000000..7712774 --- /dev/null +++ b/experiment-results/v2-placeorder-latency-10141551.csv @@ -0,0 +1,2 @@ +trial,domain,order_id,t0_utc,create_resp_status,place_ms,csr_ms,track_calls_ms,download_ms,enroll_wall_s,enroll_status,enroll_has_cert,t_place_resp_s,t_csr_resp_s,t_enroll_end_s,first_seen_listing_s,first_seen_listing_lower_s,first_seen_listing_status,seen_in_listing_before_place_resp,seen_in_listing_before_csr_resp,exposure_seen_to_enroll_end_s,track_first_obs_s,track_first_obs_status,status_after_csr,t_issued_track_s,t_issued_track_lower_s,t_issued_listing_s,issued_before_place_resp,issued_before_csr_resp,issued_before_enroll_end,track_seq,listing_seq,list_polls,list_poll_median_s,track_polls,list_errors,track_errors,cleanup,error +1,dcv-test.scrup.org,1226469856,2026-10-14T15:51:31.5398990Z,pending-approval,4680.93,2878.95,"125.41;121.05;120.10;130.79",2719.68,39.90,GENERATED,1,6.02,8.90,39.90,4.64,4.50,"Order Accepted|Pending for Approver",1,1,35.26,6.97,"pending-approval","pending-approval@9.22",17.27,17.14,36.15,0,0,1,"pending-approval@6.97; issued@17.27","Order Accepted|Pending for Approver@4.64; Order Accepted|Approved by System@16.63; Order Accepted|Certificate Generated@36.15; Order Fulfilled|Certificate Downloaded@40.64",31,0.12,33,0,0,"revoked (50)","" diff --git a/experiment-results/v2-placeorder-latency-10141552.csv b/experiment-results/v2-placeorder-latency-10141552.csv new file mode 100644 index 0000000..c8a9022 --- /dev/null +++ b/experiment-results/v2-placeorder-latency-10141552.csv @@ -0,0 +1,5 @@ +trial,domain,order_id,t0_utc,create_resp_status,place_ms,csr_ms,track_calls_ms,download_ms,enroll_wall_s,enroll_status,enroll_has_cert,t_place_resp_s,t_csr_resp_s,t_enroll_end_s,first_seen_listing_s,first_seen_listing_lower_s,first_seen_listing_status,seen_in_listing_before_place_resp,seen_in_listing_before_csr_resp,exposure_seen_to_enroll_end_s,track_first_obs_s,track_first_obs_status,status_after_csr,t_issued_track_s,t_issued_track_lower_s,t_issued_listing_s,issued_before_place_resp,issued_before_csr_resp,issued_before_enroll_end,track_seq,listing_seq,list_polls,list_poll_median_s,track_polls,list_errors,track_errors,cleanup,error +1,dcv-test.scrup.org,1918886693,2026-10-14T15:52:58.5753240Z,issued,4103.53,20227.87,"113.49",2777.85,28.52,GENERATED,1,5.39,25.61,28.52,6.13,6.01,"Order Accepted|Approved by System",0,1,22.39,6.33,"issued","issued@26.73",6.33,5.39,25.63,0,1,1,"issued@6.33","Order Accepted|Approved by System@6.13; Order Accepted|Certificate Generated@25.63; Order Fulfilled|Certificate Downloaded@28.64",23,0.12,24,0,0,"revoked (50)","" +2,dcv-test.scrup.org,7313697899,2026-10-14T15:53:55.5921110Z,pending-approval,3527.19,18789.17,"117.85",2736.23,25.58,GENERATED,1,3.93,22.72,25.58,4.64,4.50,"Order Accepted|Approved by System",0,1,20.94,4.07,"pending-approval","issued@23.17",5.18,5.07,24.14,0,1,1,"pending-approval@4.07; issued@5.18","Order Accepted|Approved by System@4.64; Order Accepted|Certificate Generated@24.14; Order Fulfilled|Certificate Downloaded@25.63",21,0.13,23,0,0,"revoked (50)","" +3,dcv-test.scrup.org,3428572213,2026-10-14T15:54:48.6744050Z,issued,4340.89,20293.81,"119.36",2772.59,28.10,GENERATED,1,4.91,25.20,28.10,4.63,4.50,"Order Accepted|Pending for Approver",1,1,23.47,5.04,"issued","issued@25.32",5.04,4.91,25.64,0,1,1,"issued@5.04","Order Accepted|Pending for Approver@4.63; Order Accepted|Approved by System@6.13; Order Accepted|Certificate Generated@25.64; Order Fulfilled|Certificate Downloaded@28.64",23,0.13,25,0,0,"revoked (50)","" +4,dcv-test.scrup.org,7915224579,2026-10-14T15:55:42.5126450Z,issued,3776.63,21483.81,"125.22",2740.45,28.52,GENERATED,1,4.17,25.66,28.52,4.63,4.50,"Order Accepted|Approved by System",0,1,23.89,4.37,"issued","issued@25.81",4.37,4.17,25.64,0,1,1,"issued@4.37","Order Accepted|Approved by System@4.63; Order Accepted|Certificate Generated@25.64; Order Fulfilled|Certificate Downloaded@28.64",23,0.13,26,0,0,"revoked (50)","" diff --git a/experiment-results/v2-placeorder-latency-10141556.csv b/experiment-results/v2-placeorder-latency-10141556.csv new file mode 100644 index 0000000..e6447e1 --- /dev/null +++ b/experiment-results/v2-placeorder-latency-10141556.csv @@ -0,0 +1,5 @@ +trial,domain,order_id,t0_utc,create_resp_status,place_ms,csr_ms,track_calls_ms,download_ms,enroll_wall_s,enroll_status,enroll_has_cert,t_place_resp_s,t_csr_resp_s,t_enroll_end_s,first_seen_listing_s,first_seen_listing_lower_s,first_seen_listing_status,seen_in_listing_before_place_resp,seen_in_listing_before_csr_resp,exposure_seen_to_enroll_end_s,track_first_obs_s,track_first_obs_status,status_after_csr,t_issued_track_s,t_issued_track_lower_s,t_issued_listing_s,issued_before_place_resp,issued_before_csr_resp,issued_before_enroll_end,track_seq,listing_seq,list_polls,list_poll_median_s,track_polls,list_errors,track_errors,cleanup,error +1,dcv-test.scrup.org,8731931793,2026-10-14T15:56:53.6759880Z,issued,3730.35,18629.94,"116.12",2719.01,26.44,GENERATED,1,4.96,23.59,26.44,4.65,4.50,"Order Accepted|Pending for Approver",1,1,21.79,5.92,"issued","issued@24.13",5.92,4.96,24.13,0,1,1,"issued@5.92","Order Accepted|Pending for Approver@4.65; Order Accepted|Approved by System@6.13; Order Accepted|Certificate Generated@24.13; Order Fulfilled|Certificate Downloaded@27.14",22,0.13,22,0,0,"revoked (50)","" +2,dcv-test.scrup.org,8487123326,2026-10-14T15:57:46.0516710Z,issued,3789.28,18738.54,"131.37",2940.75,26.04,GENERATED,1,4.23,22.97,26.04,4.64,4.50,"Order Accepted|Approved by System",0,1,21.40,4.35,"issued","issued@23.51",4.35,4.23,24.16,0,1,1,"issued@4.35","Order Accepted|Approved by System@4.64; Order Accepted|Certificate Generated@24.16; Order Fulfilled|Certificate Downloaded@27.14",22,0.13,23,0,0,"revoked (50)","" +3,dcv-test.scrup.org,7447643132,2026-10-14T15:58:37.0139520Z,issued,3789.65,17374.89,"116.52",2850.52,24.60,GENERATED,1,4.26,21.64,24.60,4.63,4.50,"Order Accepted|Approved by System",0,1,19.97,4.39,"issued","issued@22.45",4.39,4.26,22.65,0,1,1,"issued@4.39","Order Accepted|Approved by System@4.63; Order Accepted|Certificate Generated@22.65; Order Fulfilled|Certificate Downloaded@25.63",21,0.13,22,0,0,"revoked (50)","" +4,dcv-test.scrup.org,8595485484,2026-10-14T15:59:25.4610260Z,issued,4030.05,20343.68,"118.29",3001.09,27.90,GENERATED,1,4.44,24.78,27.90,4.63,4.50,"Order Accepted|Approved by System",0,1,23.27,4.57,"issued","issued@24.83",4.57,4.44,25.64,0,1,1,"issued@4.57","Order Accepted|Approved by System@4.63; Order Accepted|Certificate Generated@25.64; Order Fulfilled|Certificate Downloaded@28.80",23,0.13,25,0,0,"revoked (50)","" diff --git a/experiment-results/v2-placeorder-latency-10141601.csv b/experiment-results/v2-placeorder-latency-10141601.csv new file mode 100644 index 0000000..e95ecc1 --- /dev/null +++ b/experiment-results/v2-placeorder-latency-10141601.csv @@ -0,0 +1,4 @@ +trial,domain,order_id,t0_utc,create_resp_status,place_ms,csr_ms,track_calls_ms,download_ms,enroll_wall_s,enroll_status,enroll_has_cert,t_place_resp_s,t_csr_resp_s,t_enroll_end_s,first_seen_listing_s,first_seen_listing_lower_s,first_seen_listing_status,seen_in_listing_before_place_resp,seen_in_listing_before_csr_resp,exposure_seen_to_enroll_end_s,track_first_obs_s,track_first_obs_status,status_after_csr,t_issued_track_s,t_issued_track_lower_s,t_issued_listing_s,issued_before_place_resp,issued_before_csr_resp,issued_before_enroll_end,dl_probe_at_s,dl_probe_ms,dl_probe_result,track_seq,listing_seq,list_polls,list_poll_median_s,track_polls,list_errors,track_errors,cleanup,error +1,dcv-test.scrup.org,2299934381,2026-10-14T16:01:25.5594380Z,issued,4017.95,20289.41,"114.72",2998.62,28.65,GENERATED,1,5.23,25.52,28.65,4.67,4.50,"Order Accepted|Pending for Approver",1,1,23.98,6.27,"issued","issued@25.81",6.27,5.23,25.65,0,1,1,6.27,3567.11,"error: Exception: CERTInext V2 API error during 'V2 download certificate'. HTTP 422. Unprocessable Entity: EMS-1165 Invalid request status.","issued@6.27","Order Accepted|Pending for Approver@4.67; Order Accepted|Approved by System@6.14; Order Accepted|Certificate Generated@25.65; Order Fulfilled|Certificate Downloaded@28.65",23,0.14,21,0,0,"revoked (50)","" +2,dcv-test.scrup.org,1732815671,2026-10-14T16:02:44.5566100Z,issued,3760.70,19069.55,"118.24",2766.61,26.23,GENERATED,1,4.28,23.35,26.23,4.65,4.50,"Order Accepted|Approved by System",0,1,21.58,4.40,"issued","issued@23.95",4.40,4.28,24.15,0,1,1,4.40,3807.95,"error: Exception: CERTInext V2 API error during 'V2 download certificate'. HTTP 422. Unprocessable Entity: EMS-1165 Invalid request status.","issued@4.40","Order Accepted|Approved by System@4.65; Order Accepted|Certificate Generated@24.15; Order Fulfilled|Certificate Downloaded@27.15",22,0.14,20,0,0,"revoked (50)","" +3,dcv-test.scrup.org,7966694779,2026-10-14T16:03:48.0246110Z,issued,3890.93,23110.25,"119.99",2794.07,30.35,GENERATED,1,4.32,27.43,30.35,5.16,4.50,"Order Accepted|Approved by System",0,1,25.19,4.51,"issued","issued@28.34",4.51,4.32,28.64,0,1,1,4.51,3557.85,"error: Exception: CERTInext V2 API error during 'V2 download certificate'. HTTP 422. Unprocessable Entity: EMS-1165 Invalid request status.","issued@4.51","Order Accepted|Approved by System@5.16; Order Accepted|Certificate Generated@28.64; Order Fulfilled|Certificate Downloaded@31.65",24,0.14,24,0,0,"revoked (50)","" diff --git a/experiment-results/v2-placeorder-latency-summary.md b/experiment-results/v2-placeorder-latency-summary.md new file mode 100644 index 0000000..ae5b66a --- /dev/null +++ b/experiment-results/v2-placeorder-latency-summary.md @@ -0,0 +1,49 @@ +# V2 place-order latency vs. issue 0090 (2026-10-14, CERTInext sandbox) + +Test: `CERTInext.IntegrationTests/V2PlaceOrderLatencyExperimentTests.cs` (opt-in `CERTINEXT_V2_LATENCY_EXPERIMENT=1`). +The plugin's real `Enroll` (V2, DV SSL 842, DCV off, default pickup 5 x 10 s) runs through a timing proxy over +`ICERTInextClient`. Beside it, an independent client lists `/reports/orders` every 1.5 s (what Synchronize calls) and +another tracks the order every 1 s from the moment the create response lands. Times are seconds after Enroll start (t0). +Raw data: `v2-placeorder-latency-*.csv` (13 orders: 12 on the verified base domain, 1 on a fresh unverified subdomain). +All 13 orders were revoked or cancelled by the test. + +## V2 order placement is three calls, and the hold moved to the second one +1. `POST create` returns the orderId after 3.5-4.7 s (median 3.9 s). It does NOT hold for ~19 s. +2. `PUT /csr` blocks 17.4-23.1 s (median 20.2 s) in 11 of 12 base-domain orders (the 12th, the first base-domain order of the day, took 2.9 s and issued ~17 s after t0 instead). The certificate is generated inside this call. +3. `GET track` + `GET certificate` + pickup: ~0.12 s + ~2.8 s. Total `Enroll` wall time: 24.6-30.4 s (median 27.9 s) for + the 11 held orders; 39.9 s for the anomalous one. + +## Per-order table (base domain `reuse` orders; seconds after t0 unless noted) +| order | create-resp status | place HTTP | csr HTTP | track 'issued' first seen | listing 'Certificate Generated' | csr resp | Enroll wall | listing-first-seen -> Enroll end | +|---|---|---|---|---|---|---|---|---| +| 1226469856 | pending-approval | 4.7 | 2.9 | 17.3 | 36.2 | 8.9 | 39.9 | 35.3 | +| 1918886693 | issued | 4.1 | 20.2 | 6.3 | 25.6 | 25.6 | 28.5 | 22.4 | +| 7313697899 | pending-approval | 3.5 | 18.8 | 5.2 | 24.1 | 22.7 | 25.6 | 20.9 | +| 3428572213 | issued | 4.3 | 20.3 | 5.0 | 25.6 | 25.2 | 28.1 | 23.5 | +| 7915224579 | issued | 3.8 | 21.5 | 4.4 | 25.6 | 25.7 | 28.5 | 23.9 | +| 8731931793 | issued | 3.7 | 18.6 | 5.9 | 24.1 | 23.6 | 26.4 | 21.8 | +| 8487123326 | issued | 3.8 | 18.7 | 4.4 | 24.2 | 23.0 | 26.0 | 21.4 | +| 7447643132 | issued | 3.8 | 17.4 | 4.4 | 22.7 | 21.6 | 24.6 | 20.0 | +| 8595485484 | issued | 4.0 | 20.3 | 4.6 | 25.6 | 24.8 | 27.9 | 23.3 | +| 2299934381 | issued | 4.0 | 20.3 | 6.3 | 25.7 | 25.5 | 28.7 | 24.0 | +| 1732815671 | issued | 3.8 | 19.1 | 4.4 | 24.2 | 23.4 | 26.2 | 21.6 | +| 7966694779 | issued | 3.9 | 23.1 | 4.5 | 28.6 | 27.4 | 30.4 | 25.2 | + +Unverified fresh subdomain (3544182867): create `pending-approval`, place 4.4 s, csr 3.2 s, still `pending-approval` +>150 s later (no DCV in this run); Enroll returned EXTERNALVALIDATION after 64.7 s. + +## Key datum +- In 11 of 12 base-domain orders the order is already `issued` (per the V2 track endpoint) **before the CSR PUT returns**, + by ~17-21 s; in 10 of 12 the create response itself already says `issued`. This is the production V1 pattern (order + already issued while the response is held), moved to `PUT /csr`. +- The sync-visible window (first sighting in `/reports/orders`, within ~1.5 s of the create response (before it in 5 of 13 orders), to Enroll return, when + the gateway learns the CARequestID) is 20.0-25.2 s (median 22.4 s) for held orders; 35.3 s for the anomalous one. + The listing shows `Order Accepted | Pending for Approver` or `Approved by System` for the whole window and flips to + `Certificate Generated` only about when the CSR PUT returns. + +## Caveats +- V1 sandbox did NOT reproduce production's hold, so these are suggestive, not proof, for production V2. The V2 sandbox + does reproduce the shape (issued before response, ~20 s hold), which V1 sandbox did not. +- One account, one ~25 minute window, 13 orders; first-sighting resolution is the 1.5 s poll interval. +- Phase 1 orders share the sandbox account with the kfclab gateway, whose own sync imported at least one of them + (gateway row 1826, order 8595485484). From e2351e576e6a58394adfabf79942d156d86df7ae Mon Sep 17 00:00:00 2001 From: spbsoluble <1661003+spbsoluble@users.noreply.github.com> Date: Wed, 14 Oct 2026 11:35:35 -0700 Subject: [PATCH 3/3] test(v2): opt-in explicit-ID sandbox order cleanup (issue 0090) Track, then revoke (issued) or cancel (pending) only the order ids listed in CERTINEXT_V2_CLEANUP_ORDERS, then re-track to verify. Optional CERTINEXT_V2_CLEANUP_DRYRUN=1 reports details without acting; CERTINEXT_V2_CLEANUP_FORCE_CANCEL=1 (single id) makes one raw cancel attempt and re-reads the order report. --- .../IntegrationTestFixture.cs | 2 + .../V2OrderCleanupTests.cs | 319 ++++++++++++++++++ 2 files changed, 321 insertions(+) create mode 100644 CERTInext.IntegrationTests/V2OrderCleanupTests.cs diff --git a/CERTInext.IntegrationTests/IntegrationTestFixture.cs b/CERTInext.IntegrationTests/IntegrationTestFixture.cs index fda7fa6..4994aed 100644 --- a/CERTInext.IntegrationTests/IntegrationTestFixture.cs +++ b/CERTInext.IntegrationTests/IntegrationTestFixture.cs @@ -54,6 +54,8 @@ public sealed class IntegrationTestFixture : IDisposable "CERTINEXT_V2_LIFECYCLE_FRESH_DCV", // Issue 0090 V2 place-order latency experiment (places real sandbox orders). "CERTINEXT_V2_LATENCY_EXPERIMENT", + // Explicit-ID V2 sandbox order cleanup (revokes/cancels the listed orders). + "CERTINEXT_V2_CLEANUP_ORDERS", }; // --------------------------------------------------------------------------- diff --git a/CERTInext.IntegrationTests/V2OrderCleanupTests.cs b/CERTInext.IntegrationTests/V2OrderCleanupTests.cs new file mode 100644 index 0000000..6385c6f --- /dev/null +++ b/CERTInext.IntegrationTests/V2OrderCleanupTests.cs @@ -0,0 +1,319 @@ +// Copyright 2026 Keyfactor +// +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. + +using System; +using System.Collections.Generic; +using System.Globalization; +using System.Linq; +using System.Text.RegularExpressions; +using System.Threading.Tasks; +using Keyfactor.Extensions.CAPlugin.CERTInext.API.V2; +using Keyfactor.Extensions.CAPlugin.CERTInext.Client; +using Xunit; +using Xunit.Abstractions; + +namespace Keyfactor.Extensions.CAPlugin.CERTInext.IntegrationTests +{ + /// + /// Explicit-ID cleanup of V2 SANDBOX orders (fake credits) left behind by experiments. + /// Opt-in: CERTINEXT_V2_CLEANUP_ORDERS=<comma-separated order ids> as a REAL + /// environment variable (it is never read from an env file). Credentials come from + /// ~/.env_certinext_v2. + /// + /// Only the listed ids are ever acted on. For each: TrackOrder (record status) -> revoke if + /// issued, cancel if pending, skip if already revoked / cancelled / rejected / expired -> + /// TrackOrder again (verify). A narrow read-only order-report window (yesterday..tomorrow) is + /// read once to report each listed order's creation date and domain; no full sync is run and + /// nothing is acted on by pattern. Set CERTINEXT_V2_CLEANUP_DRYRUN=1 to track and report + /// details only (no revoke/cancel). Set + /// CERTINEXT_V2_CLEANUP_FORCE_CANCEL=1 (single id only) to make one raw cancel attempt instead of a revoke. Emails are scrubbed from all output. + /// + public class V2OrderCleanupTests : IClassFixture + { + private const string OptInFlag = "CERTINEXT_V2_CLEANUP_ORDERS"; + private const int MaxOrders = 25; + private const string CleanupReason = "Sandbox test order cleanup (issue 0090 lab race repro)."; + + private readonly ITestOutputHelper _output; + private readonly string _apiUrl; + private readonly string _clientId; + private readonly string _clientSecret; + private readonly string _groupNumber; + private readonly bool _v2Enabled; + + private static readonly Regex EmailRx = + new(@"[A-Za-z0-9._%+\-]+@[A-Za-z0-9.\-]+\.[A-Za-z]{2,}", RegexOptions.Compiled); + + public V2OrderCleanupTests(IntegrationTestFixture fixture, ITestOutputHelper output) + { + _output = output; + var env = V2EnvHelper.LoadAndPromote(); + _apiUrl = V2EnvHelper.GetEnv(env, "CERTINEXT_API_URL"); + _clientId = V2EnvHelper.GetEnv(env, "CERTINEXT_CLIENT_ID"); + _clientSecret = V2EnvHelper.GetEnv(env, "CERTINEXT_CLIENT_SECRET"); + _groupNumber = V2EnvHelper.GetEnv(env, "CERTINEXT_GROUP_NUMBER", string.Empty); + _v2Enabled = !string.IsNullOrWhiteSpace(V2EnvHelper.GetEnv(env, "CERTINEXT_USE_V2_API")) + && !string.IsNullOrWhiteSpace(_apiUrl) + && !string.IsNullOrWhiteSpace(_clientId) + && !string.IsNullOrWhiteSpace(_clientSecret); + } + + private static string Scrub(string s) + { + if (string.IsNullOrEmpty(s)) return s ?? string.Empty; + s = EmailRx.Replace(s, ""); + return s.Length > 500 ? s.Substring(0, 500) + "..." : s; + } + + private void W(string s) => _output.WriteLine(Scrub(s)); + + private static string Describe(Exception ex) => $"{ex.GetType().Name}: {ex.Message}"; + + private CERTInextConfig BuildConfig() => new CERTInextConfig + { + ApiUrl = _apiUrl, + UseV2Api = true, + OAuthClientId = _clientId, + OAuthClientSecret = _clientSecret, + RequestorName = "Keyfactor Integration Test", + RequestorIsdCode = "1", + RequestorMobileNumber = "0000000000", + SignerPlace = "Gateway Lab", + SignerIp = "127.0.0.1", + GroupNumber = _groupNumber, + PageSize = 100, + DcvEnabled = false + }; + + private static bool IsTerminalNoAction(string status) => + string.Equals(status, Constants.ApiV2.StatusRevoked, StringComparison.OrdinalIgnoreCase) + || string.Equals(status, Constants.ApiV2.StatusCancelled, StringComparison.OrdinalIgnoreCase) + || string.Equals(status, Constants.ApiV2.StatusRejected, StringComparison.OrdinalIgnoreCase) + || string.Equals(status, Constants.ApiV2.StatusExpired, StringComparison.OrdinalIgnoreCase); + + private static bool IsPending(string status) => + !string.IsNullOrEmpty(status) && status.StartsWith("pending-", StringComparison.OrdinalIgnoreCase); + + private sealed class Row + { + public string OrderId; + public string Before = "-"; + public string Action = "none"; + public string After = "-"; + public string Notes = string.Empty; + } + + [SkippableFact] + public async Task V2_CleanupExplicitOrders_RevokeOrCancelListedIdsOnly() + { + Skip.If(!_v2Enabled, + "V2 credentials not configured in ~/.env_certinext_v2 (CERTINEXT_USE_V2_API, API_URL, CLIENT_ID, CLIENT_SECRET)."); + string flag = Environment.GetEnvironmentVariable(OptInFlag); + Skip.If(string.IsNullOrWhiteSpace(flag), + $"Opt-in: set {OptInFlag}= as a real environment variable."); + + var ids = flag.Split(new[] { ',', ' ', ';' }, StringSplitOptions.RemoveEmptyEntries) + .Select(s => s.Trim()).Distinct(StringComparer.Ordinal).ToList(); + Assert.NotEmpty(ids); + Assert.True(ids.Count <= MaxOrders, $"At most {MaxOrders} order ids per run."); + Assert.All(ids, id => Assert.Matches("^[0-9]{1,20}$", id)); // digits only: refuse anything pattern-like + + var cfg = BuildConfig(); + using var client = new CERTInextClient(cfg); + string family = Constants.ApiV2.FamilySsl; + bool dryRun = Environment.GetEnvironmentVariable("CERTINEXT_V2_CLEANUP_DRYRUN") == "1"; + if (dryRun) W("DRY RUN: track + details only; no revoke/cancel will be sent."); + bool forceCancel = Environment.GetEnvironmentVariable("CERTINEXT_V2_CLEANUP_FORCE_CANCEL") == "1"; + Assert.True(!forceCancel || ids.Count == 1, "CERTINEXT_V2_CLEANUP_FORCE_CANCEL requires exactly one order id."); + if (forceCancel) W("FORCE CANCEL: one raw cancel attempt (no revoke, no retry) for the single listed order."); + + W($"V2 order cleanup: {ids.Count} listed order(s), family={family}"); + + // 1) Read-only detail lookup (creation date, domain) from a narrow order-report window. + // Only the listed ids are retained; nothing here drives an action. + var listed = new Dictionary(StringComparer.Ordinal); + try + { + string from = DateTime.UtcNow.AddDays(-1).ToString("yyyy-MM-dd", CultureInfo.InvariantCulture); + string to = DateTime.UtcNow.AddDays(1).ToString("yyyy-MM-dd", CultureInfo.InvariantCulture); + int scanned = 0; + await foreach (var e in client.ListOrdersV2Async(from, to, 100)) + { + scanned++; + if (e?.OrderNumber != null && ids.Contains(e.OrderNumber)) + listed[e.OrderNumber] = e; + } + W($"order-report window {from}..{to}: scanned={scanned}, matched listed ids={listed.Count}"); + } + catch (Exception ex) + { + W("order-report lookup failed (details only; cleanup continues): " + Describe(ex)); + } + + foreach (var id in ids) + { + if (listed.TryGetValue(id, out var e)) + W($"detail order={id} domain={e.DomainName} orderStatus={e.OrderStatus} certStatus={e.CertificateStatus} " + + $"orderDate={e.OrderDate} productCode={e.ProductCode} requestNumber={e.RequestNumber}"); + else + W($"detail order={id} NOT present in order-report window"); + } + + // 2) Per-order: track -> act -> track. + var rows = new List(); + foreach (var id in ids) + { + var row = new Row { OrderId = id }; + rows.Add(row); + + V2OrderStatusResponse before = null; + try + { + before = await client.TrackOrderV2Async(family, id); + row.Before = before.Status ?? "(null)"; + W($"track-before order={id} status={before.Status} domain={before.Domain} variant={before.ProductVariant} " + + $"issuedAt={before.IssuedAt} expiresAt={before.ExpiresAt}"); + } + catch (KeyNotFoundException) + { + row.Before = "NOT FOUND"; + row.Action = "skipped (not found in " + family + ")"; + W($"order={id} not found in family {family}; no action taken"); + continue; + } + catch (Exception ex) + { + row.Before = "TRACK ERROR"; + row.Action = "skipped"; + row.Notes = Scrub(Describe(ex)); + continue; + } + + string status = before.Status; + if (dryRun) + { + row.Action = "dry-run (none)"; + row.After = row.Before; + continue; + } + try + { + if (IsTerminalNoAction(status)) + { + row.Action = "skip (already " + status + ")"; + } + else if (forceCancel) + { + // Single attempt via the raw helper (same POST .../cancel endpoint as CancelOrderV2Async) + // so the exact HTTP status and body detail are captured; no retry, no other mutation. + row.Action = "force-cancel (single attempt)"; + try + { + await V2RawHttpHelpers.CancelSslOrderRawAsync(_apiUrl, _clientId, _clientSecret, id, CleanupReason); + row.Action += " -> accepted (2xx)"; + } + catch (Exception cex) + { + row.Action += " -> REJECTED"; + row.Notes += "cancel response: " + Scrub(Describe(cex)); + } + } + else if (string.Equals(status, Constants.ApiV2.StatusIssued, StringComparison.OrdinalIgnoreCase)) + { + row.Action = await RevokeAsync(client, family, id, row); + } + else if (IsPending(status)) + { + var outcome = await client.CancelOrderV2Async(family, id, CleanupReason); + row.Action = "cancel -> " + outcome; + } + else + { + row.Action = "skip (unrecognised status; not acting)"; + } + } + catch (Exception ex) + { + row.Action += (row.Action == "none" ? "" : "; ") + "ACTION FAILED"; + row.Notes += (row.Notes.Length > 0 ? " | " : "") + Scrub(Describe(ex)); + } + + try + { + var after = await client.TrackOrderV2Async(family, id); + row.After = after.Status ?? "(null)"; + if (after.Revocation != null) + row.Notes += (row.Notes.Length > 0 ? " | " : "") + + $"revocation.reason={after.Revocation.Reason} processedAt={after.Revocation.ProcessedAt}"; + } + catch (Exception ex) + { + row.After = "TRACK ERROR"; + row.Notes += (row.Notes.Length > 0 ? " | " : "") + Scrub(Describe(ex)); + } + } + + if (forceCancel) + { + try + { + string from2 = DateTime.UtcNow.AddDays(-1).ToString("yyyy-MM-dd", CultureInfo.InvariantCulture); + string to2 = DateTime.UtcNow.AddDays(1).ToString("yyyy-MM-dd", CultureInfo.InvariantCulture); + bool found = false; + await foreach (var e2 in client.ListOrdersV2Async(from2, to2, 100)) + if (e2?.OrderNumber != null && ids.Contains(e2.OrderNumber)) + { + found = true; + W($"listing-after order={e2.OrderNumber} orderStatus={e2.OrderStatus} certStatus={e2.CertificateStatus} orderDate={e2.OrderDate}"); + } + if (!found) W("listing-after: listed order not present in window"); + } + catch (Exception lex) { W("listing-after failed: " + Describe(lex)); } + } + + W("=== result: order | before | action | after | notes ==="); + foreach (var r in rows) + W($"RESULT {r.OrderId} | {r.Before} | {r.Action} | {r.After} | {r.Notes}"); + + if (dryRun || forceCancel) return; // force-cancel is a probe: outcome is reported, not asserted + + // Pass only when every listed order ended in a terminal non-issued state. + var bad = rows.Where(r => !IsTerminalNoAction(r.After)).Select(r => $"{r.OrderId}({r.After})").ToList(); + Assert.True(bad.Count == 0, "Orders not in a terminal state after cleanup: " + string.Join(", ", bad)); + } + + /// + /// Revoke an issued order. Tries "superseded" (what plugin reason 4 maps to); if CERTInext + /// rejects it, records the exact rejection in and retries once with + /// "unspecified" so a spec-vs-live reason discrepancy is surfaced instead of hidden. + /// + private static async Task RevokeAsync(CERTInextClient client, string family, string id, Row row) + { + try + { + await client.RevokeOrderV2Async(family, id, + new V2RevokeRequest { Reason = "superseded", Note = CleanupReason }); + return "revoke(reason=superseded)"; + } + catch (Exception ex) + { + row.Notes += "revoke(superseded) rejected: " + Scrub(Describe(ex)); + } + + await client.RevokeOrderV2Async(family, id, + new V2RevokeRequest { Reason = "unspecified", Note = CleanupReason }); + return "revoke(reason=unspecified, after superseded rejected)"; + } + } +}