Segment logging (#130)

* Implement segment-level logging of HL7 messages * Fix JSON property name * Update segment logging to log all segments in one line * Move the segment logging code a bit * Disable all segment logging in prod env * Add additional logging * BCMOHAM-16286 Logging Update: added line break * BCMOHAM-16286 Logging Update: added controller logging * BCMOHAM-16286 Logging Update: removed line break to allow for gathering of message in one Kibana document * BCMOHAM-16286 Logging Update: added logging * BCMOHAM-16286 Logging Update: changing header to track * BCMOHAM-16286 Logging Update: temp code to check for headers in deploy env * BCMOHAM-16286 Logging Update: update the config to log required segments * BCMOHAM-16286 Logging Update: removed unnecessary logging * BCMOHAM-16286 Logging Update: added related Kibana searches * BCMOHAM-16286 Logging Update: added tracking between methods * BCMOHAM-16286 Logging Update: updated Kibana search --------- Co-authored-by: dave.p.barrett <dave.p.barrett@cgi.com>
bcgov · Apr 4, 2024 · 95869a9 · 95869a9
1 parent a799895
commit 95869a9
Show file tree

Hide file tree

Showing 71 changed files with 349 additions and 6 deletions.
diff --git a/Services/ClaimService/src/appsettings.dev.json b/Services/ClaimService/src/appsettings.dev.json
@@ -6,6 +6,9 @@
             "Microsoft": "Information"
         }
     },
+    "Hl7v2Authorization": {
+        "LoggableSegments": ["MSH", "ZCA", "ZCB", "ZZZ"]
+    },
     "AllowedHosts": "*",
     "PharmanetProxy": {
         "Endpoint": "https://d1pnetgwy.hibc.gov.bc.ca/pnetIntegration/submitTransaction",

diff --git a/Services/ClaimService/src/appsettings.json b/Services/ClaimService/src/appsettings.json
@@ -37,6 +37,7 @@
         }
     },
     "Hl7v2Authorization": {
+        "LoggableSegments": [],
         "MessageConfig": [
             {
                 "Name": "TACTDU_01_REQUEST-*",

diff --git a/Services/ClaimService/src/appsettings.prd.json b/Services/ClaimService/src/appsettings.prd.json
@@ -6,6 +6,9 @@
             "Microsoft": "Information"
         }
     },
+    "HL7v2Authorization": {
+        "LoggableSegments": ["MSH", "ZCA", "ZCB", "ZZZ"]
+    },
     "AllowedHosts": "*",
     "PharmanetProxy": {
         "Endpoint": "https://pnetgwy.hibc.gov.bc.ca/pnetIntegration/submitTransaction",

diff --git a/Services/ClaimService/src/appsettings.tr1.json b/Services/ClaimService/src/appsettings.tr1.json
@@ -6,6 +6,9 @@
             "Microsoft": "Information"
         }
     },
+    "HL7v2Authorization": {
+        "LoggableSegments": ["MSH", "ZCA", "ZCB", "ZZZ"]
+    },
     "AllowedHosts": "*",
     "PharmanetProxy": {
         "Endpoint": "https://t1pnetgwy.hibc.gov.bc.ca/pnetIntegrationTR1/submitTransaction",

diff --git a/Services/ClaimService/src/appsettings.vc1.json b/Services/ClaimService/src/appsettings.vc1.json
@@ -6,6 +6,9 @@
             "Microsoft": "Information"
         }
     },
+    "HL7v2Authorization": {
+        "LoggableSegments": ["MSH", "ZCA", "ZCB", "ZZZ"]
+    },
     "AllowedHosts": "*",
     "PharmanetProxy": {
         "Endpoint": "https://t1pnetgwy.hibc.gov.bc.ca/pnetIntegrationVC1/submitTransaction",

diff --git a/Services/ClaimService/src/appsettings.vc2.json b/Services/ClaimService/src/appsettings.vc2.json
@@ -6,6 +6,9 @@
             "Microsoft": "Information"
         }
     },
+    "HL7v2Authorization": {
+        "LoggableSegments": ["MSH", "ZCA", "ZCB", "ZZZ"]
+    },
     "AllowedHosts": "*",
     "PharmanetProxy": {
         "Endpoint": "https://t1pnetgwy.hibc.gov.bc.ca/pnetIntegrationVC2/submitTransaction",

diff --git a/Services/ClaimService/src/appsettings.vs1.json b/Services/ClaimService/src/appsettings.vs1.json
@@ -6,6 +6,9 @@
             "Microsoft": "Information"
         }
     },
+    "HL7v2Authorization": {
+        "LoggableSegments": ["MSH", "ZCA", "ZCB", "ZZZ"]
+    },
     "AllowedHosts": "*",
     "PharmanetProxy": {
         "Endpoint": "https://t1pnetgwy.hibc.gov.bc.ca/pnetIntegrationVS1/submitTransaction",

diff --git a/Services/Common/src/Authorization/Requirements/Hl7v2AuthorizationHandler.cs b/Services/Common/src/Authorization/Requirements/Hl7v2AuthorizationHandler.cs
@@ -16,6 +16,7 @@
 namespace Health.PharmaNet.Authorization
 {
     using System;
+    using System.Collections.Generic;
     using System.Linq;
     using System.Threading.Tasks;
 
@@ -54,6 +55,22 @@ public Hl7v2AuthorizationHandler(ILogger<Hl7v2AuthorizationHandler> logger)
         /// <returns>A context Task.</returns>
         protected override Task HandleRequirementAsync(AuthorizationHandlerContext context, Hl7v2AuthorizationRequirement requirement, Message resource)
         {
+            // Get information from the configuration about which segments to log
+            IList<string> loggableSegments = requirement.LoggableSegments();
+            string loggedMessage = "Logged HL7v2 message:";
+
+            // Extract each matching segment of the message
+            foreach (string segmentName in loggableSegments)
+            {
+                foreach (HL7.Dotnetcore.Segment segment in resource.Segments(segmentName))
+                {
+                    loggedMessage += " [ " + segment.Value + " ] ";
+                }
+            }
+
+            // Log the extracted segments of the message
+            Logger.LogInformation(this.logger, loggedMessage);
+
             // If user does not have the scope claim, get out of here
             if (!context.User.HasClaim(c => c.Type == PharmanetAPIClaims.Scope))
             {

diff --git a/Services/Common/src/Authorization/Requirements/Hl7v2AuthorizationRequirement.cs b/Services/Common/src/Authorization/Requirements/Hl7v2AuthorizationRequirement.cs
@@ -63,6 +63,15 @@ public string[] ScopesNeededForMessage(HL7.Dotnetcore.Message message)
             return this.GetMessageAuthorizationScope(message);
         }
 
+        /// <summary>
+        /// Returns the list of segment names that are allowed to be logged.
+        /// </summary>
+        /// <returns>Returns an IList&lt;string&gt; of segment names, or empty array when the message was unknown/not supported.</returns>
+        public IList<string> LoggableSegments()
+        {
+            return this.hl7AuthConfig.Hl7v2Authorization.LoggableSegments;
+        }
+
         /// <summary>
         /// Checks that the message passed has all the fields.
         /// </summary>

diff --git a/Services/Common/src/Authorization/Requirements/Models/Hl7v2Authorization.cs b/Services/Common/src/Authorization/Requirements/Models/Hl7v2Authorization.cs
@@ -23,6 +23,12 @@ namespace Health.PharmaNet.Authorization.Requirements.Models
     /// </summary>
     public class Hl7v2Authorization
     {
+        /// <summary>
+        /// Gets the list of segment fields that are allowed to be logged.
+        /// </summary>
+        [JsonPropertyName("LoggableSegments")]
+        public IList<string> LoggableSegments { get; } = new List<string>();
+
         /// <summary>
         /// Gets the Messages configured.
         /// </summary>

diff --git a/Services/Common/src/Controllers/ServiceBaseController.cs b/Services/Common/src/Controllers/ServiceBaseController.cs
@@ -16,6 +16,8 @@
 namespace Health.PharmaNet.Controllers
 {
     using System;
+
+    using System.Linq;
     using System.Net;
     using System.Security.Claims;
     using System.Threading.Tasks;
@@ -111,9 +113,17 @@ public ServiceBaseController(
         [Authorize]
         protected async Task<ActionResult<DocumentReference>> PharmanetRequest()
         {
+            Logger.LogInformation(this.logger, $"ServiceBaseController.PharmanetRequest start");
+
             ClaimsPrincipal? user = this.HttpContext!.User;
 
+            var traceId = this.Request.Headers.TryGetValue("Kong-Request-ID", out var value) ? value.FirstOrDefault() : "";
+            Logger.LogInformation(this.logger, $"Trace ID: {traceId}: ServiceBaseController.PharmanetRequest. Extracted Kong-Request-ID header as the Trace ID.");
+
             string jsonString = await this.Request.GetRawBodyStringAsync().ConfigureAwait(true);
+
+            Logger.LogInformation(this.logger, $"Trace ID: {traceId}: ServiceBaseController.PharmanetRequest: Got the body from the request.");
+
             DocumentReference fhirRequest;
             Message hl7v2Message;
             try
@@ -130,6 +140,10 @@ protected async Task<ActionResult<DocumentReference>> PharmanetRequest()
                 return this.StatusCode((int)HttpStatusCode.BadRequest, ex.Message);
             }
 
+            HL7.Dotnetcore.Segment? mshSegment = hl7v2Message.Segments("MSH").FirstOrDefault();
+            Logger.LogInformation(this.logger, $"Trace ID: {traceId}: ServiceBaseController.PharmanetRequest: Message MSH: {mshSegment?.Value}");
+
+            Logger.LogInformation(this.logger, $"Trace ID: {traceId}: ServiceBaseController.PharmanetRequest: Authorizing...");
             AuthorizationResult authResult = await this.authorizationService.AuthorizeAsync(
                     user,
                     hl7v2Message,
@@ -138,8 +152,9 @@ protected async Task<ActionResult<DocumentReference>> PharmanetRequest()
             {
                 return new ChallengeResult();
             }
+            Logger.LogInformation(this.logger, $"Trace ID: {traceId}: ServiceBaseController.PharmanetRequest: Authorization completed. Submitting request...");
 
-            RequestResult<DocumentReference> response = await this.service.SubmitRequest(fhirRequest).ConfigureAwait(true);
+            RequestResult<DocumentReference> response = await this.service.SubmitRequest(fhirRequest, traceId + "").ConfigureAwait(true);
             if (response.IsSuccessStatusCode == false)
             {
                 Logger.LogError(this.logger, $"An Error occurred while invoking Pharmanet endpoint: {response.ErrorMessage}");
@@ -150,11 +165,13 @@ protected async Task<ActionResult<DocumentReference>> PharmanetRequest()
                     ContentType = "application/json",
                 };
             }
+            Logger.LogInformation(this.logger, $"Trace ID: {traceId}: ServiceBaseController.PharmanetRequest: Request completed.");
 
             DocumentReference? docRef = response.Payload;
 
             FhirJsonSerializer serializer = new FhirJsonSerializer(new SerializerSettings() { Pretty = true });
 
+            Logger.LogInformation(this.logger, $"Trace ID: {traceId}: ServiceBaseController.PharmanetRequest end");
             return new ContentResult()
             {
                 Content = serializer.SerializeToString(docRef),

diff --git a/Services/Common/src/Delegates/PharmanetDelegate.cs b/Services/Common/src/Delegates/PharmanetDelegate.cs
@@ -54,15 +54,16 @@ private string TrimBadCharactersInMessage(string hl7base64Message = @"")
 
             Span<byte> span = bytes;
             int i = 0;
-            foreach(byte aByte in span)
+            foreach (byte aByte in span)
             {
                 newBytes[i] = 0x00;
                 if ((aByte > 0x00) && (aByte <= 0xff))  // only bytes in UTF8 range
                 {
                     newBytes[i] = aByte;
                     i++;
                 }
-                else {
+                else
+                {
                     Logger.LogInformation(this.logger, $"WORKAROUND: Removed {aByte:X4} character from HL7v2 response.");
                 }
             }
@@ -96,6 +97,8 @@ public PharmanetDelegate(HttpClient client, ILogger<PharmanetDelegate> logger, I
         /// <returns>A PharmanetMessage response.</returns>
         public async Task<RequestResult<PharmanetMessageModel>> SubmitRequest(PharmanetMessageModel request)
         {
+            Logger.LogInformation(this.logger, $"Transaction UUID: {request.TransactionId}: PharmanetDelegate.SubmitRequest start");
+
             RequestResult<PharmanetMessageModel> requestResult = new RequestResult<PharmanetMessageModel>();
 
             JsonSerializerOptions options = new JsonSerializerOptions();
@@ -108,10 +111,14 @@ public async Task<RequestResult<PharmanetMessageModel>> SubmitRequest(PharmanetM
             {
                 Uri delegateUri = new Uri(this.pharmanetDelegateConfig.Endpoint);
 
+                Logger.LogInformation(this.logger, $"Transaction UUID: {request.TransactionId}: PharmanetDelegate.SubmitRequest: Sending message to PharmaNet...");
                 // This log statement logs sensitive health information - use it only for debugging in a development environment
                 // Logger.LogDebug(this.logger, $"PharmanetDelegate Proxy POST {delegateUri}. Payload: {jsonOutput}");
 
                 HttpResponseMessage response = await this.httpClient.PostAsync(delegateUri, content).ConfigureAwait(true);
+
+                Logger.LogInformation(this.logger, $"Transaction UUID: {request.TransactionId}: PharmanetDelegate.SubmitRequest: Received response from PharmaNet with Status Code: {response.StatusCode}.");
+
                 requestResult.IsSuccessStatusCode = response.IsSuccessStatusCode;
                 requestResult.StatusCode = response.StatusCode;
 
@@ -124,13 +131,16 @@ public async Task<RequestResult<PharmanetMessageModel>> SubmitRequest(PharmanetM
                 }
                 else
                 {
+                    Logger.LogInformation(this.logger, $"Transaction UUID: {request.TransactionId}: PharmanetDelegate.SubmitRequest: Response success, extracting response content...");
                     string? result = await response.Content.ReadAsStringAsync().ConfigureAwait(true);
+                    Logger.LogInformation(this.logger, $"Transaction UUID: {request.TransactionId}: PharmanetDelegate.SubmitRequest: Extracting response content. Deserializing message...");
                     PharmanetMessageModel? responseMessage = JsonSerializer.Deserialize<PharmanetMessageModel>(result);
+                    Logger.LogInformation(this.logger, $"Transaction UUID: {request.TransactionId}: PharmanetDelegate.SubmitRequest: Deserialized message. Building response...");
 
                     responseMessage!.Hl7Message = TrimBadCharactersInMessage(responseMessage!.Hl7Message); // Workaround stray chars from Delegate
                     requestResult.Payload = responseMessage;
                     // This log statement does not log sensitive health information, even though it looks like it might
-                    Logger.LogDebug(this.logger, $"PharmanetDelegate Proxy Response: {responseMessage}");
+                    Logger.LogDebug(this.logger, $"Transaction UUID: {request.TransactionId}: PharmanetDelegate Proxy Response: {responseMessage}");
                 }
             }
 #pragma warning disable CA1031 // Do not catch general exception types
@@ -146,6 +156,7 @@ public async Task<RequestResult<PharmanetMessageModel>> SubmitRequest(PharmanetM
                 return requestResult;
             }
 
+            Logger.LogInformation(this.logger, $"Transaction UUID: {request.TransactionId}: PharmanetDelegate.SubmitRequest end ");
             return requestResult;
         }
     }

diff --git a/Services/Common/src/Services/IPharmanetService.cs b/Services/Common/src/Services/IPharmanetService.cs
@@ -28,7 +28,8 @@ public interface IPharmanetService
         /// Submit request of type DocumentReference containing HL7v2 message to PharmaNet.
         /// </summary>
         /// <param name="request">An HL7 FHIR DocumentReference request containing HL7v2 payload.</param>
+        /// <param name="traceId">The value used to track messages from API Gateway.</param>
         /// <returns>Returns a DocumentReference response.</returns>
-        Task<RequestResult<DocumentReference>> SubmitRequest(DocumentReference request);
+        Task<RequestResult<DocumentReference>> SubmitRequest(DocumentReference request, string traceId);
     }
 }
diff --git a/Services/Common/src/Services/PharmanetService.cs b/Services/Common/src/Services/PharmanetService.cs
@@ -56,12 +56,17 @@ public PharmanetService(
         /// Submit Request to Pharmanet.
         /// </summary>
         /// <param name="request">The DocumentReference to be submitted.</param>
+        /// <param name="traceId">The value used to track messages from API Gateway.</param>
         /// <returns>Returns a DocumentReference containing the response from PharmaNet.</returns>
-        public async Task<RequestResult<DocumentReference>> SubmitRequest(DocumentReference request)
+        public async Task<RequestResult<DocumentReference>> SubmitRequest(DocumentReference request, string traceId)
         {
+            Logger.LogInformation(this.logger, $"Trace ID: {traceId}: PharmanetService.SubmitRequest start");
+
             RequestResult<DocumentReference> response = new RequestResult<DocumentReference>();
             bool base64Encode = this.configuration.GetSection(PharmanetDelegateConfig.ConfigurationSectionKey).GetValue<bool>("Base64EncodeHl7Message");
+            Logger.LogInformation(this.logger, $"Trace ID: {traceId}: PharmanetService.SubmitRequest: UUID exists in FHIR? {request.MasterIdentifier != null} ");
             PharmanetMessageModel requestMessage = PharmanetDelegateAdapter.ToPharmanetMessageModel(request, base64Encode);
+            Logger.LogInformation(this.logger, $"Trace ID: {traceId}: Transaction UUID: {requestMessage.TransactionId}: PharmanetService.SubmitRequest: PharmanetMessageModel created.");
 
             try
             {
@@ -80,8 +85,10 @@ public async Task<RequestResult<DocumentReference>> SubmitRequest(DocumentRefere
                     // This log statement logs sensitive health information - use it only for debugging in a development environment
                     // this.logger.LogDebug($"Pharmanet Response: {message!.Hl7Message}");
 
+                    Logger.LogInformation(this.logger, $"Transaction UUID: {requestMessage.TransactionId}: PharmanetService.SubmitRequest: Building DocumentReference response...");
                     ResourceReference reference = PharmanetDelegateAdapter.RelatedToDocumentReference(request);
                     response.Payload = PharmanetDelegateAdapter.ToDocumentReference(message!, reference);
+                    Logger.LogInformation(this.logger, $"Transaction UUID: {requestMessage.TransactionId}: PharmanetService.SubmitRequest: DocumentReference response built.");
 
                     // This log statement does not log sensitive health information, even though it looks like it might
                     this.logger.LogDebug($"FHIR Response: {response!.Payload.ToString()}");
@@ -104,6 +111,7 @@ public async Task<RequestResult<DocumentReference>> SubmitRequest(DocumentRefere
                 response.ErrorMessage = ex.Message;
             }
 
+            Logger.LogInformation(this.logger, $"Transaction UUID: {requestMessage.TransactionId}: PharmanetService.SubmitRequest end");
             return response;
         }
     }

diff --git a/Services/ConsentService/src/appsettings.dev.json b/Services/ConsentService/src/appsettings.dev.json
@@ -6,6 +6,9 @@
             "Microsoft": "Information"
         }
     },
+    "HL7v2Authorization": {
+        "LoggableSegments": ["MSH", "ZCA", "ZCB", "ZZZ"]
+    },
     "AllowedHosts": "*",
     "PharmanetProxy": {
         "Endpoint": "https://d1pnetgwy.hibc.gov.bc.ca/pnetIntegration/submitTransaction",

diff --git a/Services/ConsentService/src/appsettings.json b/Services/ConsentService/src/appsettings.json
@@ -32,6 +32,7 @@
         }
     },
     "Hl7v2Authorization": {
+        "LoggableSegments": [],
         "MessageConfig": [
             {
                 "Name": "TCP_00 REQUEST-998015",

diff --git a/Services/ConsentService/src/appsettings.prd.json b/Services/ConsentService/src/appsettings.prd.json
@@ -6,6 +6,9 @@
             "Microsoft": "Information"
         }
     },
+    "HL7v2Authorization": {
+        "LoggableSegments": ["MSH", "ZCA", "ZCB", "ZZZ"]
+    },
     "AllowedHosts": "*",
     "PharmanetProxy": {
         "Endpoint": "https://pnetgwy.hibc.gov.bc.ca/pnetIntegration/submitTransaction",

diff --git a/Services/ConsentService/src/appsettings.tr1.json b/Services/ConsentService/src/appsettings.tr1.json
@@ -6,6 +6,9 @@
             "Microsoft": "Information"
         }
     },
+    "HL7v2Authorization": {
+        "LoggableSegments": ["MSH", "ZCA", "ZCB", "ZZZ"]
+    },
     "AllowedHosts": "*",
     "PharmanetProxy": {
         "Endpoint": "https://t1pnetgwy.hibc.gov.bc.ca/pnetIntegrationTR1/submitTransaction",

diff --git a/Services/ConsentService/src/appsettings.vc1.json b/Services/ConsentService/src/appsettings.vc1.json
@@ -6,6 +6,9 @@
             "Microsoft": "Information"
         }
     },
+    "HL7v2Authorization": {
+        "LoggableSegments": ["MSH", "ZCA", "ZCB", "ZZZ"]
+    },
     "AllowedHosts": "*",
     "PharmanetProxy": {
         "Endpoint": "https://t1pnetgwy.hibc.gov.bc.ca/pnetIntegrationVC1/submitTransaction",

diff --git a/Services/ConsentService/src/appsettings.vc2.json b/Services/ConsentService/src/appsettings.vc2.json
@@ -6,6 +6,9 @@
             "Microsoft": "Information"
         }
     },
+    "HL7v2Authorization": {
+        "LoggableSegments": ["MSH", "ZCA", "ZCB", "ZZZ"]
+    },
     "AllowedHosts": "*",
     "PharmanetProxy": {
         "Endpoint": "https://t1pnetgwy.hibc.gov.bc.ca/pnetIntegrationVC2/submitTransaction",

diff --git a/Services/ConsentService/src/appsettings.vs1.json b/Services/ConsentService/src/appsettings.vs1.json
@@ -6,6 +6,9 @@
             "Microsoft": "Information"
         }
     },
+    "HL7v2Authorization": {
+        "LoggableSegments": ["MSH", "ZCA", "ZCB", "ZZZ"]
+    },
     "AllowedHosts": "*",
     "PharmanetProxy": {
         "Endpoint": "https://t1pnetgwy.hibc.gov.bc.ca/pnetIntegrationVS1/submitTransaction",

diff --git a/Services/LocationService/src/appsettings.dev.json b/Services/LocationService/src/appsettings.dev.json
@@ -6,6 +6,9 @@
             "Microsoft": "Information"
         }
     },
+    "HL7v2Authorization": {
+        "LoggableSegments": ["MSH", "ZCA", "ZCB", "ZZZ"]
+    },
     "AllowedHosts": "*",
     "PharmanetProxy": {
         "Endpoint": "https://d1pnetgwy.hibc.gov.bc.ca/pnetIntegration/submitTransaction",

diff --git a/Services/LocationService/src/appsettings.json b/Services/LocationService/src/appsettings.json
@@ -37,6 +37,7 @@
         }
     },
     "Hl7v2Authorization": {
+        "LoggableSegments": [],
         "MessageConfig": [
             {
                 "Name": "TIL_00_REQUEST - 1111 & 197001",