diff --git a/CHANGELOG.md b/CHANGELOG.md index 8742947..82140ec 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -1,3 +1,15 @@ +# v1.0.2 +* Fixed revocation status handling - failed revocations no longer incorrectly set certificate status to FAILED; certificate retains its current active status +* Added FlowLogger utility for structured flow diagrams across all public plugin methods +* Added guard clauses and input validation (null checks, UUID length validation before Substring) +* Added null response guards after all API calls +* Added null-safe structured logging throughout plugin, RequestManager, and HydrantIdClient +* Added AggregateException flattening in catch blocks for better error reporting +* Added per-certificate error isolation in Synchronize to prevent one bad cert from aborting sync +* Added BlockingCollection.IsAddingCompleted guard before CompleteAdding() +* Improved error handling in HydrantIdClient - non-success HTTP responses now throw with status details +* Added .NET 10 target framework support + # v1.0.1 * SaaS Containerization Fixes, added enabled flag cleaned up some log messages diff --git a/HydrantCAProxy/Client/HydrantIdClient.cs b/HydrantCAProxy/Client/HydrantIdClient.cs index ae3d539..3b5a77b 100644 --- a/HydrantCAProxy/Client/HydrantIdClient.cs +++ b/HydrantCAProxy/Client/HydrantIdClient.cs @@ -1,12 +1,12 @@ -// 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 -// thespecific language governing permissions and limitations under the -// License. +// 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 +// thespecific language governing permissions and limitations under the +// License. using System; using System.Collections.Concurrent; using System.Collections.Generic; @@ -34,24 +34,43 @@ namespace Keyfactor.HydrantId.Client { public sealed class HydrantIdClient { - private static readonly ILogger Log = LogHandler.GetClassLogger < HydrantIdClient>(); + private static readonly ILogger Log = LogHandler.GetClassLogger(); public HydrantIdClient(IAnyCAPluginConfigProvider config) { try { Log.MethodEntry(); - + + if (config == null) + throw new ArgumentNullException(nameof(config), "config cannot be null."); + if (config.CAConnectionData == null) + throw new ArgumentNullException(nameof(config), "CAConnectionData cannot be null."); + if (config.CAConnectionData.ContainsKey(HydrantIdCAPluginConfig.ConfigConstants.HydrantIdAuthId)) { ConfigProvider = config; - BaseUrl = ConfigProvider.CAConnectionData[HydrantIdCAPluginConfig.ConfigConstants.HydrantIdBaseUrl].ToString(); + var baseUrlObj = ConfigProvider.CAConnectionData[HydrantIdCAPluginConfig.ConfigConstants.HydrantIdBaseUrl]; + BaseUrl = baseUrlObj?.ToString(); + + if (string.IsNullOrEmpty(BaseUrl)) + { + Log.LogError("HydrantIdClient: BaseUrl is null or empty after reading config."); + throw new InvalidOperationException("HydrantIdBaseUrl is null or empty in CAConnectionData."); + } + + Log.LogTrace("HydrantIdClient: BaseUrl='{BaseUrl}'", BaseUrl); RequestManager = new RequestManager(); } + else + { + Log.LogError("HydrantIdClient: HydrantIdAuthId key not found in CAConnectionData."); + throw new InvalidOperationException("HydrantIdAuthId not found in CAConnectionData."); + } } catch (Exception e) { - Log.LogError($"Error Occured in HydrantIdClient.HydrantIdClient: {e.Message}"); + Log.LogError(e, "Error occurred in HydrantIdClient constructor: {Message}", e.Message); throw; } } @@ -66,66 +85,111 @@ public HydrantIdClient(IAnyCAPluginConfigProvider config) public async Task GetSubmitEnrollmentAsync(CertRequestBody registerRequest) { Log.MethodEntry(); + Log.LogTrace("GetSubmitEnrollmentAsync: registerRequest is {Null}", registerRequest == null ? "NULL" : "present"); + + if (registerRequest == null) + throw new ArgumentNullException(nameof(registerRequest), "registerRequest cannot be null."); + var apiEndpoint = "/api/v2/csr"; - var restClient = ConfigureRestClient("post", BaseUrl + apiEndpoint); - Log.LogTrace($"API Url {BaseUrl + apiEndpoint}"); + var fullUrl = BaseUrl + apiEndpoint; + Log.LogTrace("GetSubmitEnrollmentAsync: API Url={Url}", fullUrl); var json = JsonConvert.SerializeObject(registerRequest); - Log.LogTrace($"Register Request JSON: {json}"); + Log.LogTrace("GetSubmitEnrollmentAsync: request JSON: {Json}", json); - var traceWriter = new MemoryTraceWriter(); - var settings = new JsonSerializerSettings + var settings = new JsonSerializerSettings { NullValueHandling = NullValueHandling.Ignore }; + + try { - NullValueHandling = NullValueHandling.Ignore, - TraceWriter = traceWriter - }; + var restClient = ConfigureRestClient("post", fullUrl); + using var resp = await restClient.PostAsync(apiEndpoint, new StringContent(json, Encoding.UTF8, "application/json")); + var responseContent = await resp.Content.ReadAsStringAsync(); - using var resp = await restClient.PostAsync(apiEndpoint, new StringContent(json, Encoding.UTF8, "application/json")); - var responseContent = await resp.Content.ReadAsStringAsync(); + Log.LogTrace("GetSubmitEnrollmentAsync: HTTP status={StatusCode}, response length={Len}", + resp.StatusCode, responseContent?.Length ?? 0); - if (resp.StatusCode == HttpStatusCode.InternalServerError) + if (resp.StatusCode == HttpStatusCode.InternalServerError) + { + var errorResponse = JsonConvert.DeserializeObject(responseContent, settings); + Log.LogError("GetSubmitEnrollmentAsync: server error response: {Json}", JsonConvert.SerializeObject(errorResponse)); + return new CertRequestResult { ErrorReturn = errorResponse }; + } + + if (!resp.IsSuccessStatusCode) + { + Log.LogError("GetSubmitEnrollmentAsync: unexpected status {StatusCode}: {Response}", resp.StatusCode, responseContent); + return new CertRequestResult + { + ErrorReturn = new ErrorReturn { Status = "Failure", Error = $"HTTP {resp.StatusCode}: {responseContent}" } + }; + } + + var validResponse = JsonConvert.DeserializeObject(responseContent, settings); + Log.LogTrace("GetSubmitEnrollmentAsync: valid response JSON: {Json}", JsonConvert.SerializeObject(validResponse)); + return new CertRequestResult { RequestStatus = validResponse }; + } + catch (Exception e) { - var errorResponse = JsonConvert.DeserializeObject(responseContent, settings); - Log.LogError($"Error Response JSON: {JsonConvert.SerializeObject(errorResponse)}"); - return new CertRequestResult { ErrorReturn = errorResponse }; + Log.LogError(e, "GetSubmitEnrollmentAsync: exception: {Message}", e.Message); + throw; } - - var validResponse = JsonConvert.DeserializeObject(responseContent, settings); - Log.LogTrace($"Valid Response JSON: {JsonConvert.SerializeObject(validResponse)}"); - return new CertRequestResult { RequestStatus = validResponse }; } public async Task GetSubmitRenewalAsync(string certificateId, RenewalRequest renewRequest) { Log.MethodEntry(); + Log.LogTrace("GetSubmitRenewalAsync: certificateId='{CertId}', renewRequest is {Null}", + certificateId ?? "(null)", renewRequest == null ? "NULL" : "present"); + + if (string.IsNullOrEmpty(certificateId)) + throw new ArgumentNullException(nameof(certificateId), "certificateId cannot be null or empty."); + if (renewRequest == null) + throw new ArgumentNullException(nameof(renewRequest), "renewRequest cannot be null."); + var apiEndpoint = $"/api/v2/certificates/{certificateId}/renew"; - var restClient = ConfigureRestClient("post", BaseUrl + apiEndpoint); - Log.LogTrace($"API Url {BaseUrl + apiEndpoint}"); + var fullUrl = BaseUrl + apiEndpoint; + Log.LogTrace("GetSubmitRenewalAsync: API Url={Url}", fullUrl); var json = JsonConvert.SerializeObject(renewRequest); - Log.LogTrace($"Renew Request JSON: {json}"); + Log.LogTrace("GetSubmitRenewalAsync: request JSON: {Json}", json); - var traceWriter = new MemoryTraceWriter(); - var settings = new JsonSerializerSettings + var settings = new JsonSerializerSettings { NullValueHandling = NullValueHandling.Ignore }; + + try { - NullValueHandling = NullValueHandling.Ignore, - TraceWriter = traceWriter - }; + var restClient = ConfigureRestClient("post", fullUrl); + using var resp = await restClient.PostAsync(apiEndpoint, new StringContent(json, Encoding.UTF8, "application/json")); + var responseContent = await resp.Content.ReadAsStringAsync(); - using var resp = await restClient.PostAsync(apiEndpoint, new StringContent(json, Encoding.UTF8, "application/json")); - var responseContent = await resp.Content.ReadAsStringAsync(); + Log.LogTrace("GetSubmitRenewalAsync: HTTP status={StatusCode}, response length={Len}", + resp.StatusCode, responseContent?.Length ?? 0); - if (resp.StatusCode == HttpStatusCode.InternalServerError) + if (resp.StatusCode == HttpStatusCode.InternalServerError) + { + var errorResponse = JsonConvert.DeserializeObject(responseContent, settings); + Log.LogError("GetSubmitRenewalAsync: server error response: {Json}", JsonConvert.SerializeObject(errorResponse)); + return new CertRequestResult { ErrorReturn = errorResponse }; + } + + if (!resp.IsSuccessStatusCode) + { + Log.LogError("GetSubmitRenewalAsync: unexpected status {StatusCode}: {Response}", resp.StatusCode, responseContent); + return new CertRequestResult + { + ErrorReturn = new ErrorReturn { Status = "Failure", Error = $"HTTP {resp.StatusCode}: {responseContent}" } + }; + } + + var validResponse = JsonConvert.DeserializeObject(responseContent, settings); + Log.LogTrace("GetSubmitRenewalAsync: valid response JSON: {Json}", JsonConvert.SerializeObject(validResponse)); + return new CertRequestResult { RequestStatus = validResponse }; + } + catch (Exception e) { - var errorResponse = JsonConvert.DeserializeObject(responseContent, settings); - Log.LogError($"Error Response JSON: {JsonConvert.SerializeObject(errorResponse)}"); - return new CertRequestResult { ErrorReturn = errorResponse }; + Log.LogError(e, "GetSubmitRenewalAsync: exception: {Message}", e.Message); + throw; } - - var validResponse = JsonConvert.DeserializeObject(responseContent, settings); - Log.LogTrace($"Valid Response JSON: {JsonConvert.SerializeObject(validResponse)}"); - return new CertRequestResult { RequestStatus = validResponse }; } @@ -134,22 +198,42 @@ public async Task> GetPolicyList() { Log.MethodEntry(); var apiEndpoint = "/api/v2/policies"; - var restClient = ConfigureRestClient("get", BaseUrl + apiEndpoint); - Log.LogTrace($"API Url {BaseUrl + apiEndpoint}"); + var fullUrl = BaseUrl + apiEndpoint; + Log.LogTrace("GetPolicyList: API Url={Url}", fullUrl); + + var settings = new JsonSerializerSettings { NullValueHandling = NullValueHandling.Ignore }; - var traceWriter = new MemoryTraceWriter(); - var settings = new JsonSerializerSettings + try { - NullValueHandling = NullValueHandling.Ignore, - TraceWriter = traceWriter - }; + var restClient = ConfigureRestClient("get", fullUrl); + using var resp = await restClient.GetAsync(apiEndpoint); + var responseContent = await resp.Content.ReadAsStringAsync(); - using var resp = await restClient.GetAsync(apiEndpoint); - var responseContent = await resp.Content.ReadAsStringAsync(); - var policies = JsonConvert.DeserializeObject>(responseContent, settings); - Log.LogDebug(traceWriter.ToString()); + Log.LogTrace("GetPolicyList: HTTP status={StatusCode}, response length={Len}", + resp.StatusCode, responseContent?.Length ?? 0); + + if (!resp.IsSuccessStatusCode) + { + Log.LogError("GetPolicyList: request failed with status {StatusCode}: {Response}", resp.StatusCode, responseContent); + throw new HttpRequestException($"GetPolicyList failed with HTTP {resp.StatusCode}: {responseContent}"); + } - return policies; + var policies = JsonConvert.DeserializeObject>(responseContent, settings); + + if (policies == null) + { + Log.LogWarning("GetPolicyList: deserialized policy list is null"); + return new List(); + } + + Log.LogTrace("GetPolicyList: returned {Count} policies", policies.Count); + return policies; + } + catch (Exception e) + { + Log.LogError(e, "GetPolicyList: exception: {Message}", e.Message); + throw; + } } @@ -157,22 +241,37 @@ public async Task> GetPolicyList() public async Task GetSubmitGetCertificateAsync(string certificateId) { Log.MethodEntry(); + Log.LogTrace("GetSubmitGetCertificateAsync: certificateId='{CertId}'", certificateId ?? "(null)"); + + if (string.IsNullOrEmpty(certificateId)) + throw new ArgumentNullException(nameof(certificateId), "certificateId cannot be null or empty."); var apiEndpoint = $"/api/v2/certificates/{certificateId}"; - Log.LogTrace($"API Url: {BaseUrl + apiEndpoint}"); + var fullUrl = BaseUrl + apiEndpoint; + Log.LogTrace("GetSubmitGetCertificateAsync: API Url={Url}", fullUrl); try { - var restClient = ConfigureRestClient("get", BaseUrl + apiEndpoint); + var restClient = ConfigureRestClient("get", fullUrl); using var response = await restClient.GetAsync(apiEndpoint); - response.EnsureSuccessStatusCode(); var content = await response.Content.ReadAsStringAsync(); - return JsonConvert.DeserializeObject(content); + Log.LogTrace("GetSubmitGetCertificateAsync: HTTP status={StatusCode}, response length={Len}", + response.StatusCode, content?.Length ?? 0); + + response.EnsureSuccessStatusCode(); + + var cert = JsonConvert.DeserializeObject(content); + if (cert == null) + { + Log.LogWarning("GetSubmitGetCertificateAsync: deserialized certificate is null for ID='{CertId}'", certificateId); + } + + return cert; } catch (Exception e) { - Log.LogError($"Error in HydrantIdClient.GetSubmitGetCertificateAsync: {e.Message}"); + Log.LogError(e, "GetSubmitGetCertificateAsync: exception for certificateId='{CertId}': {Message}", certificateId, e.Message); throw; } } @@ -180,24 +279,40 @@ public async Task GetSubmitGetCertificateAsync(string certificateId public async Task GetSubmitGetCertificateByCsrAsync(string requestTrackingId) { + Log.MethodEntry(); + Log.LogTrace("GetSubmitGetCertificateByCsrAsync: requestTrackingId='{TrackingId}'", requestTrackingId ?? "(null)"); + + if (string.IsNullOrEmpty(requestTrackingId)) + throw new ArgumentNullException(nameof(requestTrackingId), "requestTrackingId cannot be null or empty."); + try { - Log.MethodEntry(); var apiEndpoint = $"/api/v2/csr/{requestTrackingId}/certificate"; - Log.LogTrace($"API Url {BaseUrl + apiEndpoint}"); - var restClient = ConfigureRestClient("get", BaseUrl + apiEndpoint); + var fullUrl = BaseUrl + apiEndpoint; + Log.LogTrace("GetSubmitGetCertificateByCsrAsync: API Url={Url}", fullUrl); + + var restClient = ConfigureRestClient("get", fullUrl); using (var resp = await restClient.GetAsync(apiEndpoint)) { + var content = await resp.Content.ReadAsStringAsync(); + Log.LogTrace("GetSubmitGetCertificateByCsrAsync: HTTP status={StatusCode}, response length={Len}", + resp.StatusCode, content?.Length ?? 0); + resp.EnsureSuccessStatusCode(); - var getCertificateResponse = - JsonConvert.DeserializeObject(await resp.Content.ReadAsStringAsync()); + + var getCertificateResponse = JsonConvert.DeserializeObject(content); + if (getCertificateResponse == null) + { + Log.LogWarning("GetSubmitGetCertificateByCsrAsync: deserialized response is null for trackingId='{TrackingId}'", requestTrackingId); + } + return getCertificateResponse; } } catch (Exception e) { - Log.LogError($"Error Occured in HydrantIdClient.GetSubmitGetCertificateAsync: {e.Message}"); + Log.LogError(e, "GetSubmitGetCertificateByCsrAsync: exception for trackingId='{TrackingId}': {Message}", requestTrackingId, e.Message); throw; } } @@ -205,15 +320,18 @@ public async Task GetSubmitGetCertificateByCsrAsync(string requestT public async Task GetSubmitRevokeCertificateAsync(string hydrantId, RevocationReasons revokeReason) { Log.MethodEntry(); + Log.LogTrace("GetSubmitRevokeCertificateAsync: hydrantId='{HydrantId}', revokeReason={Reason}", hydrantId ?? "(null)", revokeReason); + + if (string.IsNullOrEmpty(hydrantId)) + throw new ArgumentNullException(nameof(hydrantId), "hydrantId cannot be null or empty."); var apiEndpoint = $"/api/v2/certificates/{hydrantId}"; var fullUrl = BaseUrl + apiEndpoint; - - Log.LogTrace($"API Url: {fullUrl}"); + Log.LogTrace("GetSubmitRevokeCertificateAsync: API Url={Url}", fullUrl); var restClient = ConfigureRestClient("patch", fullUrl); var revokeRequest = RequestManager.GetRevokeRequest(revokeReason); - Log.LogTrace($"Revoke Request JSON: {JsonConvert.SerializeObject(revokeRequest)}"); + Log.LogTrace("GetSubmitRevokeCertificateAsync: request JSON: {Json}", JsonConvert.SerializeObject(revokeRequest)); try { @@ -221,16 +339,26 @@ public async Task GetSubmitRevokeCertificateAsync(string hydr JsonConvert.SerializeObject(revokeRequest), Encoding.UTF8, "application/json")); var json = await response.Content.ReadAsStringAsync(); + Log.LogTrace("GetSubmitRevokeCertificateAsync: HTTP status={StatusCode}, response length={Len}", + response.StatusCode, json?.Length ?? 0); + + if (!response.IsSuccessStatusCode) + { + Log.LogError("GetSubmitRevokeCertificateAsync: revoke failed with status {StatusCode}: {Response}", + response.StatusCode, json); + throw new HttpRequestException($"Revoke API call failed with HTTP {response.StatusCode}: {json}"); + } + var revokeResponse = JsonConvert.DeserializeObject( json, new JsonSerializerSettings { NullValueHandling = NullValueHandling.Ignore }); - Log.LogTrace($"Revoke Response JSON: {JsonConvert.SerializeObject(revokeResponse)}"); + Log.LogTrace("GetSubmitRevokeCertificateAsync: response JSON: {Json}", JsonConvert.SerializeObject(revokeResponse)); return revokeResponse; } catch (Exception e) { - Log.LogError($"Error in HydrantIdClient.GetSubmitRevokeCertificateAsync: {e.Message}"); + Log.LogError(e, "GetSubmitRevokeCertificateAsync: exception for hydrantId='{HydrantId}': {Message}", hydrantId, e.Message); throw; } } @@ -240,6 +368,8 @@ public async Task GetSubmitCertificateListRequestAsync(BlockingCollection 5) throw new RetryCountExceededException( - $"5 consecutive failures to {resp.RequestMessage.RequestUri}"); + $"5 consecutive failures to {resp.RequestMessage?.RequestUri}"); continue; } + retryCount = 0; var stringResponse = await resp.Content.ReadAsStringAsync(); - var batchResponse = - JsonConvert.DeserializeObject(stringResponse); + var batchResponse = JsonConvert.DeserializeObject(stringResponse); - Log.LogTrace($"batchResponse JSON: {JsonConvert.SerializeObject(batchResponse)}"); + Log.LogTrace("GetSubmitCertificateListRequestAsync: batchResponse is {Null}", + batchResponse == null ? "NULL" : "present"); - if (batchResponse != null) + if (batchResponse?.Items != null) { var batchCount = batchResponse.Items.Count; + Log.LogTrace("GetSubmitCertificateListRequestAsync: processing {Count} items in batch", batchCount); - Log.LogTrace($"Processing {batchCount} items in batch"); do { var r = batchResponse.Items[batchItemsProcessed]; + if (r == null) + { + Log.LogTrace("GetSubmitCertificateListRequestAsync: skipping null item at index {Index}", batchItemsProcessed); + batchItemsProcessed++; + continue; + } + if (bc.TryAdd(r, 10, ct)) { - Log.LogTrace($"Added Template ID {r.Id} to Queue for processing"); + Log.LogTrace("GetSubmitCertificateListRequestAsync: added ID={Id} to queue (batch {BatchIdx}/{BatchCount}, total={Total})", + r.Id ?? "(null)", batchItemsProcessed + 1, batchCount, itemsProcessed + 1); batchItemsProcessed++; itemsProcessed++; - Log.LogTrace($"Processed {batchItemsProcessed} of {batchCount}"); - Log.LogTrace($"Total Items Processed: {itemsProcessed}"); } else { - Log.LogTrace($"Adding {r} blocked. Retry"); + Log.LogTrace("GetSubmitCertificateListRequestAsync: adding ID={Id} blocked, retrying", r.Id ?? "(null)"); } - } while (batchItemsProcessed < batchCount); //batch loop + } while (batchItemsProcessed < batchCount); + } + else + { + Log.LogWarning("GetSubmitCertificateListRequestAsync: batchResponse or Items is null at pageCounter={PageCounter}", pageCounter); } } - //assume that if we process less records than requested that we have reached the end of the certificate list if (batchItemsProcessed < PageSize) isComplete = true; pageCounter = pageCounter + PageSize; - } while (!isComplete); //page loop + } while (!isComplete); + + Log.LogTrace("GetSubmitCertificateListRequestAsync: completed. Total items processed={Total}", itemsProcessed); - bc.CompleteAdding(); + if (!bc.IsAddingCompleted) + bc.CompleteAdding(); } catch (OperationCanceledException cancelEx) { - Log.LogWarning($"Synchronize method was cancelled. Message: {cancelEx.Message}"); - bc.CompleteAdding(); - Log.MethodExit(); - // ReSharper disable once PossibleIntendedRethrow + Log.LogWarning("GetSubmitCertificateListRequestAsync: cancelled. Message={Message}", cancelEx.Message); + if (!bc.IsAddingCompleted) + bc.CompleteAdding(); throw; } catch (RetryCountExceededException retryEx) { - Log.LogError($"Retries Failed: {retryEx.Message}"); - Log.MethodExit(); - bc.CompleteAdding(); + Log.LogError(retryEx, "GetSubmitCertificateListRequestAsync: retries exceeded: {Message}", retryEx.Message); + if (!bc.IsAddingCompleted) + bc.CompleteAdding(); throw; } catch (HttpRequestException ex) { - Log.LogError($"HttpRequest Failed: {ex.Message}"); - Log.MethodExit(); - bc.CompleteAdding(); + Log.LogError(ex, "GetSubmitCertificateListRequestAsync: HTTP request failed: {Message}", ex.Message); + if (!bc.IsAddingCompleted) + bc.CompleteAdding(); + throw; + } + catch (Exception ex) + { + Log.LogError(ex, "GetSubmitCertificateListRequestAsync: unhandled exception: {Message}", ex.Message); + if (!bc.IsAddingCompleted) + bc.CompleteAdding(); throw; } @@ -342,9 +493,9 @@ public async Task Ping() { Log.MethodEntry(); - var apiEndpoint = "/api/v2/policies"; // Lightweight, safe endpoint + var apiEndpoint = "/api/v2/policies"; var fullUrl = BaseUrl + apiEndpoint; - Log.LogTrace($"Ping API Url: {fullUrl}"); + Log.LogTrace("Ping: API Url={Url}", fullUrl); try { @@ -352,41 +503,61 @@ public async Task Ping() using var response = await restClient.GetAsync(apiEndpoint); var content = await response.Content.ReadAsStringAsync(); + Log.LogTrace("Ping: HTTP status={StatusCode}, response length={Len}", response.StatusCode, content?.Length ?? 0); + if (!response.IsSuccessStatusCode) { - Log.LogError($"Ping failed. Status: {response.StatusCode}, Response: {content}"); + Log.LogError("Ping: failed. Status={StatusCode}, Response={Response}", response.StatusCode, content); return false; } - Log.LogTrace("Ping successful."); + Log.LogTrace("Ping: successful."); return true; } catch (Exception e) { - Log.LogError($"Error in HydrantIdClient.Ping: {e.Message}"); + Log.LogError(e, "Ping: exception: {Message}", e.Message); return false; } } - // ReSharper disable once InconsistentNaming private HttpClient ConfigureRestClient(string method, string url) { try { Log.MethodEntry(); + Log.LogTrace("ConfigureRestClient: method='{Method}', url='{Url}'", method ?? "(null)", url ?? "(null)"); + + if (string.IsNullOrEmpty(method)) + throw new ArgumentNullException(nameof(method), "HTTP method cannot be null or empty."); + if (string.IsNullOrEmpty(url)) + throw new ArgumentNullException(nameof(url), "URL cannot be null or empty."); + var bUrl = new Uri(BaseUrl); - ApiId = ConfigProvider.CAConnectionData[HydrantIdCAPluginConfig.ConfigConstants.HydrantIdAuthId].ToString(); + ApiId = ConfigProvider.CAConnectionData[HydrantIdCAPluginConfig.ConfigConstants.HydrantIdAuthId]?.ToString(); + + if (string.IsNullOrEmpty(ApiId)) + { + Log.LogError("ConfigureRestClient: ApiId is null or empty after reading from config."); + throw new InvalidOperationException("HydrantIdAuthId is null or empty in CAConnectionData."); + } + + var authKey = ConfigProvider.CAConnectionData[HydrantIdCAPluginConfig.ConfigConstants.HydrantIdAuthKey]?.ToString(); + if (string.IsNullOrEmpty(authKey)) + { + Log.LogError("ConfigureRestClient: AuthKey is null or empty after reading from config."); + throw new InvalidOperationException("HydrantIdAuthKey is null or empty in CAConnectionData."); + } var credentials = new HawkCredential { - Id = ConfigProvider.CAConnectionData[HydrantIdCAPluginConfig.ConfigConstants.HydrantIdAuthId].ToString(), - Key = ConfigProvider.CAConnectionData[HydrantIdCAPluginConfig.ConfigConstants.HydrantIdAuthKey].ToString(), + Id = ApiId, + Key = authKey, Algorithm = "sha256" }; var byteArray = new byte[20]; - //Generate a cryptographically random set of bytes using (var rnd = RandomNumberGenerator.Create()) { rnd.GetBytes(byteArray); @@ -400,8 +571,7 @@ private HttpClient ConfigureRestClient(string method, string url) var authorization = $"id=\"{ApiId}\", ts=\"{ts}\", nonce=\"{nOnce}\", mac=\"{mac}\""; - - var clientHandler = new HttpClientHandler(); // Replaces WebRequestHandler in .NET 6 + var clientHandler = new HttpClientHandler(); var returnClient = new HttpClient(clientHandler, disposeHandler: true) { @@ -411,11 +581,12 @@ private HttpClient ConfigureRestClient(string method, string url) returnClient.DefaultRequestHeaders.Accept.Add(new MediaTypeWithQualityHeaderValue("application/json")); returnClient.DefaultRequestHeaders.Add("Authorization", "Hawk " + authorization); + Log.LogTrace("ConfigureRestClient: configured client for {Method} {Url}", method, url); return returnClient; } catch (Exception e) { - Log.LogError($"Error Occured in HydrantIdClient.ConfigureRestClient: {e.Message}"); + Log.LogError(e, "ConfigureRestClient: exception: {Message}", e.Message); throw; } } @@ -432,4 +603,4 @@ private static byte[] ConvertHexStringToBytes(string hex) } } -} \ No newline at end of file +} diff --git a/HydrantCAProxy/FlowLogger.cs b/HydrantCAProxy/FlowLogger.cs new file mode 100644 index 0000000..d1b0ce4 --- /dev/null +++ b/HydrantCAProxy/FlowLogger.cs @@ -0,0 +1,145 @@ +// 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.Threading.Tasks; +using Microsoft.Extensions.Logging; + +namespace Keyfactor.HydrantId +{ + public sealed class FlowLogger : IDisposable + { + private readonly ILogger _logger; + private readonly string _flowName; + private readonly List _steps = new List(); + private readonly Stopwatch _stopwatch; + + public FlowLogger(ILogger logger, string flowName) + { + _logger = logger ?? throw new ArgumentNullException(nameof(logger)); + _flowName = flowName ?? "Unknown"; + _stopwatch = Stopwatch.StartNew(); + _logger.LogTrace("===== FLOW START: {FlowName} =====", _flowName); + } + + public void Step(string name, string detail = null) + { + _steps.Add(new FlowStep(name, FlowStepStatus.Ok, detail)); + _logger.LogTrace("[FLOW] {FlowName} -> {StepName}: {Detail}", _flowName, name, detail ?? "OK"); + } + + public void Step(string name, Action action) + { + var sw = Stopwatch.StartNew(); + try + { + action(); + sw.Stop(); + _steps.Add(new FlowStep(name, FlowStepStatus.Ok, $"{sw.ElapsedMilliseconds}ms")); + _logger.LogTrace("[FLOW] {FlowName} -> {StepName}: OK ({Elapsed}ms)", _flowName, name, sw.ElapsedMilliseconds); + } + catch (Exception ex) + { + sw.Stop(); + _steps.Add(new FlowStep(name, FlowStepStatus.Failed, ex.Message)); + _logger.LogTrace("[FLOW] {FlowName} -> {StepName}: FAILED - {Error}", _flowName, name, ex.Message); + throw; + } + } + + public async Task StepAsync(string name, Func action) + { + var sw = Stopwatch.StartNew(); + try + { + await action(); + sw.Stop(); + _steps.Add(new FlowStep(name, FlowStepStatus.Ok, $"{sw.ElapsedMilliseconds}ms")); + _logger.LogTrace("[FLOW] {FlowName} -> {StepName}: OK ({Elapsed}ms)", _flowName, name, sw.ElapsedMilliseconds); + } + catch (Exception ex) + { + sw.Stop(); + _steps.Add(new FlowStep(name, FlowStepStatus.Failed, ex.Message)); + _logger.LogTrace("[FLOW] {FlowName} -> {StepName}: FAILED - {Error}", _flowName, name, ex.Message); + throw; + } + } + + public void Fail(string name, string reason) + { + _steps.Add(new FlowStep(name, FlowStepStatus.Failed, reason)); + _logger.LogTrace("[FLOW] {FlowName} -> {StepName}: FAILED - {Reason}", _flowName, name, reason); + } + + public void Skip(string name, string reason) + { + _steps.Add(new FlowStep(name, FlowStepStatus.Skipped, reason)); + _logger.LogTrace("[FLOW] {FlowName} -> {StepName}: SKIPPED - {Reason}", _flowName, name, reason); + } + + public void Dispose() + { + _stopwatch.Stop(); + var hasFailure = false; + + _logger.LogTrace("===== FLOW DIAGRAM: {FlowName} =====", _flowName); + foreach (var step in _steps) + { + string icon; + switch (step.Status) + { + case FlowStepStatus.Ok: + icon = "[OK]"; + break; + case FlowStepStatus.Failed: + icon = "[FAIL]"; + hasFailure = true; + break; + case FlowStepStatus.Skipped: + icon = "[SKIP]"; + break; + default: + icon = "[...]"; + break; + } + + var detail = string.IsNullOrEmpty(step.Detail) ? "" : $" ({step.Detail})"; + _logger.LogTrace(" | {Icon} {StepName}{Detail}", icon, step.Name, detail); + _logger.LogTrace(" v"); + } + + var result = hasFailure ? "PARTIAL FAILURE" : "SUCCESS"; + _logger.LogTrace("===== FLOW RESULT: {Result} ({Elapsed}ms) =====", result, _stopwatch.ElapsedMilliseconds); + } + + private enum FlowStepStatus + { + Ok, + Failed, + Skipped + } + + private class FlowStep + { + public string Name { get; } + public FlowStepStatus Status { get; } + public string Detail { get; } + + public FlowStep(string name, FlowStepStatus status, string detail) + { + Name = name; + Status = status; + Detail = detail; + } + } + } +} diff --git a/HydrantCAProxy/HydrantIdCAPlugin.cs b/HydrantCAProxy/HydrantIdCAPlugin.cs index ad510da..a89c54c 100644 --- a/HydrantCAProxy/HydrantIdCAPlugin.cs +++ b/HydrantCAProxy/HydrantIdCAPlugin.cs @@ -1,4 +1,4 @@ -using System; +using System; using System.Collections.Concurrent; using System.Collections.Generic; using System.Linq; @@ -17,6 +17,7 @@ using System.Diagnostics; using Keyfactor.AnyGateway.Extensions; using System.Data; +using System.Net.Http; using Keyfactor.PKI.Enums.EJBCA; using Keyfactor.PKI.X509; using Keyfactor.HydrantId.Client.Models.Enums; @@ -33,18 +34,47 @@ public class HydrantIdCAPlugin : IAnyCAPlugin public void Initialize(IAnyCAPluginConfigProvider configProvider, ICertificateDataReader certificateDataReader) { + using var flow = new FlowLogger(_logger, "Initialize"); _logger.MethodEntry(); + try { - certDataReader = certificateDataReader; - Config = configProvider; - var rawData = JsonConvert.SerializeObject(configProvider.CAConnectionData); - _config = JsonConvert.DeserializeObject(rawData); - _logger.LogTrace($"Initialize - Enabled: {_config.Enabled}"); + flow.Step("ValidateInputs", () => + { + if (configProvider == null) + throw new ArgumentNullException(nameof(configProvider), "configProvider cannot be null in Initialize"); + if (certificateDataReader == null) + throw new ArgumentNullException(nameof(certificateDataReader), "certificateDataReader cannot be null in Initialize"); + }); + + flow.Step("DeserializeConfig", () => + { + certDataReader = certificateDataReader; + Config = configProvider; + var rawData = JsonConvert.SerializeObject(configProvider.CAConnectionData); + _logger.LogTrace("Initialize: raw config JSON: {Json}", rawData); + _config = JsonConvert.DeserializeObject(rawData); + }); + + if (_config == null) + { + flow.Fail("ConfigValidation", "Deserialized config is null"); + _logger.LogError("Initialize: _config is null after deserialization."); + return; + } + + flow.Step("ConfigValidation", $"Enabled={_config.Enabled}"); + _logger.LogTrace("Initialize: Enabled={Enabled}, BaseUrl='{BaseUrl}'", + _config.Enabled, _config.HydrantIdBaseUrl ?? "(null)"); } catch (Exception ex) { - _logger.LogError($"Failed to initialize HydrantId CAPlugin: {ex}"); + flow.Fail("Initialize", ex.Message); + _logger.LogError(ex, "Failed to initialize HydrantId CAPlugin: {Message}", ex.Message); + } + finally + { + _logger.MethodExit(); } } @@ -62,30 +92,66 @@ private static List CheckRequiredValues(Dictionary conne public async Task Ping() { + using var flow = new FlowLogger(_logger, "Ping"); _logger.MethodEntry(); - if (!_config.Enabled) + + try + { + if (_config == null) + { + flow.Fail("ConfigCheck", "_config is null"); + _logger.LogError("Ping: _config is null. Initialize may not have been called."); + _logger.MethodExit(LogLevel.Trace); + return; + } + + if (!_config.Enabled) + { + flow.Skip("Ping", "CA is disabled"); + _logger.LogWarning("The CA is currently in the Disabled state. It must be Enabled to perform operations. Skipping connectivity test..."); + _logger.MethodExit(LogLevel.Trace); + return; + } + + flow.Step("PingCA"); + _logger.LogDebug("Pinging HydrantId to validate connection"); + } + finally { - _logger.LogWarning($"The CA is currently in the Disabled state. It must be Enabled to perform operations. Skipping connectivity test..."); - _logger.MethodExit(LogLevel.Trace); - return; + _logger.MethodExit(); } - _logger.LogDebug("Pinging HydrantId to validate connection"); - _logger.MethodExit(); } public Task ValidateCAConnectionInfo(Dictionary connectionInfo) { + using var flow = new FlowLogger(_logger, "ValidateCAConnectionInfo"); _logger.MethodEntry(); - _logger.LogDebug($"Validating HydrantId CA Connection properties"); + + flow.Step("ValidateInputs", () => + { + if (connectionInfo == null) + throw new ArgumentNullException(nameof(connectionInfo), "connectionInfo cannot be null"); + }); + + _logger.LogDebug("Validating HydrantId CA Connection properties"); var rawData = JsonConvert.SerializeObject(connectionInfo); + _logger.LogTrace("ValidateCAConnectionInfo: raw connectionInfo JSON: {Json}", rawData); + _config = JsonConvert.DeserializeObject(rawData); - _logger.LogTrace($"HydrantIdClientFromCAConnectionData - HydrantIdBaseUrl: {_config.HydrantIdBaseUrl}"); - _logger.LogTrace($"HydrantIdClientFromCAConnectionData - Enabled: {_config.Enabled}"); + _logger.LogTrace("ValidateCAConnectionInfo: HydrantIdBaseUrl='{BaseUrl}', Enabled={Enabled}", + _config?.HydrantIdBaseUrl ?? "(null)", _config?.Enabled); + + if (_config == null) + { + flow.Fail("DeserializeConfig", "Deserialized config is null"); + throw new InvalidOperationException("Failed to deserialize connection info into config."); + } if (!_config.Enabled) { - _logger.LogWarning($"The CA is currently in the Disabled state. It must be Enabled to perform operations. Skipping config validation..."); + flow.Skip("Validation", "CA is disabled"); + _logger.LogWarning("The CA is currently in the Disabled state. It must be Enabled to perform operations. Skipping config validation..."); _logger.MethodExit(); return Task.CompletedTask; } @@ -98,9 +164,11 @@ public Task ValidateCAConnectionInfo(Dictionary connectionInfo) if (missingFields.Count > 0) { + flow.Fail("RequiredFields", $"Missing: {string.Join(", ", missingFields)}"); throw new ArgumentException($"The following required fields are missing or empty: {string.Join(", ", missingFields)}"); } + flow.Step("RequiredFields", "all present"); _logger.MethodExit(); return Ping(); } @@ -116,24 +184,58 @@ public Task ValidateProductInfo(EnrollmentProductInfo productInfo, Dictionary GetProductIds() { - var client = new HydrantIdClient(Config); - var policies = client.GetPolicyList().GetAwaiter().GetResult(); + using var flow = new FlowLogger(_logger, "GetProductIds"); + _logger.MethodEntry(); - var ids = policies - .Where(p => p.Id.HasValue) - .Select(p => p.Name.ToString()) - .ToList(); + try + { + var client = new HydrantIdClient(Config); + List policies = null; - return ids; + flow.Step("FetchPolicies", () => + { + policies = client.GetPolicyList().GetAwaiter().GetResult(); + }); + + if (policies == null) + { + flow.Fail("ParsePolicies", "API returned null policy list"); + _logger.LogWarning("GetProductIds: GetPolicyList returned null."); + return new List(); + } + + var ids = policies + .Where(p => p.Id.HasValue) + .Select(p => p.Name.ToString()) + .ToList(); + + flow.Step("MapPolicyIds", $"{ids.Count} product IDs found"); + _logger.LogTrace("GetProductIds: found {Count} product IDs", ids.Count); + return ids; + } + catch (Exception ex) + { + flow.Fail("UNHANDLED", ex.Message); + _logger.LogError(ex, "GetProductIds: unhandled exception: {Message}", ex.Message); + throw; + } + finally + { + _logger.MethodExit(); + } } public async Task Synchronize(BlockingCollection blockingBuffer, DateTime? lastSync, bool fullSync, CancellationToken cancelToken) { + using var flow = new FlowLogger(_logger, $"Synchronize(fullSync={fullSync})"); _logger.MethodEntry(); + _logger.LogTrace("Synchronize: lastSync={LastSync}, fullSync={FullSync}", lastSync?.ToString() ?? "(null)", fullSync); _requestManager = new RequestManager(); var certs = new BlockingCollection(100); var client = new HydrantIdClient(Config); + var processedCount = 0; + var skippedCount = 0; _ = client.GetSubmitCertificateListRequestAsync(certs, cancelToken); @@ -144,28 +246,48 @@ public async Task Synchronize(BlockingCollection blockin cancelToken.ThrowIfCancellationRequested(); if (item == null) + { + _logger.LogTrace("Synchronize: skipping null item from queue"); + skippedCount++; continue; + } - _logger.LogTrace($"Took Certificate ID {item.Id} from Queue"); + _logger.LogTrace("Synchronize: processing Certificate ID={Id}", item.Id ?? "(null)"); var certStatus = _requestManager.GetMapReturnStatus(item.RevocationStatus); - _logger.LogTrace($"Numeric Status: {certStatus}"); + _logger.LogTrace("Synchronize: ID={Id}, RevocationStatus={RevStatus}, MappedStatus={MappedStatus}", + item.Id ?? "(null)", item.RevocationStatus, certStatus); if (certStatus != Convert.ToInt32(EndEntityStatus.GENERATED) && certStatus != Convert.ToInt32(EndEntityStatus.REVOKED)) + { + _logger.LogTrace("Synchronize: skipping ID={Id} with status {Status} (not GENERATED or REVOKED)", item.Id ?? "(null)", certStatus); + skippedCount++; continue; + } - _logger.LogTrace($"Product Id: {item.Policy.Name}"); + _logger.LogTrace("Synchronize: Product ID={ProductId}", item.Policy?.Name ?? "(null)"); try { var cert = await client.GetSubmitGetCertificateAsync(item.Id); + + if (cert == null) + { + _logger.LogWarning("Synchronize: GetSubmitGetCertificateAsync returned null for ID={Id}", item.Id ?? "(null)"); + skippedCount++; + continue; + } + var fileContent = cert.Pem ?? string.Empty; if (string.IsNullOrWhiteSpace(fileContent)) + { + _logger.LogTrace("Synchronize: empty PEM for ID={Id}", item.Id ?? "(null)"); + skippedCount++; continue; + } - // Extract the end entity certificate using the same logic pattern var endEntityCert = GetEndEntityCertificate(fileContent); if (!string.IsNullOrEmpty(endEntityCert)) @@ -175,29 +297,50 @@ public async Task Synchronize(BlockingCollection blockin CARequestID = item.Id, Certificate = endEntityCert, Status = certStatus, - ProductID = item.Policy.Name + ProductID = item.Policy?.Name }, cancelToken); - _logger.LogTrace($"Processed end entity cert for ID {item.Id}"); + processedCount++; + _logger.LogTrace("Synchronize: processed end entity cert for ID={Id} (total={Total})", item.Id ?? "(null)", processedCount); } else { - _logger.LogWarning($"Could not extract end entity certificate for ID {item.Id}"); + _logger.LogWarning("Synchronize: could not extract end entity certificate for ID={Id}", item.Id ?? "(null)"); + skippedCount++; } } catch (Exception certEx) { - _logger.LogError($"Failed to retrieve or process cert {item.Id}: {certEx.Message}"); + _logger.LogError(certEx, "Synchronize: failed to retrieve or process cert ID={Id}: {Message}", item.Id ?? "(null)", certEx.Message); + skippedCount++; } } + + flow.Step("SyncComplete", $"processed={processedCount}, skipped={skippedCount}"); } catch (OperationCanceledException) { - _logger.LogError("Synchronize was canceled."); + flow.Fail("Cancelled", "operation was cancelled"); + _logger.LogWarning("Synchronize: operation was cancelled. Processed={Processed}, Skipped={Skipped}", processedCount, skippedCount); + if (!blockingBuffer.IsAddingCompleted) + blockingBuffer.CompleteAdding(); + throw; + } + catch (AggregateException ae) + { + var inner = ae.Flatten().InnerException; + flow.Fail("UNHANDLED", inner?.Message ?? ae.Message); + _logger.LogError(inner ?? ae, "Synchronize: AggregateException: {Message}", inner?.Message ?? ae.Message); + if (!blockingBuffer.IsAddingCompleted) + blockingBuffer.CompleteAdding(); + throw; } - catch (AggregateException) + catch (Exception ex) { - _logger.LogError("Csc Global Synchronize Task failed!"); + flow.Fail("UNHANDLED", ex.Message); + _logger.LogError(ex, "Synchronize: unhandled exception: {Message}", ex.Message); + if (!blockingBuffer.IsAddingCompleted) + blockingBuffer.CompleteAdding(); throw; } finally @@ -209,6 +352,14 @@ public async Task Synchronize(BlockingCollection blockin // Helper method to extract end entity certificate from PEM chain private string GetEndEntityCertificate(string certData) { + _logger.LogTrace("GetEndEntityCertificate: input length={Length}", certData?.Length ?? 0); + + if (string.IsNullOrWhiteSpace(certData)) + { + _logger.LogWarning("GetEndEntityCertificate: certData is null or empty"); + return string.Empty; + } + var splitCerts = certData.Split( new[] { "-----END CERTIFICATE-----", "-----BEGIN CERTIFICATE-----" }, StringSplitOptions.RemoveEmptyEntries); @@ -217,11 +368,19 @@ private string GetEndEntityCertificate(string certData) foreach (var cert in splitCerts) { - _logger.LogTrace($"Split Cert Value: {cert}"); + if (cert == null) + { + _logger.LogTrace("GetEndEntityCertificate: skipping null split segment"); + continue; + } + + _logger.LogTrace("GetEndEntityCertificate: split cert segment length={Length}", cert.Length); try { - // Clean the cert string and add PEM headers if needed var cleanCert = cert.Trim(); + if (string.IsNullOrWhiteSpace(cleanCert)) + continue; + if (!cleanCert.StartsWith("-----BEGIN CERTIFICATE-----")) { cleanCert = $"-----BEGIN CERTIFICATE-----\n{cleanCert}\n-----END CERTIFICATE-----"; @@ -230,25 +389,34 @@ private string GetEndEntityCertificate(string certData) } catch (Exception ex) { - _logger.LogWarning($"Failed to import certificate segment: {ex.Message}"); + _logger.LogWarning("GetEndEntityCertificate: failed to import certificate segment: {Message}", ex.Message); } + } + if (col.Count == 0) + { + _logger.LogWarning("GetEndEntityCertificate: no certificates imported from PEM data"); + return string.Empty; } - _logger.LogTrace("Getting End Entity Certificate"); + _logger.LogTrace("GetEndEntityCertificate: imported {Count} certificates, extracting end entity", col.Count); var currentCert = X509Utilities.ExtractEndEntityCertificateContents(ExportCollectionToPem(col), ""); - _logger.LogTrace("Converting to Byte Array"); - var byteArray = currentCert?.Export(X509ContentType.Cert); + if (currentCert == null) + { + _logger.LogWarning("GetEndEntityCertificate: ExtractEndEntityCertificateContents returned null"); + return string.Empty; + } - _logger.LogTrace("Initializing empty string"); - var certString = string.Empty; - if (byteArray != null) + var byteArray = currentCert.Export(X509ContentType.Cert); + if (byteArray == null) { - certString = Convert.ToBase64String(byteArray); + _logger.LogWarning("GetEndEntityCertificate: cert Export returned null"); + return string.Empty; } - _logger.LogTrace($"Got certificate {certString}"); + var certString = Convert.ToBase64String(byteArray); + _logger.LogTrace("GetEndEntityCertificate: extracted cert length={Length}", certString.Length); return certString; } @@ -267,83 +435,250 @@ private string ExportCollectionToPem(X509Certificate2Collection collection) public async Task Enroll(string csr, string subject, Dictionary san, EnrollmentProductInfo productInfo, RequestFormat requestFormat, EnrollmentType enrollmentType) { + using var flow = new FlowLogger(_logger, $"Enroll-{enrollmentType}"); _logger.MethodEntry(); + _logger.LogTrace("Enroll: csr length={CsrLen}, subject='{Subject}', enrollmentType={Type}, productID='{ProductId}'", + csr?.Length ?? 0, subject ?? "(null)", enrollmentType, productInfo?.ProductID ?? "(null)"); + _requestManager = new RequestManager(); - int timerTries = 0; Certificate csrTrackingResponse = null; var client = new HydrantIdClient(Config); try { + flow.Step("ValidateInputs", () => + { + if (string.IsNullOrEmpty(csr)) + throw new ArgumentNullException(nameof(csr), "CSR cannot be null or empty."); + if (productInfo == null) + throw new ArgumentNullException(nameof(productInfo), "productInfo cannot be null."); + }); + CertRequestResult enrollmentResponse = null; if (enrollmentType == EnrollmentType.New) { - _logger.LogTrace("Entering New Enrollment"); - var policyListResult = await client.GetPolicyList(); - _logger.LogTrace($"Policy Result List: {JsonConvert.SerializeObject(policyListResult)}"); + _logger.LogTrace("Enroll: entering New Enrollment path"); + + List policyListResult = null; + await flow.StepAsync("FetchPolicies", async () => + { + policyListResult = await client.GetPolicyList(); + }); - var policyId = policyListResult.Single(p => p.Name.Equals(productInfo.ProductID)); - _logger.LogTrace($"PolicyId: {JsonConvert.SerializeObject(policyId)}"); + if (policyListResult == null) + { + flow.Fail("FetchPolicies", "API returned null policy list"); + return new EnrollmentResult + { + Status = (int)EndEntityStatus.FAILED, + StatusMessage = "Enrollment failed: policy list returned null from HydrantId." + }; + } + + _logger.LogTrace("Enroll: policy list result: {Json}", JsonConvert.SerializeObject(policyListResult)); + + var policyId = policyListResult.SingleOrDefault(p => p.Name.Equals(productInfo.ProductID)); + if (policyId == null) + { + flow.Fail("MatchPolicy", $"No policy found matching ProductID '{productInfo.ProductID}'"); + return new EnrollmentResult + { + Status = (int)EndEntityStatus.FAILED, + StatusMessage = $"Enrollment failed: no policy found matching ProductID '{productInfo.ProductID}'." + }; + } + + _logger.LogTrace("Enroll: matched policy: {Json}", JsonConvert.SerializeObject(policyId)); + flow.Step("MatchPolicy", $"policyId={policyId.Id}"); var enrollmentRequest = _requestManager.GetEnrollmentRequest(policyId.Id, productInfo, csr, san); - _logger.LogTrace($"Enrollment Request JSON: {JsonConvert.SerializeObject(enrollmentRequest)}"); + _logger.LogTrace("Enroll: enrollment request JSON: {Json}", JsonConvert.SerializeObject(enrollmentRequest)); - enrollmentResponse = await client.GetSubmitEnrollmentAsync(enrollmentRequest); + await flow.StepAsync("SubmitEnrollment", async () => + { + enrollmentResponse = await client.GetSubmitEnrollmentAsync(enrollmentRequest); + }); } else if (enrollmentType == EnrollmentType.RenewOrReissue) { - _logger.LogTrace("Entering Renew/Reissue Logic..."); + _logger.LogTrace("Enroll: entering Renew/Reissue path"); + + if (productInfo.ProductParameters == null || !productInfo.ProductParameters.ContainsKey("PriorCertSN")) + { + flow.Fail("ValidateRenewParams", "PriorCertSN not found in ProductParameters"); + return new EnrollmentResult + { + Status = (int)EndEntityStatus.FAILED, + StatusMessage = "Renewal failed: PriorCertSN not found in product parameters." + }; + } var sn = productInfo.ProductParameters["PriorCertSN"]; - _logger.LogTrace($"Prior Cert Serial Number: {sn}"); + _logger.LogTrace("Enroll: Prior Cert Serial Number='{SerialNumber}'", sn ?? "(null)"); + + if (string.IsNullOrEmpty(sn)) + { + flow.Fail("ValidateSerialNumber", "PriorCertSN is null or empty"); + return new EnrollmentResult + { + Status = (int)EndEntityStatus.FAILED, + StatusMessage = "Renewal failed: PriorCertSN is null or empty." + }; + } var certificateId = await certDataReader.GetRequestIDBySerialNumber(sn); + _logger.LogTrace("Enroll: certificateId from serial lookup='{CertId}'", certificateId ?? "(null)"); + + if (string.IsNullOrEmpty(certificateId)) + { + flow.Fail("LookupCertId", $"No certificate found for serial number '{sn}'"); + return new EnrollmentResult + { + Status = (int)EndEntityStatus.FAILED, + StatusMessage = $"Renewal failed: no certificate found for serial number '{sn}'." + }; + } + + flow.Step("LookupCertId", $"certificateId={certificateId}"); - //1) Get Single Certificate for the previous certificate var previousCert = await GetSingleRecord(certificateId); - //2) Look up the Expiration Date for that cert + if (previousCert == null || string.IsNullOrEmpty(previousCert.Certificate)) + { + flow.Fail("FetchPreviousCert", $"Could not retrieve previous certificate for ID '{certificateId}'"); + return new EnrollmentResult + { + Status = (int)EndEntityStatus.FAILED, + StatusMessage = $"Renewal failed: could not retrieve previous certificate for ID '{certificateId}'." + }; + } + var previousX509 = new X509Certificate2(Encoding.ASCII.GetBytes(previousCert.Certificate)); var expiration = previousX509.NotAfter; var now = DateTime.UtcNow; - //3) Determine if it is a Renewal vs Re-Issue + if (!productInfo.ProductParameters.ContainsKey("RenewalDays")) + { + flow.Fail("ValidateRenewalDays", "RenewalDays not found in ProductParameters"); + return new EnrollmentResult + { + Status = (int)EndEntityStatus.FAILED, + StatusMessage = "Renewal failed: RenewalDays not found in product parameters." + }; + } + var isRenewal = (expiration - now).TotalDays <= Convert.ToInt16(productInfo.ProductParameters["RenewalDays"]); - _logger.LogTrace($"Certificate Expiration: {expiration}, Current Time: {now}, IsRenewal: {isRenewal}"); + _logger.LogTrace("Enroll: expiration={Expiration}, now={Now}, isRenewal={IsRenewal}", + expiration, now, isRenewal); + flow.Step("DetermineRenewOrReissue", isRenewal ? "Renewal" : "Re-Issue"); if (isRenewal) { - _logger.LogTrace("Proceeding with Renewal Request..."); + _logger.LogTrace("Enroll: proceeding with Renewal request"); + + if (certificateId.Length < 36) + { + flow.Fail("ValidateCertId", $"certificateId '{certificateId}' too short ({certificateId.Length} chars) to extract UUID"); + return new EnrollmentResult + { + Status = (int)EndEntityStatus.FAILED, + StatusMessage = $"Renewal failed: certificateId '{certificateId}' is too short to extract a UUID." + }; + } + var renewRequest = _requestManager.GetRenewalRequest(csr, false); - _logger.LogTrace($"Renewal Request JSON: {JsonConvert.SerializeObject(renewRequest)}"); - enrollmentResponse = await client.GetSubmitRenewalAsync(certificateId, renewRequest); + _logger.LogTrace("Enroll: renewal request JSON: {Json}", JsonConvert.SerializeObject(renewRequest)); + + await flow.StepAsync("SubmitRenewal", async () => + { + enrollmentResponse = await client.GetSubmitRenewalAsync(certificateId, renewRequest); + }); } else { - _logger.LogTrace("Proceeding with Re-Issue Request..."); - var policyListResult = await client.GetPolicyList(); - var policyId = policyListResult.Single(p => p.Name.Equals(productInfo.ProductID)); + _logger.LogTrace("Enroll: proceeding with Re-Issue request"); + + List policyListResult = null; + await flow.StepAsync("FetchPolicies", async () => + { + policyListResult = await client.GetPolicyList(); + }); + + if (policyListResult == null) + { + flow.Fail("FetchPolicies", "API returned null policy list"); + return new EnrollmentResult + { + Status = (int)EndEntityStatus.FAILED, + StatusMessage = "Re-issue failed: policy list returned null from HydrantId." + }; + } + + var policyId = policyListResult.SingleOrDefault(p => p.Name.Equals(productInfo.ProductID)); + if (policyId == null) + { + flow.Fail("MatchPolicy", $"No policy found matching ProductID '{productInfo.ProductID}'"); + return new EnrollmentResult + { + Status = (int)EndEntityStatus.FAILED, + StatusMessage = $"Re-issue failed: no policy found matching ProductID '{productInfo.ProductID}'." + }; + } + var reissueRequest = _requestManager.GetEnrollmentRequest(policyId.Id, productInfo, csr, san); - _logger.LogTrace($"Re-Issue Request JSON: {JsonConvert.SerializeObject(reissueRequest)}"); - enrollmentResponse = await client.GetSubmitEnrollmentAsync(reissueRequest); + _logger.LogTrace("Enroll: re-issue request JSON: {Json}", JsonConvert.SerializeObject(reissueRequest)); + + await flow.StepAsync("SubmitReissue", async () => + { + enrollmentResponse = await client.GetSubmitEnrollmentAsync(reissueRequest); + }); } } - if (enrollmentResponse?.ErrorReturn?.Status == "Failure") + if (enrollmentResponse == null) + { + flow.Fail("EnrollmentResponse", "enrollment response is null"); + return new EnrollmentResult + { + Status = (int)EndEntityStatus.FAILED, + StatusMessage = "Enrollment failed: received null response from HydrantId." + }; + } + + _logger.LogTrace("Enroll: enrollment response JSON: {Json}", JsonConvert.SerializeObject(enrollmentResponse)); + + if (enrollmentResponse.ErrorReturn?.Status == "Failure") { + flow.Fail("EnrollmentResult", enrollmentResponse.ErrorReturn.Error ?? "(no error message)"); return new EnrollmentResult { Status = (int)EndEntityStatus.FAILED, - StatusMessage = $"Enrollment Failed with error {enrollmentResponse.ErrorReturn.Error}" + StatusMessage = $"Enrollment Failed with error {enrollmentResponse.ErrorReturn.Error ?? "(no error message)"}" }; } - timerTries++; - csrTrackingResponse = await GetCertificateOnTimerAsync(enrollmentResponse?.RequestStatus?.Id); + var requestId = enrollmentResponse.RequestStatus?.Id; + _logger.LogTrace("Enroll: request tracking ID='{TrackingId}'", requestId ?? "(null)"); + + if (string.IsNullOrEmpty(requestId)) + { + flow.Fail("TrackingId", "enrollment response has no request tracking ID"); + return new EnrollmentResult + { + Status = (int)EndEntityStatus.FAILED, + StatusMessage = "Enrollment failed: no request tracking ID in response." + }; + } + + await flow.StepAsync("WaitForCertificate", async () => + { + csrTrackingResponse = await GetCertificateOnTimerAsync(requestId); + }); if (csrTrackingResponse == null) { + flow.Fail("WaitForCertificate", "Certificate not ready after polling"); return new EnrollmentResult { Status = (int)EndEntityStatus.FAILED, @@ -351,11 +686,24 @@ public async Task Enroll(string csr, string subject, Dictionar }; } - var cert = await GetSingleRecord(csrTrackingResponse.Id.ToString()); + _logger.LogTrace("Enroll: csrTrackingResponse ID={Id}", csrTrackingResponse.Id?.ToString() ?? "(null)"); + var cert = await GetSingleRecord(csrTrackingResponse.Id.ToString()); var result = _requestManager.GetEnrollmentResult(csrTrackingResponse, cert); + + flow.Step("EnrollmentComplete", $"status={result?.Status}, caRequestId={result?.CARequestID ?? "(null)"}"); return result; } + catch (Exception ex) + { + flow.Fail("UNHANDLED", ex.Message); + _logger.LogError(ex, "Enroll: unhandled exception during {EnrollmentType}: {Message}", enrollmentType, ex.Message); + return new EnrollmentResult + { + Status = (int)EndEntityStatus.FAILED, + StatusMessage = $"Enrollment failed with error: {ex.Message}" + }; + } finally { _logger.MethodExit(); @@ -364,28 +712,72 @@ public async Task Enroll(string csr, string subject, Dictionar public async Task Revoke(string caRequestID, string hexSerialNumber, uint revocationReason) { + using var flow = new FlowLogger(_logger, $"Revoke({caRequestID ?? "null"})"); _logger.MethodEntry(); + _logger.LogTrace("Revoke: caRequestID='{CaRequestId}', hexSerialNumber='{SerialNumber}', revocationReason={Reason}", + caRequestID ?? "(null)", hexSerialNumber ?? "(null)", revocationReason); + _requestManager = new RequestManager(); try { - _logger.LogTrace("Starting Revoke Method"); + flow.Step("ValidateInput", () => + { + if (string.IsNullOrEmpty(caRequestID)) + throw new ArgumentNullException(nameof(caRequestID), "caRequestID cannot be null or empty."); + if (caRequestID.Length < 36) + throw new ArgumentException($"caRequestID '{caRequestID}' is too short ({caRequestID.Length} chars) to extract a UUID.", nameof(caRequestID)); + }); var client = new HydrantIdClient(Config); var hydrantId = caRequestID.Substring(0, 36); - var revokeReason = _requestManager.GetMapRevokeReasons(revocationReason); + _logger.LogTrace("Revoke: extracted UUID='{Uuid}'", hydrantId); + + RevocationReasons revokeReason = default; + flow.Step("MapRevokeReason", () => + { + revokeReason = _requestManager.GetMapRevokeReasons(revocationReason); + }); + _logger.LogTrace("Revoke: mapped reason={Reason}", revokeReason); + + CertificateStatus revokeResponse = null; + await flow.StepAsync("SubmitRevoke", async () => + { + revokeResponse = await client.GetSubmitRevokeCertificateAsync(hydrantId, revokeReason); + }); - _logger.LogTrace($"Revoke Reason: {revokeReason}"); + _logger.LogTrace("Revoke: response JSON: {Json}", JsonConvert.SerializeObject(revokeResponse)); - var revokeResponse = await client.GetSubmitRevokeCertificateAsync(hydrantId, revokeReason); - _logger.LogTrace($"Revoke Response JSON: {JsonConvert.SerializeObject(revokeResponse)}"); + if (revokeResponse == null) + { + flow.Fail("ParseResponse", "API returned null revocation response"); + _logger.LogError("Revoke: GetSubmitRevokeCertificateAsync returned null for UUID='{Uuid}'", hydrantId); + throw new InvalidOperationException($"Revoke failed: received null response from HydrantId for UUID '{hydrantId}'."); + } + flow.Step("RevokeComplete", $"revocationStatus={revokeResponse.RevocationStatus}"); return (int)EndEntityStatus.REVOKED; } + catch (HttpRequestException httpEx) + { + flow.Fail("HttpError", httpEx.Message); + _logger.LogError(httpEx, "Revoke: HTTP error for caRequestID='{CaRequestId}': {Message}", caRequestID ?? "(null)", httpEx.Message); + throw; + } + catch (AggregateException ae) + { + var inner = ae.Flatten().InnerException; + flow.Fail("UNHANDLED", inner?.Message ?? ae.Message); + _logger.LogError(inner ?? ae, "Revoke: AggregateException for caRequestID='{CaRequestId}': {Message}", + caRequestID ?? "(null)", inner?.Message ?? ae.Message); + throw new Exception($"Revoke failed for '{caRequestID}' with message {inner?.Message ?? ae.Message}", inner ?? ae); + } catch (Exception e) { - _logger.LogError($"Error during revoke process: {e.Message}"); - return (int)EndEntityStatus.FAILED; + flow.Fail("UNHANDLED", e.Message); + _logger.LogError(e, "Revoke: unhandled exception for caRequestID='{CaRequestId}': {Message}", + caRequestID ?? "(null)", e.Message); + throw new Exception($"Revoke failed for '{caRequestID}' with message {e.Message}", e); } finally { @@ -395,6 +787,7 @@ public async Task Revoke(string caRequestID, string hexSerialNumber, uint r private async Task GetCertificateOnTimerAsync(string id) { + _logger.LogTrace("GetCertificateOnTimerAsync: waiting for certificate with tracking ID='{Id}'", id ?? "(null)"); var stopwatch = Stopwatch.StartNew(); var client = new HydrantIdClient(Config); @@ -404,64 +797,103 @@ private async Task GetCertificateOnTimerAsync(string id) { var result = await client.GetSubmitGetCertificateByCsrAsync(id); if (result != null) + { + _logger.LogTrace("GetCertificateOnTimerAsync: certificate available after {Elapsed}ms", stopwatch.ElapsedMilliseconds); return result; + } } catch (Exception e) { - _logger.LogTrace($"Enrollment Response not available yet: {LogHandler.FlattenException(e)}"); + _logger.LogTrace("GetCertificateOnTimerAsync: not available yet ({Elapsed}ms): {Message}", + stopwatch.ElapsedMilliseconds, e.Message); } await Task.Delay(1000); } + _logger.LogWarning("GetCertificateOnTimerAsync: timed out after 30s for tracking ID='{Id}'", id ?? "(null)"); return null; } public async Task GetSingleRecord(string caRequestID) { + using var flow = new FlowLogger(_logger, $"GetSingleRecord({caRequestID ?? "null"})"); _logger.MethodEntry(); _requestManager = new RequestManager(); - _logger.LogTrace($"Keyfactor CA ID: {caRequestID}"); + _logger.LogTrace("GetSingleRecord: caRequestID='{CaRequestId}'", caRequestID ?? "(null)"); try { + flow.Step("ValidateInput", () => + { + if (string.IsNullOrEmpty(caRequestID)) + throw new ArgumentNullException(nameof(caRequestID), "caRequestID cannot be null or empty."); + if (caRequestID.Length < 36) + throw new ArgumentException($"caRequestID '{caRequestID}' is too short ({caRequestID.Length} chars) to extract a UUID.", nameof(caRequestID)); + }); + var client = new HydrantIdClient(Config); var certId = caRequestID.Substring(0, 36); - var certificateResponse = await client.GetSubmitGetCertificateAsync(certId); + _logger.LogTrace("GetSingleRecord: extracted UUID='{CertId}'", certId); + + Certificate certificateResponse = null; + await flow.StepAsync("FetchCertificate", async () => + { + certificateResponse = await client.GetSubmitGetCertificateAsync(certId); + }); + + if (certificateResponse == null) + { + flow.Fail("ParseResponse", "API returned null"); + _logger.LogWarning("GetSingleRecord: GetSubmitGetCertificateAsync returned null for certId='{CertId}'", certId); + return new AnyCAPluginCertificate + { + CARequestID = caRequestID, + Certificate = string.Empty, + Status = _requestManager.GetMapReturnStatus(RevocationStatusEnum.Failed) + }; + } - _logger.LogTrace($"Single Cert JSON: {JsonConvert.SerializeObject(certificateResponse)}"); + _logger.LogTrace("GetSingleRecord: response JSON: {Json}", JsonConvert.SerializeObject(certificateResponse)); - // Extract the end entity certificate from the PEM chain var endEntityCert = GetEndEntityCertificate(certificateResponse.Pem); if (string.IsNullOrEmpty(endEntityCert)) { - _logger.LogWarning($"Could not extract end entity certificate for CARequestID {caRequestID}"); + flow.Fail("ExtractCert", $"Could not extract end entity certificate for caRequestID '{caRequestID}'"); + _logger.LogWarning("GetSingleRecord: could not extract end entity certificate for caRequestID='{CaRequestId}'", caRequestID); return new AnyCAPluginCertificate { CARequestID = caRequestID, - Status = _requestManager.GetMapReturnStatus(RevocationStatusEnum.Failed) // Failed + Status = _requestManager.GetMapReturnStatus(RevocationStatusEnum.Failed) }; } - _logger.MethodExit(); + var mappedStatus = _requestManager.GetMapReturnStatus(certificateResponse.RevocationStatus); + flow.Step("MapStatus", $"{certificateResponse.RevocationStatus} -> {mappedStatus}"); + _logger.MethodExit(); return new AnyCAPluginCertificate { CARequestID = caRequestID, - Certificate = endEntityCert, // Now returns the extracted end-entity cert instead of raw PEM - Status = _requestManager.GetMapReturnStatus(certificateResponse.RevocationStatus), + Certificate = endEntityCert, + Status = mappedStatus, }; } + catch (AggregateException ae) + { + var inner = ae.Flatten().InnerException; + flow.Fail("UNHANDLED", inner?.Message ?? ae.Message); + _logger.LogError(inner ?? ae, "GetSingleRecord: AggregateException for caRequestID='{CaRequestId}': {Message}", + caRequestID ?? "(null)", inner?.Message ?? ae.Message); + throw new Exception($"Error occurred getting single cert for '{caRequestID}': {inner?.Message ?? ae.Message}", inner ?? ae); + } catch (Exception ex) { - _logger.LogWarning($"Could not retrieve cert for CARequestID {caRequestID}: {ex.Message}"); - - return new AnyCAPluginCertificate - { - CARequestID = caRequestID, - Status = _requestManager.GetMapReturnStatus(0) // Failed - }; + flow.Fail("UNHANDLED", ex.Message); + _logger.LogError(ex, "GetSingleRecord: exception for caRequestID='{CaRequestId}': {Message}", + caRequestID ?? "(null)", ex.Message); + throw new Exception($"Error occurred getting single cert for '{caRequestID}': {ex.Message}", ex); } } @@ -480,4 +912,4 @@ public Dictionary GetTemplateParameterAnnotations() } } -} \ No newline at end of file +} diff --git a/HydrantCAProxy/HydrantIdCAPlugin.csproj b/HydrantCAProxy/HydrantIdCAPlugin.csproj index 48b20b9..fef6cf3 100644 --- a/HydrantCAProxy/HydrantIdCAPlugin.csproj +++ b/HydrantCAProxy/HydrantIdCAPlugin.csproj @@ -1,6 +1,6 @@  - net6.0;net8.0 + net6.0;net8.0;net10.0 disable true false @@ -12,6 +12,8 @@ + + diff --git a/HydrantCAProxy/RequestManager.cs b/HydrantCAProxy/RequestManager.cs index 0473410..ac47a34 100644 --- a/HydrantCAProxy/RequestManager.cs +++ b/HydrantCAProxy/RequestManager.cs @@ -1,12 +1,12 @@ -// 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 -// thespecific language governing permissions and limitations under the -// License. +// 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 +// thespecific language governing permissions and limitations under the +// License. using System; using System.Collections.Generic; using System.IO; @@ -35,7 +35,8 @@ public int GetMapReturnStatus(RevocationStatusEnum hydrantIdStatus) { Log.MethodEntry(); int returnStatus; - Log.LogTrace($"hydrantIdStatus: {hydrantIdStatus}"); + Log.LogTrace("GetMapReturnStatus: hydrantIdStatus={Status}", hydrantIdStatus); + switch (hydrantIdStatus) { case RevocationStatusEnum.Valid: @@ -45,59 +46,66 @@ public int GetMapReturnStatus(RevocationStatusEnum hydrantIdStatus) returnStatus = (int)EndEntityStatus.INPROCESS; break; case RevocationStatusEnum.Revoked: - returnStatus =(int)EndEntityStatus.REVOKED; + returnStatus = (int)EndEntityStatus.REVOKED; break; case RevocationStatusEnum.Failed: returnStatus = (int)EndEntityStatus.FAILED; break; default: + Log.LogWarning("GetMapReturnStatus: unrecognized status '{Status}', defaulting to FAILED", hydrantIdStatus); returnStatus = (int)EndEntityStatus.FAILED; break; } + + Log.LogTrace("GetMapReturnStatus: {HydrantStatus} -> {MappedStatus}", hydrantIdStatus, returnStatus); Log.MethodExit(); - return Convert.ToInt32(returnStatus); + return returnStatus; } catch (Exception e) { - Log.LogError($"Error Occured in RequestManager.GetMapReturnStatus: {e.Message}"); + Log.LogError(e, "Error occurred in RequestManager.GetMapReturnStatus: {Message}", e.Message); throw; } } public RevocationReasons GetMapRevokeReasons(uint keyfactorRevokeReason) { - try { - RevocationReasons returnStatus = RevocationReasons.KeyCompromise; - if (keyfactorRevokeReason == 1 | keyfactorRevokeReason == 3 | keyfactorRevokeReason == 4 | keyfactorRevokeReason == 5) - { - - switch (keyfactorRevokeReason) - { - case 1: - returnStatus = RevocationReasons.KeyCompromise; - break; - case 3: - returnStatus = RevocationReasons.AffiliationChanged; - break; - case 4: - returnStatus = RevocationReasons.Superseded; - break; - case 5: - returnStatus = RevocationReasons.CessationOfOperation; - break; - } + Log.MethodEntry(); + Log.LogTrace("GetMapRevokeReasons: keyfactorRevokeReason={Reason}", keyfactorRevokeReason); - return returnStatus; + RevocationReasons returnStatus; + switch (keyfactorRevokeReason) + { + case 1: + returnStatus = RevocationReasons.KeyCompromise; + break; + case 3: + returnStatus = RevocationReasons.AffiliationChanged; + break; + case 4: + returnStatus = RevocationReasons.Superseded; + break; + case 5: + returnStatus = RevocationReasons.CessationOfOperation; + break; + default: + Log.LogError("GetMapRevokeReasons: unsupported revoke reason {Reason}", keyfactorRevokeReason); + throw new RevokeReasonNotSupportedException($"Revoke reason {keyfactorRevokeReason} is not supported. Supported values: 1 (KeyCompromise), 3 (AffiliationChanged), 4 (Superseded), 5 (CessationOfOperation)."); } - throw new RevokeReasonNotSupportedException("This Revoke Reason is not Supported"); - + Log.LogTrace("GetMapRevokeReasons: {Input} -> {Mapped}", keyfactorRevokeReason, returnStatus); + Log.MethodExit(); + return returnStatus; + } + catch (RevokeReasonNotSupportedException) + { + throw; } catch (Exception e) { - Log.LogError($"Error Occured in RequestManager.GetMapRevokeReasons: {e.Message}"); + Log.LogError(e, "Error occurred in RequestManager.GetMapRevokeReasons: {Message}", e.Message); throw; } } @@ -107,15 +115,15 @@ public RevokeCertificateReason GetRevokeRequest(RevocationReasons reason) try { Log.MethodEntry(); + Log.LogTrace("GetRevokeRequest: reason={Reason}", reason); return new RevokeCertificateReason { Reason = reason }; } - catch (Exception e) { - Log.LogError($"Error Occured in RequestManager.GetRevokeRequest: {e.Message}"); + Log.LogError(e, "Error occurred in RequestManager.GetRevokeRequest: {Message}", e.Message); throw; } } @@ -125,6 +133,7 @@ public CertificatesPayload GetCertificatesListRequest(int offset, int limit) try { Log.MethodEntry(); + Log.LogTrace("GetCertificatesListRequest: offset={Offset}, limit={Limit}", offset, limit); return new CertificatesPayload { Limit = limit, @@ -135,7 +144,7 @@ public CertificatesPayload GetCertificatesListRequest(int offset, int limit) } catch (Exception e) { - Log.LogError($"Error Occured in RequestManager.GetCertificatesListRequest: {e.Message}"); + Log.LogError(e, "Error occurred in RequestManager.GetCertificatesListRequest: {Message}", e.Message); throw; } } @@ -143,6 +152,20 @@ public CertificatesPayload GetCertificatesListRequest(int offset, int limit) public CertRequestBody GetEnrollmentRequest(Guid? policyId, EnrollmentProductInfo productInfo, string csr, Dictionary san) { Log.MethodEntry(); + Log.LogTrace("GetEnrollmentRequest: policyId={PolicyId}, productID='{ProductId}', csr length={CsrLen}", + policyId?.ToString() ?? "(null)", productInfo?.ProductID ?? "(null)", csr?.Length ?? 0); + + if (productInfo == null) + throw new ArgumentNullException(nameof(productInfo), "productInfo cannot be null."); + if (productInfo.ProductParameters == null) + throw new ArgumentNullException(nameof(productInfo), "productInfo.ProductParameters cannot be null."); + if (string.IsNullOrEmpty(csr)) + throw new ArgumentNullException(nameof(csr), "CSR cannot be null or empty."); + + if (!productInfo.ProductParameters.ContainsKey("ValidityPeriod")) + throw new ArgumentException("ValidityPeriod is required in ProductParameters.", nameof(productInfo)); + if (!productInfo.ProductParameters.ContainsKey("ValidityUnits")) + throw new ArgumentException("ValidityUnits is required in ProductParameters.", nameof(productInfo)); var request = new CertRequestBody { @@ -152,11 +175,12 @@ public CertRequestBody GetEnrollmentRequest(Guid? policyId, EnrollmentProductInf Validity = GetValidity(productInfo.ProductParameters["ValidityPeriod"], Convert.ToInt16(productInfo.ProductParameters["ValidityUnits"])) }; - if (san!= null && san?.Count>0) + if (san != null && san.Count > 0) { request.SubjectAltNames = GetSansRequest(san); } + Log.MethodExit(); return request; } @@ -166,6 +190,11 @@ public RenewalRequest GetRenewalRequest(string csr, bool reuseCsr) try { Log.MethodEntry(); + Log.LogTrace("GetRenewalRequest: csr length={CsrLen}, reuseCsr={ReuseCsr}", csr?.Length ?? 0, reuseCsr); + + if (string.IsNullOrEmpty(csr) && !reuseCsr) + throw new ArgumentNullException(nameof(csr), "CSR cannot be null or empty when reuseCsr is false."); + return new RenewalRequest { Csr = csr, @@ -174,7 +203,7 @@ public RenewalRequest GetRenewalRequest(string csr, bool reuseCsr) } catch (Exception e) { - Log.LogError($"Error Occured in RequestManager.GetRenewalRequest: {e.Message}"); + Log.LogError(e, "Error occurred in RequestManager.GetRenewalRequest: {Message}", e.Message); throw; } } @@ -184,6 +213,11 @@ private CertRequestBodyValidity GetValidity(string period, int units) try { Log.MethodEntry(); + Log.LogTrace("GetValidity: period='{Period}', units={Units}", period ?? "(null)", units); + + if (string.IsNullOrEmpty(period)) + throw new ArgumentNullException(nameof(period), "Validity period cannot be null or empty."); + CertRequestBodyValidity validity = new CertRequestBodyValidity(); switch (period) { @@ -196,13 +230,16 @@ private CertRequestBodyValidity GetValidity(string period, int units) case "Days": validity.Days = units; break; + default: + Log.LogWarning("GetValidity: unrecognized period '{Period}', no validity set", period); + break; } return validity; } catch (Exception e) { - Log.LogError($"Error Occured in RequestManager.GetValidity: {e.Message}"); + Log.LogError(e, "Error occurred in RequestManager.GetValidity: {Message}", e.Message); throw; } } @@ -212,71 +249,101 @@ public CertRequestBodySubjectAltNames GetSansRequest(Dictionary(); + Log.LogTrace("GetSansRequest: dnsname count={Count}", san.Dnsname.Count); + } if (sans.TryGetValue("ipaddress", out var ipAddresses)) - san.Ipaddress = ipAddresses.ToList(); + { + san.Ipaddress = ipAddresses?.ToList() ?? new List(); + Log.LogTrace("GetSansRequest: ipaddress count={Count}", san.Ipaddress.Count); + } if (sans.TryGetValue("rfc822name", out var rfcNames)) - san.Rfc822Name = rfcNames.ToList(); + { + san.Rfc822Name = rfcNames?.ToList() ?? new List(); + Log.LogTrace("GetSansRequest: rfc822name count={Count}", san.Rfc822Name.Count); + } if (sans.TryGetValue("upn", out var upns)) - san.Upn = upns.ToList(); + { + san.Upn = upns?.ToList() ?? new List(); + Log.LogTrace("GetSansRequest: upn count={Count}", san.Upn.Count); + } return san; } catch (Exception e) { - Log.LogError($"Error occurred in RequestManager.GetSansRequest: {e.Message}"); + Log.LogError(e, "Error occurred in RequestManager.GetSansRequest: {Message}", e.Message); throw; } } - public EnrollmentResult - GetEnrollmentResult( - ICertificate enrollmentResult, AnyCAPluginCertificate cert) + public EnrollmentResult GetEnrollmentResult(ICertificate enrollmentResult, AnyCAPluginCertificate cert) { try { Log.MethodEntry(); + Log.LogTrace("GetEnrollmentResult: enrollmentResult is {Null}, cert is {CertNull}", + enrollmentResult == null ? "NULL" : "present", + cert == null ? "NULL" : "present"); + if (enrollmentResult == null) { + Log.LogError("GetEnrollmentResult: enrollmentResult is null."); return new EnrollmentResult { - Status = (int)EndEntityStatus.FAILED, //failure - StatusMessage = $"Enrollment Failed with could not get the certificate from the request tracking id" + Status = (int)EndEntityStatus.FAILED, + StatusMessage = "Enrollment failed: could not get the certificate from the request tracking id." }; } if (!enrollmentResult.Id.HasValue) { + Log.LogError("GetEnrollmentResult: enrollmentResult.Id has no value."); return new EnrollmentResult { - Status = (int)EndEntityStatus.FAILED, //failure - StatusMessage = $"Enrollment Failed with could not get the certificate from the request tracking id" + Status = (int)EndEntityStatus.FAILED, + StatusMessage = "Enrollment failed: certificate response has no ID." }; } - if (enrollmentResult.Id.HasValue) + if (cert == null || string.IsNullOrEmpty(cert.Certificate)) { + Log.LogWarning("GetEnrollmentResult: cert is null or has empty Certificate for ID={Id}", enrollmentResult.Id); return new EnrollmentResult { - Status = (int)EndEntityStatus.GENERATED, //success - CARequestID = enrollmentResult.Id.ToString(), - Certificate = cert.Certificate, - StatusMessage = $"Order Successfully Created" + Status = (int)EndEntityStatus.FAILED, + StatusMessage = "Enrollment failed: could not retrieve certificate content." }; } - return null; + Log.LogTrace("GetEnrollmentResult: success - ID={Id}, certificate length={Len}", + enrollmentResult.Id, cert.Certificate?.Length ?? 0); + + return new EnrollmentResult + { + Status = (int)EndEntityStatus.GENERATED, + CARequestID = enrollmentResult.Id.ToString(), + Certificate = cert.Certificate, + StatusMessage = "Order Successfully Created" + }; } catch (Exception e) { - Log.LogError($"Error Occured in RequestManager.GetEnrollmentResult: {e.Message}"); + Log.LogError(e, "Error occurred in RequestManager.GetEnrollmentResult: {Message}", e.Message); throw; } } @@ -289,6 +356,11 @@ public CertRequestBodyDnComponents GetDnComponentsRequest(string csr) try { Log.MethodEntry(); + Log.LogTrace("GetDnComponentsRequest: csr length={CsrLen}", csr?.Length ?? 0); + + if (string.IsNullOrEmpty(csr)) + throw new ArgumentNullException(nameof(csr), "CSR cannot be null or empty."); + var c = String.Empty; var o = String.Empty; var cn = string.Empty; @@ -296,46 +368,68 @@ public CertRequestBodyDnComponents GetDnComponentsRequest(string csr) var st = string.Empty; var ou = string.Empty; - Log.LogTrace($"CSR: {csr}"); - //var cert = "-----BEGIN CERTIFICATE REQUEST-----\r\n"; - var cert = csr; - //cert = cert + "\r\n-----END CERTIFICATE REQUEST-----"; - Log.LogTrace($"cert: {cert}"); + var cert = csr; + Log.LogTrace("GetDnComponentsRequest: parsing CSR"); var reader = new PemReader(new StringReader(cert)); - if (reader.ReadObject() is Pkcs10CertificationRequest req) + var pemObject = reader.ReadObject(); + if (pemObject == null) + { + Log.LogWarning("GetDnComponentsRequest: PemReader returned null object"); + return new CertRequestBodyDnComponents { Cn = cn, Ou = new List { ou }, O = o, L = l, St = st, C = c }; + } + + if (pemObject is Pkcs10CertificationRequest req) { var info = req.GetCertificationRequestInfo(); - Log.LogTrace($"subject: {info.Subject}"); + Log.LogTrace("GetDnComponentsRequest: subject='{Subject}'", info?.Subject?.ToString() ?? "(null)"); - var array1 = info.Subject.ToString().Split(','); - foreach (var x in array1) + if (info?.Subject != null) { - var itemArray = x.Split('='); - - switch (itemArray[0].ToUpper()) + var array1 = info.Subject.ToString().Split(','); + foreach (var x in array1) { - case "C": - c = itemArray[1]; - break; - case "O": - o = itemArray[1]; - break; - case "CN": - cn = itemArray[1]; - break; - case "OU": - ou = itemArray[1]; - break; - case "ST": - st = itemArray[1]; - break; - case "L": - l = itemArray[1]; - break; + if (string.IsNullOrWhiteSpace(x)) + continue; + + var itemArray = x.Split('='); + if (itemArray.Length < 2) + { + Log.LogTrace("GetDnComponentsRequest: skipping malformed DN component '{Component}'", x); + continue; + } + + switch (itemArray[0].Trim().ToUpper()) + { + case "C": + c = itemArray[1].Trim(); + break; + case "O": + o = itemArray[1].Trim(); + break; + case "CN": + cn = itemArray[1].Trim(); + break; + case "OU": + ou = itemArray[1].Trim(); + break; + case "ST": + st = itemArray[1].Trim(); + break; + case "L": + l = itemArray[1].Trim(); + break; + } } } } + else + { + Log.LogWarning("GetDnComponentsRequest: PEM object is not a PKCS10 request, type={Type}", pemObject.GetType().Name); + } + + Log.LogTrace("GetDnComponentsRequest: CN='{Cn}', O='{O}', OU='{Ou}', C='{C}', ST='{St}', L='{L}'", + cn, o, ou, c, st, l); return new CertRequestBodyDnComponents { @@ -349,10 +443,9 @@ public CertRequestBodyDnComponents GetDnComponentsRequest(string csr) } catch (Exception e) { - Log.LogError($"Error Occured in RequestManager.GetDnComponentsRequest: {e.Message}"); + Log.LogError(e, "Error occurred in RequestManager.GetDnComponentsRequest: {Message}", e.Message); throw; } } } } -