Skip to content

Commit 9b79805

Browse files
Add FlowLogger and sync diagnostics for certificate metadata troubleshooting
Port the FlowLogger workflow-tracing utility from the cscglobal-caplugin 200dayfixes branch and wire it into the plugin's Synchronize, Enroll, and GetSingleRecord operations to render step-by-step, timed flow diagrams to Trace logs. Add [SYNC-DIAG] instrumentation in GCPCASClient that, for every certificate handed to the AnyCA Gateway during sync, parses the PEM content and logs the fingerprint (thumbprint), NotBefore (as epoch ms), NotAfter, serial number, and subject - i.e. the exact metadata the Gateway must surface to Command on /v2/certificate/search and that the incremental sync gates on. Records whose content is null/empty or unparseable are flagged, pinpointing whether empty fingerprint / notBefore=0 values originate in the plugin.
1 parent ffc3923 commit 9b79805

3 files changed

Lines changed: 356 additions & 15 deletions

File tree

GCPCAS/Client/GCPCASClient.cs

Lines changed: 51 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -17,6 +17,7 @@ limitations under the License.
1717
using System;
1818
using System.Collections.Concurrent;
1919
using System.Collections.Generic;
20+
using System.Security.Cryptography.X509Certificates;
2021
using System.Threading;
2122
using System.Threading.Tasks;
2223
using Google.Api.Gax;
@@ -297,6 +298,7 @@ public async Task<int> DownloadAllIssuedCertificates(BlockingCollection<AnyCAPlu
297298
{
298299
certificatesBuffer.CompleteAdding();
299300
_logger.LogDebug($"Fetched {certificatesBuffer.Count} certificates from GCP over {pageNumber} pages.");
301+
_logger.LogInformation($"[SYNC-DIAG] Handed {numberOfCertificates} certificate(s) to the AnyCA Gateway buffer. Review the per-record [SYNC-DIAG] lines above to confirm each carries a parseable fingerprint and NotBefore - these are the values the Gateway must surface to Command on /v2/certificate/search.");
300302
}
301303
_logger.MethodExit();
302304
return numberOfCertificates;
@@ -356,17 +358,64 @@ private AnyCAPluginCertificate AnyCAPluginCertificateFromGCPCertificate(Certific
356358
status = EndEntityStatus.REVOKED;
357359
revocationReason = (int)certificate.RevocationDetails.RevocationState;
358360
}
361+
362+
string caRequestId = certificate.CertificateName.CertificateId;
363+
string pem = certificate.PemCertificate;
364+
365+
// DIAGNOSTIC: the AnyCA Gateway derives the synced certificate's fingerprint and notBefore
366+
// (the fields Command's sync gates on) by parsing the content we put in AnyCAPluginCertificate.Certificate.
367+
// Log the shape of that content and the metadata that *should* be derivable from it, so we can
368+
// compare against what the Gateway stores / returns to Command on the /v2/certificate/search response.
369+
LogCertificateContentDiagnostics(caRequestId, pem, status, revocationDate, revocationReason);
370+
359371
_logger.MethodExit();
360372
return new AnyCAPluginCertificate
361373
{
362-
CARequestID = certificate.CertificateName.CertificateId,
363-
Certificate = certificate.PemCertificate,
374+
CARequestID = caRequestId,
375+
Certificate = pem,
364376
Status = (int)status,
365377
ProductID = productId,
366378
RevocationDate = revocationDate,
367379
RevocationReason = revocationReason,
368380
};
369381
}
382+
383+
/// <summary>
384+
/// Emits detailed diagnostics about the certificate content being handed to the AnyCA Gateway.
385+
/// The Gateway parses <see cref="AnyCAPluginCertificate.Certificate"/> to populate the fingerprint and
386+
/// notBefore fields that Command's incremental sync (IssuedDateSyncPartitionTracker) gates on. Logging
387+
/// the raw shape and the parsed metadata here pinpoints whether the plugin is the source of empty/zero
388+
/// values seen downstream.
389+
/// </summary>
390+
private void LogCertificateContentDiagnostics(string caRequestId, string pem, EndEntityStatus status, DateTime? revocationDate, int? revocationReason)
391+
{
392+
try
393+
{
394+
if (string.IsNullOrEmpty(pem))
395+
{
396+
_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)}");
397+
return;
398+
}
399+
400+
bool hasPemArmor = pem.Contains("-----BEGIN");
401+
_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")}'");
402+
403+
// Parse exactly what the Gateway would parse to derive metadata.
404+
using var parsed = X509Certificate2.CreateFromPem(pem);
405+
long notBeforeEpochMs = new DateTimeOffset(parsed.NotBefore.ToUniversalTime()).ToUnixTimeMilliseconds();
406+
long notAfterEpochMs = new DateTimeOffset(parsed.NotAfter.ToUniversalTime()).ToUnixTimeMilliseconds();
407+
408+
_logger.LogDebug(
409+
$"[SYNC-DIAG] CARequestID={caRequestId}: parsed OK -> Thumbprint(fingerprint)={parsed.Thumbprint}, " +
410+
$"SerialNumber={parsed.SerialNumber}, Subject='{parsed.Subject}', " +
411+
$"NotBefore={parsed.NotBefore:o} (epochMs={notBeforeEpochMs}), NotAfter={parsed.NotAfter:o} (epochMs={notAfterEpochMs}), " +
412+
$"status={status}, revoked={(revocationDate != null)}, revocationReason={revocationReason}");
413+
}
414+
catch (Exception ex)
415+
{
416+
_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}");
417+
}
418+
}
370419
/// <summary>
371420
/// Enrolls a certificate using a configured <see cref="ICreateCertificateRequestBuilder"/> and returns the result.
372421
/// </summary>

GCPCAS/FlowLogger.cs

Lines changed: 244 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,244 @@
1+
// Copyright 2025 Keyfactor
2+
// Licensed under the Apache License, Version 2.0 (the "License"); you may not use this file except in compliance with the License.
3+
// You may obtain a copy of the License at http://www.apache.org/licenses/LICENSE-2.0
4+
// Unless required by applicable law or agreed to in writing, software distributed under the License is distributed on an "AS IS" BASIS,
5+
// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. See the License for the specific language governing permissions
6+
// and limitations under the License.
7+
8+
using System;
9+
using System.Collections.Generic;
10+
using System.Diagnostics;
11+
using System.Linq;
12+
using System.Text;
13+
using System.Threading.Tasks;
14+
using Microsoft.Extensions.Logging;
15+
16+
namespace Keyfactor.Extensions.CAPlugin.GCPCAS;
17+
18+
public enum FlowStepStatus
19+
{
20+
Success,
21+
Failed,
22+
Skipped,
23+
InProgress
24+
}
25+
26+
public class FlowStep
27+
{
28+
public string Name { get; set; }
29+
public FlowStepStatus Status { get; set; }
30+
public string Detail { get; set; }
31+
public long ElapsedMs { get; set; }
32+
public List<FlowStep> Children { get; } = new();
33+
}
34+
35+
/// <summary>
36+
/// Tracks high-level operation flow and renders a visual step diagram to Trace logs.
37+
/// Usage:
38+
/// using var flow = new FlowLogger(logger, "Enroll-New");
39+
/// flow.Step("ParseCSR");
40+
/// flow.Step("ValidateCSR", () => { ... });
41+
/// flow.Fail("CreateOrder", "API returned 400");
42+
/// // flow renders automatically on Dispose
43+
/// </summary>
44+
public sealed class FlowLogger : IDisposable
45+
{
46+
private readonly ILogger _logger;
47+
private readonly string _flowName;
48+
private readonly Stopwatch _totalTimer;
49+
private readonly List<FlowStep> _steps = new();
50+
private FlowStep _currentParent;
51+
private bool _disposed;
52+
53+
public FlowLogger(ILogger logger, string flowName)
54+
{
55+
_logger = logger;
56+
_flowName = flowName;
57+
_totalTimer = Stopwatch.StartNew();
58+
_logger.LogTrace("===== FLOW START: {FlowName} =====", _flowName);
59+
}
60+
61+
/// <summary>Record a completed step.</summary>
62+
public FlowLogger Step(string name, string detail = null)
63+
{
64+
var step = new FlowStep { Name = name, Status = FlowStepStatus.Success, Detail = detail };
65+
AddStep(step);
66+
_logger.LogTrace(" [{FlowName}] {StepName} ... OK{Detail}",
67+
_flowName, name, detail != null ? $" ({detail})" : "");
68+
return this;
69+
}
70+
71+
/// <summary>Record a step that executes an action and times it.</summary>
72+
public FlowLogger Step(string name, Action action, string detail = null)
73+
{
74+
var sw = Stopwatch.StartNew();
75+
var step = new FlowStep { Name = name, Detail = detail };
76+
try
77+
{
78+
_logger.LogTrace(" [{FlowName}] {StepName} ...", _flowName, name);
79+
action();
80+
sw.Stop();
81+
step.Status = FlowStepStatus.Success;
82+
step.ElapsedMs = sw.ElapsedMilliseconds;
83+
AddStep(step);
84+
_logger.LogTrace(" [{FlowName}] {StepName} ... OK ({Elapsed}ms){Detail}",
85+
_flowName, name, sw.ElapsedMilliseconds, detail != null ? $" {detail}" : "");
86+
}
87+
catch (Exception ex)
88+
{
89+
sw.Stop();
90+
step.Status = FlowStepStatus.Failed;
91+
step.ElapsedMs = sw.ElapsedMilliseconds;
92+
step.Detail = ex.Message;
93+
AddStep(step);
94+
_logger.LogTrace(" [{FlowName}] {StepName} ... FAILED ({Elapsed}ms): {Error}",
95+
_flowName, name, sw.ElapsedMilliseconds, ex.Message);
96+
throw;
97+
}
98+
return this;
99+
}
100+
101+
/// <summary>Record an async step that executes and times it.</summary>
102+
public async Task<FlowLogger> StepAsync(string name, Func<Task> action, string detail = null)
103+
{
104+
var sw = Stopwatch.StartNew();
105+
var step = new FlowStep { Name = name, Detail = detail };
106+
try
107+
{
108+
_logger.LogTrace(" [{FlowName}] {StepName} ...", _flowName, name);
109+
await action();
110+
sw.Stop();
111+
step.Status = FlowStepStatus.Success;
112+
step.ElapsedMs = sw.ElapsedMilliseconds;
113+
AddStep(step);
114+
_logger.LogTrace(" [{FlowName}] {StepName} ... OK ({Elapsed}ms){Detail}",
115+
_flowName, name, sw.ElapsedMilliseconds, detail != null ? $" {detail}" : "");
116+
}
117+
catch (Exception ex)
118+
{
119+
sw.Stop();
120+
step.Status = FlowStepStatus.Failed;
121+
step.ElapsedMs = sw.ElapsedMilliseconds;
122+
step.Detail = ex.Message;
123+
AddStep(step);
124+
_logger.LogTrace(" [{FlowName}] {StepName} ... FAILED ({Elapsed}ms): {Error}",
125+
_flowName, name, sw.ElapsedMilliseconds, ex.Message);
126+
throw;
127+
}
128+
return this;
129+
}
130+
131+
/// <summary>Record a failed step without throwing.</summary>
132+
public FlowLogger Fail(string name, string reason = null)
133+
{
134+
var step = new FlowStep { Name = name, Status = FlowStepStatus.Failed, Detail = reason };
135+
AddStep(step);
136+
_logger.LogTrace(" [{FlowName}] {StepName} ... FAILED{Reason}",
137+
_flowName, name, reason != null ? $": {reason}" : "");
138+
return this;
139+
}
140+
141+
/// <summary>Record a skipped step.</summary>
142+
public FlowLogger Skip(string name, string reason = null)
143+
{
144+
var step = new FlowStep { Name = name, Status = FlowStepStatus.Skipped, Detail = reason };
145+
AddStep(step);
146+
_logger.LogTrace(" [{FlowName}] {StepName} ... SKIPPED{Reason}",
147+
_flowName, name, reason != null ? $": {reason}" : "");
148+
return this;
149+
}
150+
151+
/// <summary>Start a branch (group of child steps).</summary>
152+
public FlowLogger Branch(string name)
153+
{
154+
var step = new FlowStep { Name = name, Status = FlowStepStatus.InProgress };
155+
AddStep(step);
156+
_currentParent = step;
157+
_logger.LogTrace(" [{FlowName}] >> Branch: {BranchName}", _flowName, name);
158+
return this;
159+
}
160+
161+
/// <summary>End the current branch.</summary>
162+
public FlowLogger EndBranch()
163+
{
164+
_currentParent = null;
165+
return this;
166+
}
167+
168+
private void AddStep(FlowStep step)
169+
{
170+
if (_currentParent != null)
171+
_currentParent.Children.Add(step);
172+
else
173+
_steps.Add(step);
174+
}
175+
176+
/// <summary>Render the visual flow diagram to Trace log.</summary>
177+
private string RenderFlow()
178+
{
179+
var sb = new StringBuilder();
180+
sb.AppendLine();
181+
sb.AppendLine($" ===== FLOW: {_flowName} ({_totalTimer.ElapsedMilliseconds}ms total) =====");
182+
sb.AppendLine();
183+
184+
for (var i = 0; i < _steps.Count; i++)
185+
{
186+
var step = _steps[i];
187+
var icon = GetStatusIcon(step.Status);
188+
var elapsed = step.ElapsedMs > 0 ? $" ({step.ElapsedMs}ms)" : "";
189+
var detail = !string.IsNullOrEmpty(step.Detail) ? $" [{step.Detail}]" : "";
190+
191+
sb.AppendLine($" {icon} {step.Name}{elapsed}{detail}");
192+
193+
// Render children (branch)
194+
if (step.Children.Count > 0)
195+
{
196+
for (var j = 0; j < step.Children.Count; j++)
197+
{
198+
var child = step.Children[j];
199+
var childIcon = GetStatusIcon(child.Status);
200+
var childElapsed = child.ElapsedMs > 0 ? $" ({child.ElapsedMs}ms)" : "";
201+
var childDetail = !string.IsNullOrEmpty(child.Detail) ? $" [{child.Detail}]" : "";
202+
sb.AppendLine($" |");
203+
sb.AppendLine($" +-- {childIcon} {child.Name}{childElapsed}{childDetail}");
204+
}
205+
}
206+
207+
// Connector between top-level steps
208+
if (i < _steps.Count - 1)
209+
{
210+
sb.AppendLine(" |");
211+
sb.AppendLine(" v");
212+
}
213+
}
214+
215+
sb.AppendLine();
216+
217+
// Final status line
218+
var finalStatus = _steps.Count > 0 && _steps.Last().Status == FlowStepStatus.Failed
219+
? "FAILED" : _steps.Any(s => s.Status == FlowStepStatus.Failed) ? "PARTIAL FAILURE" : "SUCCESS";
220+
sb.AppendLine($" ===== FLOW RESULT: {finalStatus} =====");
221+
222+
return sb.ToString();
223+
}
224+
225+
private static string GetStatusIcon(FlowStepStatus status)
226+
{
227+
return status switch
228+
{
229+
FlowStepStatus.Success => "[OK]",
230+
FlowStepStatus.Failed => "[FAIL]",
231+
FlowStepStatus.Skipped => "[SKIP]",
232+
FlowStepStatus.InProgress => "[...]",
233+
_ => "[?]"
234+
};
235+
}
236+
237+
public void Dispose()
238+
{
239+
if (_disposed) return;
240+
_disposed = true;
241+
_totalTimer.Stop();
242+
_logger.LogTrace(RenderFlow());
243+
}
244+
}

0 commit comments

Comments
 (0)