200dayfixes

CHANGELOG.md

@@ -1,3 +1,5 @@
+- 1.3.3
+  - Sync now skips bad/unparseable certificates returned from Google CAS instead of failing the sync.
 - 1.3.2
   - Fixed Sans Being passed through Extensions Data, Google does not like this.
 - 1.3.1

GCPCAS/Client/GCPCASClient.cs

@@ -17,6 +17,7 @@ limitations under the License.
 using System;
 using System.Collections.Concurrent;
 using System.Collections.Generic;
+using System.Security.Cryptography.X509Certificates;
 using System.Threading;
 using System.Threading.Tasks;
 using Google.Api.Gax;
@@ -247,6 +248,7 @@ public async Task<int> DownloadAllIssuedCertificates(BlockingCollection<AnyCAPlu
 
         int pageNumber = 0;
         int numberOfCertificates = 0;
+        int skippedCertificates = 0;
 
         try
         {
@@ -269,7 +271,21 @@ public async Task<int> DownloadAllIssuedCertificates(BlockingCollection<AnyCAPlu
                             continue;
                         }
                     }
-                    certificatesBuffer.Add(AnyCAPluginCertificateFromGCPCertificate(certificate));
+                    AnyCAPluginCertificate pluginCertificate = AnyCAPluginCertificateFromGCPCertificate(certificate);
+
+                    // Mirror the subject handling the AnyCA Gateway performs when it builds the
+                    // /v2/certificate/search response: `new X509Name(true, netCert.Subject)`. That call throws
+                    // on subjects BouncyCastle cannot re-parse from .NET's string form, which 500s the entire
+                    // gateway search page and aborts Command's CA sync. Skip such certs here so they never enter
+                    // the gateway database and can never break the downstream sync.
+                    if (!GatewayCanParseSubject(pluginCertificate.Certificate, out string subject, out string skipReason))
+                    {
+                        skippedCertificates++;
+                        _logger.LogWarning($"[SYNC-SKIP] Skipping certificate {pluginCertificate.CARequestID} - its subject would fail the AnyCA Gateway X509Name parse and abort the sync. Subject='{subject}', reason: {skipReason}");
+                        continue;
+                    }
+
+                    certificatesBuffer.Add(pluginCertificate);
                     numberOfCertificates++;
                     _logger.LogDebug($"Found Certificate with name {certificate.CertificateName.CertificateId} {this.ToString()}");
                 }
@@ -297,6 +313,7 @@ public async Task<int> DownloadAllIssuedCertificates(BlockingCollection<AnyCAPlu
         {
             certificatesBuffer.CompleteAdding();
             _logger.LogDebug($"Fetched {certificatesBuffer.Count} certificates from GCP over {pageNumber} pages.");
+            _logger.LogInformation($"[SYNC-DIAG] Handed {numberOfCertificates} certificate(s) to the AnyCA Gateway buffer; skipped {skippedCertificates} certificate(s) with subjects the gateway cannot parse. Review the per-record [SYNC-DIAG]/[SYNC-SKIP] lines above for details.");
         }
         _logger.MethodExit();
         return numberOfCertificates;
@@ -356,17 +373,94 @@ private AnyCAPluginCertificate AnyCAPluginCertificateFromGCPCertificate(Certific
             status = EndEntityStatus.REVOKED;
             revocationReason = (int)certificate.RevocationDetails.RevocationState;
         }
+
+        string caRequestId = certificate.CertificateName.CertificateId;
+        string pem = certificate.PemCertificate;
+
+        // DIAGNOSTIC: the AnyCA Gateway derives the synced certificate's fingerprint and notBefore
+        // (the fields Command's sync gates on) by parsing the content we put in AnyCAPluginCertificate.Certificate.
+        // Log the shape of that content and the metadata that *should* be derivable from it, so we can
+        // compare against what the Gateway stores / returns to Command on the /v2/certificate/search response.
+        LogCertificateContentDiagnostics(caRequestId, pem, status, revocationDate, revocationReason);
+
         _logger.MethodExit();
         return new AnyCAPluginCertificate
         {
-            CARequestID = certificate.CertificateName.CertificateId,
-            Certificate = certificate.PemCertificate,
+            CARequestID = caRequestId,
+            Certificate = pem,
             Status = (int)status,
             ProductID = productId,
             RevocationDate = revocationDate,
             RevocationReason = revocationReason,
         };
     }
+
+    /// <summary>
+    /// Emits detailed diagnostics about the certificate content being handed to the AnyCA Gateway.
+    /// The Gateway parses <see cref="AnyCAPluginCertificate.Certificate"/> to populate the fingerprint and
+    /// notBefore fields that Command's incremental sync (IssuedDateSyncPartitionTracker) gates on. Logging
+    /// the raw shape and the parsed metadata here pinpoints whether the plugin is the source of empty/zero
+    /// values seen downstream.
+    /// </summary>
+    private void LogCertificateContentDiagnostics(string caRequestId, string pem, EndEntityStatus status, DateTime? revocationDate, int? revocationReason)
+    {
+        try
+        {
+            if (string.IsNullOrEmpty(pem))
+            {
+                _logger.LogWarning($"[SYNC-DIAG] CARequestID={caRequestId}: PemCertificate is NULL or EMPTY - the Gateway will have no content to derive fingerprint/notBefore from. status={status} revoked={(revocationDate != null)}");
+                return;
+            }
+
+            bool hasPemArmor = pem.Contains("-----BEGIN");
+            _logger.LogTrace($"[SYNC-DIAG] CARequestID={caRequestId}: PemCertificate length={pem.Length}, hasPemArmor={hasPemArmor}, first40='{pem.Substring(0, Math.Min(40, pem.Length)).Replace("\n", "\\n").Replace("\r", "\\r")}'");
+
+            // Parse exactly what the Gateway would parse to derive metadata.
+            using var parsed = X509Certificate2.CreateFromPem(pem);
+            long notBeforeEpochMs = new DateTimeOffset(parsed.NotBefore.ToUniversalTime()).ToUnixTimeMilliseconds();
+            long notAfterEpochMs = new DateTimeOffset(parsed.NotAfter.ToUniversalTime()).ToUnixTimeMilliseconds();
+
+            _logger.LogDebug(
+                $"[SYNC-DIAG] CARequestID={caRequestId}: parsed OK -> Thumbprint(fingerprint)={parsed.Thumbprint}, " +
+                $"SerialNumber={parsed.SerialNumber}, Subject='{parsed.Subject}', " +
+                $"NotBefore={parsed.NotBefore:o} (epochMs={notBeforeEpochMs}), NotAfter={parsed.NotAfter:o} (epochMs={notAfterEpochMs}), " +
+                $"status={status}, revoked={(revocationDate != null)}, revocationReason={revocationReason}");
+        }
+        catch (Exception ex)
+        {
+            _logger.LogWarning($"[SYNC-DIAG] CARequestID={caRequestId}: FAILED to parse PemCertificate into an X509Certificate2 - the Gateway will likely store an empty fingerprint / notBefore=0 for this record. Error: {ex.Message}");
+        }
+    }
+
+    /// <summary>
+    /// Mirrors the subject parsing the AnyCA Gateway performs when it builds the /v2/certificate/search
+    /// response: <c>new Org.BouncyCastle.Asn1.X509.X509Name(true, netCert.Subject)</c>. That call throws on
+    /// subjects BouncyCastle cannot re-parse from .NET's string representation, which 500s the entire gateway
+    /// search page and aborts Command's CA sync. Returning <see langword="false"/> lets the sync skip the
+    /// certificate so it never enters the gateway database and can never break the downstream Command sync.
+    /// </summary>
+    /// <param name="pem">The PEM certificate content that will be handed to the gateway.</param>
+    /// <param name="subject">The parsed .NET subject string, when available (for logging).</param>
+    /// <param name="failureReason">The exception message when parsing fails.</param>
+    /// <returns><see langword="true"/> if the gateway can parse the subject; otherwise <see langword="false"/>.</returns>
+    private bool GatewayCanParseSubject(string pem, out string subject, out string failureReason)
+    {
+        subject = null;
+        failureReason = null;
+        try
+        {
+            using X509Certificate2 netCert = X509Certificate2.CreateFromPem(pem);
+            subject = netCert.Subject;
+            // This is the exact operation the gateway performs and that throws on problematic subjects.
+            _ = new Org.BouncyCastle.Asn1.X509.X509Name(true, subject);
+            return true;
+        }
+        catch (Exception ex)
+        {
+            failureReason = ex.Message;
+            return false;
+        }
+    }
     /// <summary>
     /// Enrolls a certificate using a configured <see cref="ICreateCertificateRequestBuilder"/> and returns the result.
     /// </summary>

GCPCAS/FlowLogger.cs

@@ -0,0 +1,244 @@
+// Copyright 2025 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.Diagnostics;
+using System.Linq;
+using System.Text;
+using System.Threading.Tasks;
+using Microsoft.Extensions.Logging;
+
+namespace Keyfactor.Extensions.CAPlugin.GCPCAS;
+
+public enum FlowStepStatus
+{
+    Success,
+    Failed,
+    Skipped,
+    InProgress
+}
+
+public class FlowStep
+{
+    public string Name { get; set; }
+    public FlowStepStatus Status { get; set; }
+    public string Detail { get; set; }
+    public long ElapsedMs { get; set; }
+    public List<FlowStep> Children { get; } = new();
+}
+
+/// <summary>
+///     Tracks high-level operation flow and renders a visual step diagram to Trace logs.
+///     Usage:
+///       using var flow = new FlowLogger(logger, "Enroll-New");
+///       flow.Step("ParseCSR");
+///       flow.Step("ValidateCSR", () => { ... });
+///       flow.Fail("CreateOrder", "API returned 400");
+///       // flow renders automatically on Dispose
+/// </summary>
+public sealed class FlowLogger : IDisposable
+{
+    private readonly ILogger _logger;
+    private readonly string _flowName;
+    private readonly Stopwatch _totalTimer;
+    private readonly List<FlowStep> _steps = new();
+    private FlowStep _currentParent;
+    private bool _disposed;
+
+    public FlowLogger(ILogger logger, string flowName)
+    {
+        _logger = logger;
+        _flowName = flowName;
+        _totalTimer = Stopwatch.StartNew();
+        _logger.LogTrace("===== FLOW START: {FlowName} =====", _flowName);
+    }
+
+    /// <summary>Record a completed step.</summary>
+    public FlowLogger Step(string name, string detail = null)
+    {
+        var step = new FlowStep { Name = name, Status = FlowStepStatus.Success, Detail = detail };
+        AddStep(step);
+        _logger.LogTrace("  [{FlowName}] {StepName} ... OK{Detail}",
+            _flowName, name, detail != null ? $" ({detail})" : "");
+        return this;
+    }
+
+    /// <summary>Record a step that executes an action and times it.</summary>
+    public FlowLogger Step(string name, Action action, string detail = null)
+    {
+        var sw = Stopwatch.StartNew();
+        var step = new FlowStep { Name = name, Detail = detail };
+        try
+        {
+            _logger.LogTrace("  [{FlowName}] {StepName} ...", _flowName, name);
+            action();
+            sw.Stop();
+            step.Status = FlowStepStatus.Success;
+            step.ElapsedMs = sw.ElapsedMilliseconds;
+            AddStep(step);
+            _logger.LogTrace("  [{FlowName}] {StepName} ... OK ({Elapsed}ms){Detail}",
+                _flowName, name, sw.ElapsedMilliseconds, detail != null ? $" {detail}" : "");
+        }
+        catch (Exception ex)
+        {
+            sw.Stop();
+            step.Status = FlowStepStatus.Failed;
+            step.ElapsedMs = sw.ElapsedMilliseconds;
+            step.Detail = ex.Message;
+            AddStep(step);
+            _logger.LogTrace("  [{FlowName}] {StepName} ... FAILED ({Elapsed}ms): {Error}",
+                _flowName, name, sw.ElapsedMilliseconds, ex.Message);
+            throw;
+        }
+        return this;
+    }
+
+    /// <summary>Record an async step that executes and times it.</summary>
+    public async Task<FlowLogger> StepAsync(string name, Func<Task> action, string detail = null)
+    {
+        var sw = Stopwatch.StartNew();
+        var step = new FlowStep { Name = name, Detail = detail };
+        try
+        {
+            _logger.LogTrace("  [{FlowName}] {StepName} ...", _flowName, name);
+            await action();
+            sw.Stop();
+            step.Status = FlowStepStatus.Success;
+            step.ElapsedMs = sw.ElapsedMilliseconds;
+            AddStep(step);
+            _logger.LogTrace("  [{FlowName}] {StepName} ... OK ({Elapsed}ms){Detail}",
+                _flowName, name, sw.ElapsedMilliseconds, detail != null ? $" {detail}" : "");
+        }
+        catch (Exception ex)
+        {
+            sw.Stop();
+            step.Status = FlowStepStatus.Failed;
+            step.ElapsedMs = sw.ElapsedMilliseconds;
+            step.Detail = ex.Message;
+            AddStep(step);
+            _logger.LogTrace("  [{FlowName}] {StepName} ... FAILED ({Elapsed}ms): {Error}",
+                _flowName, name, sw.ElapsedMilliseconds, ex.Message);
+            throw;
+        }
+        return this;
+    }
+
+    /// <summary>Record a failed step without throwing.</summary>
+    public FlowLogger Fail(string name, string reason = null)
+    {
+        var step = new FlowStep { Name = name, Status = FlowStepStatus.Failed, Detail = reason };
+        AddStep(step);
+        _logger.LogTrace("  [{FlowName}] {StepName} ... FAILED{Reason}",
+            _flowName, name, reason != null ? $": {reason}" : "");
+        return this;
+    }
+
+    /// <summary>Record a skipped step.</summary>
+    public FlowLogger Skip(string name, string reason = null)
+    {
+        var step = new FlowStep { Name = name, Status = FlowStepStatus.Skipped, Detail = reason };
+        AddStep(step);
+        _logger.LogTrace("  [{FlowName}] {StepName} ... SKIPPED{Reason}",
+            _flowName, name, reason != null ? $": {reason}" : "");
+        return this;
+    }
+
+    /// <summary>Start a branch (group of child steps).</summary>
+    public FlowLogger Branch(string name)
+    {
+        var step = new FlowStep { Name = name, Status = FlowStepStatus.InProgress };
+        AddStep(step);
+        _currentParent = step;
+        _logger.LogTrace("  [{FlowName}] >> Branch: {BranchName}", _flowName, name);
+        return this;
+    }
+
+    /// <summary>End the current branch.</summary>
+    public FlowLogger EndBranch()
+    {
+        _currentParent = null;
+        return this;
+    }
+
+    private void AddStep(FlowStep step)
+    {
+        if (_currentParent != null)
+            _currentParent.Children.Add(step);
+        else
+            _steps.Add(step);
+    }
+
+    /// <summary>Render the visual flow diagram to Trace log.</summary>
+    private string RenderFlow()
+    {
+        var sb = new StringBuilder();
+        sb.AppendLine();
+        sb.AppendLine($"  ===== FLOW: {_flowName} ({_totalTimer.ElapsedMilliseconds}ms total) =====");
+        sb.AppendLine();
+
+        for (var i = 0; i < _steps.Count; i++)
+        {
+            var step = _steps[i];
+            var icon = GetStatusIcon(step.Status);
+            var elapsed = step.ElapsedMs > 0 ? $" ({step.ElapsedMs}ms)" : "";
+            var detail = !string.IsNullOrEmpty(step.Detail) ? $" [{step.Detail}]" : "";
+
+            sb.AppendLine($"    {icon} {step.Name}{elapsed}{detail}");
+
+            // Render children (branch)
+            if (step.Children.Count > 0)
+            {
+                for (var j = 0; j < step.Children.Count; j++)
+                {
+                    var child = step.Children[j];
+                    var childIcon = GetStatusIcon(child.Status);
+                    var childElapsed = child.ElapsedMs > 0 ? $" ({child.ElapsedMs}ms)" : "";
+                    var childDetail = !string.IsNullOrEmpty(child.Detail) ? $" [{child.Detail}]" : "";
+                    sb.AppendLine($"    |");
+                    sb.AppendLine($"    +-- {childIcon} {child.Name}{childElapsed}{childDetail}");
+                }
+            }
+
+            // Connector between top-level steps
+            if (i < _steps.Count - 1)
+            {
+                sb.AppendLine("    |");
+                sb.AppendLine("    v");
+            }
+        }
+
+        sb.AppendLine();
+
+        // Final status line
+        var finalStatus = _steps.Count > 0 && _steps.Last().Status == FlowStepStatus.Failed
+            ? "FAILED" : _steps.Any(s => s.Status == FlowStepStatus.Failed) ? "PARTIAL FAILURE" : "SUCCESS";
+        sb.AppendLine($"  ===== FLOW RESULT: {finalStatus} =====");
+
+        return sb.ToString();
+    }
+
+    private static string GetStatusIcon(FlowStepStatus status)
+    {
+        return status switch
+        {
+            FlowStepStatus.Success => "[OK]",
+            FlowStepStatus.Failed => "[FAIL]",
+            FlowStepStatus.Skipped => "[SKIP]",
+            FlowStepStatus.InProgress => "[...]",
+            _ => "[?]"
+        };
+    }
+
+    public void Dispose()
+    {
+        if (_disposed) return;
+        _disposed = true;
+        _totalTimer.Stop();
+        _logger.LogTrace(RenderFlow());
+    }
+}