From acb21cb4bdcff611ae9f7a6e94ba888ba28c0f9f Mon Sep 17 00:00:00 2001
From: Mads Magnus Due <xmadu@energinet.dk>
Date: Tue, 10 Dec 2024 14:32:20 +0100
Subject: [PATCH] feat: added execution time logging when validating incoming
 messages (#1417)

---
 .../UseCases/ValidateIncomingMessage.cs       | 27 ++++++++++++++++++-
 1 file changed, 26 insertions(+), 1 deletion(-)

diff --git a/source/IncomingMessages.Application/UseCases/ValidateIncomingMessage.cs b/source/IncomingMessages.Application/UseCases/ValidateIncomingMessage.cs
index 78abacd3f..f54feb791 100644
--- a/source/IncomingMessages.Application/UseCases/ValidateIncomingMessage.cs
+++ b/source/IncomingMessages.Application/UseCases/ValidateIncomingMessage.cs
@@ -12,12 +12,14 @@
 // See the License for the specific language governing permissions and
 // limitations under the License.
 
+using System.Diagnostics;
 using Energinet.DataHub.EDI.BuildingBlocks.Domain.Models;
 using Energinet.DataHub.EDI.IncomingMessages.Domain.Abstractions;
 using Energinet.DataHub.EDI.IncomingMessages.Domain.Validation;
 using Energinet.DataHub.EDI.IncomingMessages.Domain.Validation.ValidationErrors;
 using Energinet.DataHub.EDI.IncomingMessages.Infrastructure.Repositories.MessageId;
 using Energinet.DataHub.EDI.IncomingMessages.Infrastructure.Repositories.TransactionId;
+using Microsoft.Extensions.Logging;
 
 namespace Energinet.DataHub.EDI.IncomingMessages.Application.UseCases;
 
@@ -28,7 +30,8 @@ public class ValidateIncomingMessage(
     IMessageTypeValidator messageTypeValidator,
     IProcessTypeValidator processTypeValidator,
     IBusinessTypeValidator businessTypeValidator,
-    ITransactionIdRepository transactionIdRepository)
+    ITransactionIdRepository transactionIdRepository,
+    ILogger<ValidateIncomingMessage> logger)
 {
     private const int MaxMessageIdLength = 36;
     private const int MaxTransactionIdLength = 36;
@@ -54,8 +57,11 @@ public async Task<Result> ValidateAsync(
         // It is slightly annoying since all we do is FirstOrDefaultAsync which we await.
         // And read access shouldn't be that much of a problem wrt concurrency.
         // It is also a bit silly to have this as a separate call, but it works.
+        var stopwatch = Stopwatch.StartNew();
         var transactionIdErrors =
             await CheckTransactionIdsAsync(incomingMessage, cancellationToken).ConfigureAwait(false);
+        stopwatch.Stop();
+        logger.LogInformation($"ValidateIncomingMessage CheckTransactionIdsAsync execution time: {stopwatch.ElapsedMilliseconds} ms");
 
         var allErrors = errors.Concat(transactionIdErrors).ToArray();
 
@@ -64,20 +70,26 @@ public async Task<Result> ValidateAsync(
 
     private async Task<IReadOnlyCollection<ValidationError>> AuthorizeSenderAsync(IIncomingMessage message)
     {
+        var stopwatch = Stopwatch.StartNew();
         var allSeriesAreDelegated = message.Series.Count > 0 && message.Series.All(s => s.IsDelegated);
 
         var result = await senderAuthorizer
             .AuthorizeAsync(message, allSeriesAreDelegated)
             .ConfigureAwait(false);
+        stopwatch.Stop();
+        logger.LogInformation($"ValidateIncomingMessage AuthorizeSenderAsync execution time: {stopwatch.ElapsedMilliseconds} ms");
 
         return result.Errors;
     }
 
     private async Task<IReadOnlyCollection<ValidationError>> VerifyReceiverAsync(IIncomingMessage message)
     {
+        var stopwatch = Stopwatch.StartNew();
         var receiverVerification = await receiverValidator
             .VerifyAsync(message.ReceiverNumber, message.ReceiverRoleCode)
             .ConfigureAwait(false);
+        stopwatch.Stop();
+        logger.LogInformation($"ValidateIncomingMessage VerifyReceiverAsync execution time: {stopwatch.ElapsedMilliseconds} ms");
 
         return receiverVerification.Errors;
     }
@@ -86,6 +98,7 @@ private async Task<IReadOnlyCollection<ValidationError>> CheckMessageIdAsync(
         IIncomingMessage message,
         CancellationToken cancellationToken)
     {
+        var stopwatch = Stopwatch.StartNew();
         var errors = new List<ValidationError>();
 
         if (string.IsNullOrEmpty(message.MessageId))
@@ -104,6 +117,9 @@ private async Task<IReadOnlyCollection<ValidationError>> CheckMessageIdAsync(
             errors.Add(new DuplicateMessageIdDetected(message.MessageId));
         }
 
+        stopwatch.Stop();
+        logger.LogInformation($"ValidateIncomingMessage CheckMessageIdAsync execution time: {stopwatch.ElapsedMilliseconds} ms");
+
         return errors;
     }
 
@@ -111,8 +127,11 @@ private async Task<IReadOnlyCollection<ValidationError>> CheckMessageTypeAsync(
         IIncomingMessage message,
         CancellationToken cancellationToken)
     {
+        var stopwatch = Stopwatch.StartNew();
         var result = await messageTypeValidator.ValidateAsync(message, cancellationToken)
             .ConfigureAwait(false);
+        stopwatch.Stop();
+        logger.LogInformation($"ValidateIncomingMessage CheckMessageTypeAsync execution time: {stopwatch.ElapsedMilliseconds} ms");
         return result.Errors;
     }
 
@@ -121,8 +140,11 @@ private async Task<IReadOnlyCollection<ValidationError>> CheckBusinessReasonAsyn
         DocumentFormat documentFormat,
         CancellationToken cancellationToken)
     {
+        var stopwatch = Stopwatch.StartNew();
         var result = await processTypeValidator.ValidateAsync(message, documentFormat, cancellationToken)
             .ConfigureAwait(false);
+        stopwatch.Stop();
+        logger.LogInformation($"ValidateIncomingMessage CheckBusinessReasonAsync execution time: {stopwatch.ElapsedMilliseconds} ms");
         return result.Errors;
     }
 
@@ -130,8 +152,11 @@ private async Task<IReadOnlyCollection<ValidationError>> CheckBusinessTypeAsync(
         IIncomingMessage message,
         CancellationToken cancellationToken)
     {
+        var stopwatch = Stopwatch.StartNew();
         var result = await businessTypeValidator.ValidateAsync(message.BusinessType, cancellationToken)
             .ConfigureAwait(false);
+        stopwatch.Stop();
+        logger.LogInformation($"ValidateIncomingMessage CheckBusinessTypeAsync execution time: {stopwatch.ElapsedMilliseconds} ms");
         return result.Errors;
     }