Skip to content

Commit 140376a

Browse files
committed
chore(logging): verbose Debug/Trace across the sync flow
Info-level sync logs were too sparse to debug gateway-side behavior. Add: - Per-record Trace in Synchronize: listed vs mapped status, order date, whether a body was present in the listing. - DCV-gate decision Trace per pending order (decision, age, attempted-so-far, cap). - Body-refetch Debug: before the refetch and the resulting cert byte count. - MethodEntry/MethodExit bumped from Trace to Debug across the plugin (Keyfactor logger helpers), and added to EnrollNewAsync and TryRunDcvDuringSyncAsync. 172 unit tests pass; builds clean against IAnyCAPlugin 3.2.0.
1 parent 68c33e4 commit 140376a

1 file changed

Lines changed: 42 additions & 18 deletions

File tree

CERTInext/CERTInextCAPlugin.cs

Lines changed: 42 additions & 18 deletions
Original file line numberDiff line numberDiff line change
@@ -221,7 +221,7 @@ public void Dispose()
221221
/// </summary>
222222
public void Initialize(IAnyCAPluginConfigProvider configProvider, ICertificateDataReader certificateDataReader)
223223
{
224-
_logger.MethodEntry(LogLevel.Trace);
224+
_logger.MethodEntry(LogLevel.Debug);
225225

226226
_certificateDataReader = certificateDataReader;
227227

@@ -271,7 +271,7 @@ public void Initialize(IAnyCAPluginConfigProvider configProvider, ICertificateDa
271271
"gateway image that supplies the factory, or set DcvEnabled=false to clear " +
272272
"this warning.");
273273
}
274-
_logger.MethodExit(LogLevel.Trace);
274+
_logger.MethodExit(LogLevel.Debug);
275275
}
276276

277277
// ---------------------------------------------------------------------------
@@ -319,12 +319,12 @@ public List<string> GetProductIds()
319319
/// <inheritdoc/>
320320
public async Task Ping()
321321
{
322-
_logger.MethodEntry(LogLevel.Trace);
322+
_logger.MethodEntry(LogLevel.Debug);
323323

324324
if (!_config.Enabled)
325325
{
326326
_logger.LogWarning("CERTInext connector is disabled — skipping connectivity test.");
327-
_logger.MethodExit(LogLevel.Trace);
327+
_logger.MethodExit(LogLevel.Debug);
328328
return;
329329
}
330330

@@ -342,14 +342,14 @@ public async Task Ping()
342342
}
343343
finally
344344
{
345-
_logger.MethodExit(LogLevel.Trace);
345+
_logger.MethodExit(LogLevel.Debug);
346346
}
347347
}
348348

349349
/// <inheritdoc/>
350350
public async Task ValidateCAConnectionInfo(Dictionary<string, object> connectionInfo)
351351
{
352-
_logger.MethodEntry(LogLevel.Trace);
352+
_logger.MethodEntry(LogLevel.Debug);
353353

354354
// SOX CC6.1 / SOC2 CC6.1: log the access attempt so that every configuration
355355
// change event is traceable in the audit trail.
@@ -367,7 +367,7 @@ public async Task ValidateCAConnectionInfo(Dictionary<string, object> connection
367367
_logger.LogWarning(
368368
"CA connection validation skipped — connector is disabled. ApiUrl={ApiUrl}",
369369
attemptedApiUrl);
370-
_logger.MethodExit(LogLevel.Trace);
370+
_logger.MethodExit(LogLevel.Debug);
371371
return;
372372
}
373373

@@ -469,13 +469,13 @@ public async Task ValidateCAConnectionInfo(Dictionary<string, object> connection
469469
_logger.LogInformation(
470470
"CA connection validation succeeded. ApiUrl={ApiUrl}, AuthMode={AuthMode}",
471471
attemptedApiUrl, attemptedAuthMode);
472-
_logger.MethodExit(LogLevel.Trace);
472+
_logger.MethodExit(LogLevel.Debug);
473473
}
474474

475475
/// <inheritdoc/>
476476
public async Task ValidateProductInfo(EnrollmentProductInfo productInfo, Dictionary<string, object> connectionInfo)
477477
{
478-
_logger.MethodEntry(LogLevel.Trace);
478+
_logger.MethodEntry(LogLevel.Debug);
479479

480480
string rawConfig = JsonSerializer.Serialize(connectionInfo);
481481
var tempConfig = JsonSerializer.Deserialize<CERTInextConfig>(rawConfig);
@@ -544,7 +544,7 @@ public async Task ValidateProductInfo(EnrollmentProductInfo productInfo, Diction
544544
}
545545

546546
_logger.LogInformation("Product/profile validation succeeded. ProfileId={ProfileId}", profileId);
547-
_logger.MethodExit(LogLevel.Trace);
547+
_logger.MethodExit(LogLevel.Debug);
548548
}
549549

550550
// ---------------------------------------------------------------------------
@@ -560,7 +560,7 @@ public async Task<EnrollmentResult> Enroll(
560560
RequestFormat requestFormat,
561561
EnrollmentType enrollmentType)
562562
{
563-
_logger.MethodEntry(LogLevel.Trace);
563+
_logger.MethodEntry(LogLevel.Debug);
564564

565565
var ep = new EnrollmentParams(productInfo);
566566

@@ -618,7 +618,7 @@ public async Task<EnrollmentResult> Enroll(
618618
enrollmentType, result.CARequestID, result.Status,
619619
result.Certificate != null ? ExtractSerialFromPem(result.Certificate) : "(pending)",
620620
subject, ep.ProfileId);
621-
_logger.MethodExit(LogLevel.Trace);
621+
_logger.MethodExit(LogLevel.Debug);
622622
return result;
623623
}
624624

@@ -629,7 +629,7 @@ public async Task<EnrollmentResult> Enroll(
629629
/// <inheritdoc/>
630630
public async Task<AnyCAPluginCertificate> GetSingleRecord(string caRequestID)
631631
{
632-
_logger.MethodEntry(LogLevel.Trace);
632+
_logger.MethodEntry(LogLevel.Debug);
633633
_logger.LogInformation("GetSingleRecord started. CARequestID={Id}", caRequestID);
634634

635635
try
@@ -666,7 +666,7 @@ public async Task<AnyCAPluginCertificate> GetSingleRecord(string caRequestID)
666666
_logger.LogInformation(
667667
"GetSingleRecord complete. CARequestID={Id}, Status={Status}, SerialNumber={Serial}",
668668
caRequestID, cert.Status, cert.SerialNumber ?? "(none)");
669-
_logger.MethodExit(LogLevel.Trace);
669+
_logger.MethodExit(LogLevel.Debug);
670670
return record;
671671
}
672672
catch (KeyNotFoundException)
@@ -688,7 +688,7 @@ public async Task<AnyCAPluginCertificate> GetSingleRecord(string caRequestID)
688688
/// <inheritdoc/>
689689
public async Task<int> Revoke(string caRequestID, string hexSerialNumber, uint revocationReason)
690690
{
691-
_logger.MethodEntry(LogLevel.Trace);
691+
_logger.MethodEntry(LogLevel.Debug);
692692

693693
string reasonString = StatusMapper.ToRevocationReason(revocationReason);
694694

@@ -758,7 +758,7 @@ public async Task<int> Revoke(string caRequestID, string hexSerialNumber, uint r
758758
"ReasonCode={ReasonCode}, ReasonString={ReasonString}",
759759
caRequestID, hexSerialNumber, current.Subject,
760760
revocationReason, reasonString);
761-
_logger.MethodExit(LogLevel.Trace);
761+
_logger.MethodExit(LogLevel.Debug);
762762
return (int)EndEntityStatus.REVOKED;
763763
}
764764

@@ -773,7 +773,7 @@ public async Task Synchronize(
773773
bool fullSync,
774774
CancellationToken cancelToken)
775775
{
776-
_logger.MethodEntry(LogLevel.Trace);
776+
_logger.MethodEntry(LogLevel.Debug);
777777

778778
DateTime? issuedAfter = fullSync ? (DateTime?)null : lastSync;
779779

@@ -819,6 +819,15 @@ public async Task Synchronize(
819819

820820
int status = StatusMapper.ToRequestDisposition(current.Status);
821821

822+
// Per-record trace so a sync pass is fully reconstructable from logs
823+
// (info-level only emits start/summary). Enable Trace on this category.
824+
_logger.LogTrace(
825+
"Sync: processing order Id={Id}, listedStatus='{Listed}', mappedStatus={Status}, " +
826+
"orderDate={OrderDate}, bodyInListing={HasBody}",
827+
current.Id, current.Status, status,
828+
current.OrderDate?.ToString("o") ?? "(none)",
829+
!string.IsNullOrWhiteSpace(current.Certificate));
830+
822831
// Deferred DCV: pending orders (EXTERNALVALIDATION) often need DCV driven
823832
// forward during sync — CERTInext parks fresh orders and exposes the DCV
824833
// challenge minutes after enrollment, and scans are the only place that gets
@@ -834,6 +843,12 @@ public async Task Synchronize(
834843
var decision = EvaluateDcvSyncEligibility(
835844
current.OrderDate, DateTime.UtcNow, ageWindowHours, dcvAttempted, perPassCap);
836845

846+
_logger.LogTrace(
847+
"Sync DCV gate: Id={Id}, decision={Decision}, orderDate={OrderDate}, " +
848+
"ageWindowHours={Age}, attemptedSoFar={Attempted}, perPassCap={Cap}",
849+
current.Id, decision, current.OrderDate?.ToString("o") ?? "(none)",
850+
ageWindowHours, dcvAttempted, perPassCap);
851+
837852
if (decision == DcvSyncDecision.SkipByAge)
838853
{
839854
dcvSkippedAge++;
@@ -885,10 +900,16 @@ public async Task Synchronize(
885900
&& (status == (int)EndEntityStatus.GENERATED
886901
|| status == (int)EndEntityStatus.REVOKED))
887902
{
903+
_logger.LogDebug(
904+
"Sync: issued/revoked order Id={Id} has no body in the listing — refetching full certificate.",
905+
current.Id);
888906
try
889907
{
890908
current = await _client.GetCertificateAsync(current.Id, cancelToken);
891909
status = StatusMapper.ToRequestDisposition(current.Status);
910+
_logger.LogDebug(
911+
"Sync: refetched order Id={Id} — status={Status}, certBytes={Bytes}.",
912+
current.Id, status, current.Certificate?.Length ?? 0);
892913
}
893914
catch (Exception fetchEx)
894915
{
@@ -982,7 +1003,7 @@ public async Task Synchronize(
9821003
blockingBuffer.CompleteAdding();
9831004
}
9841005

985-
_logger.MethodExit(LogLevel.Trace);
1006+
_logger.MethodExit(LogLevel.Debug);
9861007
}
9871008

9881009
// ---------------------------------------------------------------------------
@@ -1031,6 +1052,7 @@ private async Task<EnrollmentResult> EnrollNewAsync(
10311052
Dictionary<string, string[]> san,
10321053
EnrollmentParams ep)
10331054
{
1055+
_logger.MethodEntry(LogLevel.Debug);
10341056
var enrollReq = new EnrollCertificateRequest
10351057
{
10361058
ProfileId = ep.ProfileId,
@@ -1111,6 +1133,7 @@ private async Task<EnrollmentResult> EnrollNewAsync(
11111133
}
11121134
#endif
11131135

1136+
_logger.MethodExit(LogLevel.Debug);
11141137
return BuildEnrollmentResult(enrollResp, ep.AutoApprove);
11151138
}
11161139

@@ -1309,6 +1332,7 @@ private static bool IsDcvNotYetReady(Exception ex)
13091332
/// </summary>
13101333
private async Task<bool> TryRunDcvDuringSyncAsync(string orderNumber, CancellationToken ct, bool fastSync = false)
13111334
{
1335+
_logger.MethodEntry(LogLevel.Debug);
13121336
#if SUPPORTS_DCV
13131337
if (_domainValidatorFactory == null || !_config.DcvEnabled || string.IsNullOrEmpty(orderNumber))
13141338
return false;

0 commit comments

Comments
 (0)