diff --git a/CHANGELOG.md b/CHANGELOG.md index 8355964..90e8230 100644 --- a/CHANGELOG.md +++ b/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 diff --git a/GCPCAS/Client/GCPCASClient.cs b/GCPCAS/Client/GCPCASClient.cs index 0197836..455a733 100644 --- a/GCPCAS/Client/GCPCASClient.cs +++ b/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 DownloadAllIssuedCertificates(BlockingCollection DownloadAllIssuedCertificates(BlockingCollection DownloadAllIssuedCertificates(BlockingCollection + /// Emits detailed diagnostics about the certificate content being handed to the AnyCA Gateway. + /// The Gateway parses 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. + /// + 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}"); + } + } + + /// + /// Mirrors the subject parsing the AnyCA Gateway performs when it builds the /v2/certificate/search + /// response: new Org.BouncyCastle.Asn1.X509.X509Name(true, netCert.Subject). 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 lets the sync skip the + /// certificate so it never enters the gateway database and can never break the downstream Command sync. + /// + /// The PEM certificate content that will be handed to the gateway. + /// The parsed .NET subject string, when available (for logging). + /// The exception message when parsing fails. + /// if the gateway can parse the subject; otherwise . + 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; + } + } /// /// Enrolls a certificate using a configured and returns the result. /// diff --git a/GCPCAS/FlowLogger.cs b/GCPCAS/FlowLogger.cs new file mode 100644 index 0000000..f21e613 --- /dev/null +++ b/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 Children { get; } = new(); +} + +/// +/// 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 +/// +public sealed class FlowLogger : IDisposable +{ + private readonly ILogger _logger; + private readonly string _flowName; + private readonly Stopwatch _totalTimer; + private readonly List _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); + } + + /// Record a completed step. + 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; + } + + /// Record a step that executes an action and times it. + 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; + } + + /// Record an async step that executes and times it. + public async Task StepAsync(string name, Func 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; + } + + /// Record a failed step without throwing. + 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; + } + + /// Record a skipped step. + 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; + } + + /// Start a branch (group of child steps). + 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; + } + + /// End the current branch. + public FlowLogger EndBranch() + { + _currentParent = null; + return this; + } + + private void AddStep(FlowStep step) + { + if (_currentParent != null) + _currentParent.Children.Add(step); + else + _steps.Add(step); + } + + /// Render the visual flow diagram to Trace log. + 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()); + } +} diff --git a/GCPCAS/GCPCAS.csproj b/GCPCAS/GCPCAS.csproj index d27536c..366c8df 100644 --- a/GCPCAS/GCPCAS.csproj +++ b/GCPCAS/GCPCAS.csproj @@ -1,6 +1,6 @@ - net6.0;net8.0 + net6.0;net8.0;net10.0 disable true Keyfactor.Extensions.CAPlugin.GCPCAS diff --git a/GCPCAS/GCPCASCAPlugin.cs b/GCPCAS/GCPCASCAPlugin.cs index 431720b..1a2337e 100644 --- a/GCPCAS/GCPCASCAPlugin.cs +++ b/GCPCAS/GCPCASCAPlugin.cs @@ -113,40 +113,88 @@ public Task ValidateProductInfo(EnrollmentProductInfo productInfo, Dictionary blockingBuffer, DateTime? lastSync, bool fullSync, CancellationToken cancelToken) { _logger.MethodEntry(); + string syncType = fullSync ? "Full" : "Incremental"; + using var flow = new FlowLogger(_logger, $"Synchronize-{syncType}"); + _logger.LogTrace($"Synchronize called. fullSync={fullSync}, lastSync={lastSync?.ToString("o") ?? "(null)"}, blockingBuffer is {(blockingBuffer == null ? "NULL" : "present")}"); + + if (blockingBuffer == null) + { + flow.Fail("ValidateBuffer", "blockingBuffer is null"); + throw new ArgumentNullException(nameof(blockingBuffer), "blockingBuffer cannot be null in Synchronize"); + } + if (fullSync && lastSync != null) { _logger.LogInformation("Performing a full CA synchronization"); lastSync = null; + flow.Step("DetermineFilter", "Full sync - clearing date filter"); } else { _logger.LogInformation($"Performing an incremental CA synchronization - downloading certificates issued after {lastSync}"); + flow.Step("DetermineFilter", $"Incremental - issuedAfter={lastSync?.ToString("o") ?? "(null)"}"); + } + + int certificates = 0; + try + { + await flow.StepAsync("DownloadAllIssuedCertificates", async () => + { + certificates = await Client.DownloadAllIssuedCertificates(blockingBuffer, cancelToken, lastSync); + }, $"buffered count after download"); + flow.Step("Synchronized", $"{certificates} certificate(s)"); + _logger.LogDebug($"Synchronized {certificates} certificates"); + } + catch (OperationCanceledException) + { + flow.Fail("Cancelled", "operation was cancelled"); + throw; + } + catch (Exception e) + { + flow.Fail("SyncError", e.Message); + _logger.LogError($"GCP CAS Synchronize task failed: {e.Message}"); + throw; } - int certificates = await Client.DownloadAllIssuedCertificates(blockingBuffer, cancelToken, lastSync); - _logger.LogDebug($"Synchronized {certificates} certificates"); _logger.MethodExit(); } - public Task GetSingleRecord(string caRequestID) + public async Task GetSingleRecord(string caRequestID) { _logger.MethodEntry(); + using var flow = new FlowLogger(_logger, $"GetSingleRecord({caRequestID ?? "null"})"); + AnyCAPluginCertificate result = null; + await flow.StepAsync("DownloadCertificate", async () => + { + result = await Client.DownloadCertificate(caRequestID); + }, $"caRequestID={caRequestID ?? "(null)"}"); _logger.MethodExit(); - return Client.DownloadCertificate(caRequestID); + return result; } - public Task Enroll(string csr, string subject, Dictionary san, EnrollmentProductInfo productInfo, RequestFormat requestFormat, EnrollmentType enrollmentType) + public async Task Enroll(string csr, string subject, Dictionary san, EnrollmentProductInfo productInfo, RequestFormat requestFormat, EnrollmentType enrollmentType) { _logger.MethodEntry(); - ICreateCertificateRequestBuilder ccrBuilder = new CreateCertificateRequestBuilder() - .WithCsr(csr) - .WithSubject(subject) - .WithSans(san) - .WithEnrollmentProductInfo(productInfo) - .WithRequestFormat(requestFormat) - .WithEnrollmentType(enrollmentType); + using var flow = new FlowLogger(_logger, $"Enroll-{enrollmentType}"); + ICreateCertificateRequestBuilder ccrBuilder = null; + flow.Step("BuildRequest", () => + { + ccrBuilder = new CreateCertificateRequestBuilder() + .WithCsr(csr) + .WithSubject(subject) + .WithSans(san) + .WithEnrollmentProductInfo(productInfo) + .WithRequestFormat(requestFormat) + .WithEnrollmentType(enrollmentType); + }, $"subject='{subject}', sanCount={(san?.Count ?? 0)}"); + EnrollmentResult result = null; + await flow.StepAsync("Enroll", async () => + { + result = await Client.Enroll(ccrBuilder, CancellationToken.None); + }, $"status after enroll"); _logger.MethodExit(); - return Client.Enroll(ccrBuilder, CancellationToken.None); + return result; } public async Task Revoke(string caRequestID, string hexSerialNumber, uint revocationReason)