Fix Dan logging (#32)

Dan.Common/Enums/LogAction.cs

@@ -2,19 +2,37 @@
 
 public enum LogAction
 {
+    // Used once per accreditation
     AuthorizationGranted = 1,
 
+    // Used per consent request (one accreditation may incur several consent requests, each of which may span
+    // several datasets
     ConsentRequested = 2,
 
+    // As with ConsentRequested
     ConsentGiven = 3,
 
+    // As with ConsentRequested
     ConsentDenied = 4,
 
-    DataRetrieved = 5,
+    // Used for each harvest performed, of which there may be several per accreditation
+    DatasetRetrieved = 5,
 
+    // As with ConsentRequested
     ConsentReminderSent = 6,
 
-    OpenDataRetrieved = 7,
+    // Used when a open data set harvest is performed
+    OpenDatasetRetrieved = 7,
 
-    AccreditationDeleted = 8
+    // Used once per accreditation
+    AccreditationDeleted = 8,
+
+    // Used per data set requested for each AuthorizationGranted
+    DatasetRequested = 9,
+
+    // Used for each dataset in a consent request
+    DatasetRequiringConsentRequested = 10,
+
+    // Used for each correspondence sent related to consent requests (may be skipped, so counted seperately)
+    CorrespondenceSent = 11,
 }

Dan.Core/Extensions/ILoggerExtension.cs

@@ -7,23 +7,22 @@ namespace Dan.Core.Extensions;
 
 public static class LoggerExtensions
 {
-    // Add "prop__" to emulate in-process behaviour. This is needed to be consistent with historic data.
-    public static string LogString = "{prop__action}:{prop__callingClass}.{prop__callingMethod}, accreditationid={prop__accreditationId}, consentreference={prop__consentReference}, externalReference={prop__externalReference}, owner={prop__owner}, requestor={prop__requestor}, subject={prop__subject}, evidenceCode={prop__evidenceCodeName}, timestamp={prop__dateTime}, serviceContext={prop__serviceContext}, customData={prop__customData}";
+    private const string LogString = "{action}:{callingClass}.{callingMethod},a={accreditationId},c={consentReference},e={externalReference},o={owner},r={requestor},s={subject},d={evidenceCodeName},t={dateTime},sc={serviceContext}";
 
     public static void DanLog(
         this ILogger logger,
         Accreditation accreditation,
         LogAction action,
+        string? dataSetName = null,
         [CallerFilePath] string callingClass = "",
-        [CallerMemberName] string callingMethod = "",
-        string customData = "")
+        [CallerMemberName] string callingMethod = "")
     {
-        foreach (var a in accreditation.EvidenceCodes)
-            logger.LogInformation(LogString, Enum.GetName(typeof(LogAction), action),
-                Path.GetFileNameWithoutExtension(callingClass), callingMethod, accreditation.AccreditationId,
-                accreditation.ConsentReference, accreditation.ExternalReference, accreditation.Owner,
-                accreditation.RequestorParty?.ToString(), accreditation.SubjectParty?.ToString(), a.EvidenceCodeName,
-                DateTime.UtcNow, accreditation.ServiceContext, customData);
+
+        logger.LogInformation(LogString, Enum.GetName(typeof(LogAction), action),
+            Path.GetFileNameWithoutExtension(callingClass), callingMethod, accreditation.AccreditationId,
+            accreditation.ConsentReference, accreditation.ExternalReference, accreditation.Owner,
+            accreditation.RequestorParty?.ToString(), accreditation.SubjectParty?.ToString(), dataSetName,
+            DateTime.UtcNow, accreditation.ServiceContext);
     }
 
     public static void DanLog(
@@ -33,11 +32,10 @@ public static void DanLog(
         string serviceContext,
         LogAction action,
         [CallerFilePath] string callingClass = "",
-        [CallerMemberName] string callingMethod = "",
-        string customData = "")
+        [CallerMemberName] string callingMethod = "")
     {
         logger.LogInformation(LogString, Enum.GetName(typeof(LogAction), action),
             Path.GetFileNameWithoutExtension(callingClass), callingMethod, null, "", "", "", "", subject,
-            evidenceCodeName, DateTime.UtcNow, serviceContext, customData);
+            evidenceCodeName, DateTime.UtcNow, serviceContext);
     }
 }

Dan.Core/FuncAuthorization.cs

@@ -103,7 +103,6 @@ public async Task<HttpResponseData> RunAsync(
                 _logger.LogInformation("Start init consent aid={accreditationId}", accreditation.AccreditationId);
                 await _consentService.Initiate(accreditation, authRequest.SkipAltinnNotification);
                 _logger.LogInformation("Completed init consent aid={accreditationId} elapsedMs={elapsedMs}", accreditation.AccreditationId, t.ElapsedMilliseconds);
-                _logger.DanLog(accreditation, LogAction.ConsentRequested);
             }
         }
 
@@ -120,6 +119,10 @@ public async Task<HttpResponseData> RunAsync(
 
         _logger.LogInformation("Completed authorization request successfully for aid={accreditationId}", accreditation.AccreditationId);
         _logger.DanLog(accreditation, LogAction.AuthorizationGranted);
+        foreach (var evidenceRequest in authRequest.EvidenceRequests)
+        {
+            _logger.DanLog(accreditation, LogAction.DatasetRequested, evidenceRequest.EvidenceCodeName);
+        }
 
         return response;
     }

Dan.Core/FuncDirectHarvester.cs

@@ -107,9 +107,9 @@ public async Task<HttpResponseData> RunAsync(
                     await response.SetEvidenceAsync(evidence);
                 }    
             }
-            
-            _logger.DanLog(accreditation, LogAction.AuthorizationGranted);            
-            _logger.DanLog(accreditation, LogAction.DataRetrieved);
+
+            _logger.DanLog(accreditation, LogAction.AuthorizationGranted);
+            _logger.DanLog(accreditation, LogAction.DatasetRetrieved, evidenceCodeName);
 
             return response;
         }

Dan.Core/FuncEvidenceHarvester.cs

@@ -122,7 +122,7 @@ await response.SetUnenvelopedEvidenceValuesAsync(evidence.EvidenceValues,
 
             await _accreditationRepository.UpdateAccreditationAsync(accreditation);
 
-            _logger.DanLog(accreditation, LogAction.DataRetrieved);
+            _logger.DanLog(accreditation, LogAction.DatasetRetrieved, evidenceCodeName);
 
             return response;
         }

Dan.Core/FuncOpenData.cs

@@ -59,7 +59,7 @@ private async Task<HttpResponseData> GetOpenData(string datasetName, HttpRequest
             var response = req.CreateResponse(HttpStatusCode.OK);
             await response.SetUnenvelopedEvidenceValuesAsync(evidence.EvidenceValues, req.GetQueryParam(JmesPathTransfomer.QueryParameter));
 
-            _logger.DanLog(identifier, datasetName, "OpenData", LogAction.OpenDataRetrieved);
+            _logger.DanLog(identifier, datasetName, "OpenData", LogAction.OpenDatasetRetrieved);
 
             return response;
         }

Dan.Core/Services/ConsentService.cs

@@ -31,11 +31,10 @@ public class ConsentService : IConsentService
 
     private readonly HttpClient _httpClient;
     private readonly HttpClient _noCertHttpClient;
-    private readonly ILogger<ConsentService> _log;
+    private readonly ILogger<ConsentService> _logger;
     private readonly IAltinnCorrespondenceService _correspondenceService;
     private readonly IEntityRegistryService _entityRegistryService;
     private readonly IAltinnServiceOwnerApiService _altinnServiceOwnerApiService;
-    private readonly IAvailableEvidenceCodesService _availableEvidenceCodesService;
     private readonly IRequestContextService _requestContextService;
 
     /// <summary>
@@ -60,11 +59,10 @@ public ConsentService(
         _httpClient = httpClientFactory.CreateClient("ECHttpClient");
         _noCertHttpClient = httpClientFactory.CreateClient("SafeHttpClient");
 
-        _log = loggerFactory.CreateLogger<ConsentService>();
+        _logger = loggerFactory.CreateLogger<ConsentService>();
         _correspondenceService = altinnCorrespondenceService;
         _entityRegistryService = entityRegistryService;
         _altinnServiceOwnerApiService = altinnServiceOwnerApiService;
-        _availableEvidenceCodesService = availableEvidenceCodesService;
         _requestContextService = requestContextService;
 
         _entityRegistryService.UseCoreProxy = false;
@@ -112,12 +110,20 @@ public async Task Initiate(Accreditation accreditation, bool skipAltinnNotificat
 
         var processedConsentRequestStrings = TextTemplateProcessor.ProcessConsentRequestMacros(_requestContextService.ServiceContext.ServiceContextTextTemplate.ConsentDelegationContexts, accreditation, requestorName, subjectName, _requestContextService.ServiceContext.Name);
         var consentRequest = await CreateConsentRequest(accreditation, evidenceCodesRequiringConsent, processedConsentRequestStrings);
+
+        _logger.DanLog(accreditation, LogAction.ConsentRequested);
+        foreach (var ec in evidenceCodesRequiringConsent)
+        {
+           _logger.DanLog(accreditation, LogAction.DatasetRequiringConsentRequested, ec.EvidenceCodeName);
+        }
+
         accreditation.AltinnConsentUrl = GetConsentRequestUrl(consentRequest);
 
         var renderedTexts = TextTemplateProcessor.GetRenderedTexts(_requestContextService.ServiceContext, accreditation, requestorName, subjectName, accreditation.AltinnConsentUrl);
 
         if (!skipAltinnNotification)
         {
+            _logger.DanLog(accreditation, LogAction.CorrespondenceSent);
             await SendCorrespondence(accreditation, renderedTexts);
         }
     }
@@ -139,7 +145,7 @@ public async Task<ConsentStatus> Check(Accreditation accreditation, bool onlyLoc
         var evidenceCodesRequiringConsent = GetEvidenceCodesRequiringConsentForActiveContext(accreditation);
         if (evidenceCodesRequiringConsent.Count == 0)
         {
-            _log.LogError("Expected at least one evidencecode in the accreditation requiring consent in accredition {accreditationId}", accreditation.AccreditationId);
+            _logger.LogError("Expected at least one evidencecode in the accreditation requiring consent in accredition {accreditationId}", accreditation.AccreditationId);
         }
 
         if (accreditation.AuthorizationCode == null)
@@ -196,12 +202,12 @@ public async Task<string> GetJwt(Accreditation accreditation)
         request.Headers.TryAddWithoutValidation("ApiKey", Settings.AltinnApiKey);
         request.Headers.TryAddWithoutValidation("Accept", "application/json");
         request.SetAllowedErrorCodes(HttpStatusCode.BadRequest, HttpStatusCode.Forbidden);
-        _log.LogInformation("Getting jwt: " + url);
+        _logger.LogInformation("Getting jwt: " + url);
         try
         {
             var result = await _noCertHttpClient.SendAsync(request);
 
-            _log.LogInformation($"JWT-get {result.RequestMessage} result: {result.StatusCode} : {result.ReasonPhrase}");
+            _logger.LogInformation($"JWT-get {result.RequestMessage} result: {result.StatusCode} : {result.ReasonPhrase}");
 
             // Altinn returns JWTs as bare JSON strings (with leading and trailing double quotes) 
             var jwt = await result.Content.ReadAsStringAsync();
@@ -273,7 +279,7 @@ public async Task<bool> LogUse(Accreditation accreditation, EvidenceCode evidenc
         }
         catch (Exception ex)
         {
-            _log.LogError($"Failed to check consent status for AccreditationId={accreditation.AccreditationId}, Subject={accreditation.Subject}:\n{ex}");
+            _logger.LogError($"Failed to check consent status for AccreditationId={accreditation.AccreditationId}, Subject={accreditation.Subject}:\n{ex}");
             return false;
         }
     }
@@ -378,7 +384,7 @@ private async Task<ConsentRequest> CreateConsentRequest(Accreditation accreditat
                     }
                 }
 
-                _log.LogError("Failed to create consent request for AccreditationId={accreditationId}, Subject={subject}, StatusCode={statusCode}, ReasonPhrase={reasonPhrase}, ConsentErrors={consentErrors}, RequestJson={requestJson}",
+                _logger.LogError("Failed to create consent request for AccreditationId={accreditationId}, Subject={subject}, StatusCode={statusCode}, ReasonPhrase={reasonPhrase}, ConsentErrors={consentErrors}, RequestJson={requestJson}",
                     accreditation.AccreditationId, accreditation.SubjectParty, response.StatusCode, response.ReasonPhrase, errorString, request.Content == null ? string.Empty : await request.Content.ReadAsStringAsync());
                 throw new ServiceNotAvailableException("Altinn denied the consent request. This is an internal error, please contact support");
             }
@@ -393,7 +399,7 @@ private async Task<ConsentRequest> CreateConsentRequest(Accreditation accreditat
         }
         catch (Exception ex)
         {
-            _log.LogError("Failed to create consent request (no/invalid error model returned, no response) for AccreditationId={accreditationId}, Subject={subject}, Exception={ex}",
+            _logger.LogError("Failed to create consent request (no/invalid error model returned, no response) for AccreditationId={accreditationId}, Subject={subject}, Exception={ex}",
                 accreditation.AccreditationId, accreditation.SubjectParty, ex.Message);
 
             throw;