Add file-line processing diagnostics and event-handler tracing

FileProcessor.BusinessLogic.Tests/CapturingLogger.cs

@@ -0,0 +1,32 @@
+using System;
+using System.Collections.Generic;
+using Microsoft.Extensions.Logging;
+
+namespace FileProcessor.BusinessLogic.Tests;
+
+internal sealed class CapturingLogger<T> : ILogger<T>
+{
+    public List<string> Messages { get; } = new();
+
+    public IDisposable BeginScope<TState>(TState state) where TState : notnull => NullScope.Instance;
+
+    public bool IsEnabled(LogLevel logLevel) => true;
+
+    public void Log<TState>(LogLevel logLevel,
+                            EventId eventId,
+                            TState state,
+                            Exception exception,
+                            Func<TState, Exception, string> formatter)
+    {
+        this.Messages.Add(formatter(state, exception));
+    }
+
+    private sealed class NullScope : IDisposable
+    {
+        public static NullScope Instance { get; } = new();
+
+        public void Dispose()
+        {
+        }
+    }
+}

FileProcessor.BusinessLogic.Tests/DomainEventHandlerTests.cs

@@ -12,17 +12,47 @@ namespace FileProcessor.BusinessLogic.Tests
     using FileImportLog.DomainEvents;
     using MediatR;
     using Imposter.Abstractions;
+    using Requests;
+    using SimpleResults;
     using Shouldly;
     using Shouldly.Configuration;
     using Testing;
     using Xunit;
 
     public class DomainEventHandlerTests
     {
+        [Fact]
+        public async Task FileDomainEventHandler_FileLineAddedEvent_MediatorFailureIsReturned()
+        {
+            IMediatorImposter mediator = new IMediatorImposter();
+            mediator.Send(Arg<IRequest<Result>>.Any(), Arg<CancellationToken>.Any())
+                .ReturnsAsync(Result.Failure("Processing failed"));
+            FileDomainEventHandler eventHandler = new(mediator.Instance());
+
+            Result result = await eventHandler.Handle(TestData.FileLineAddedEvent, CancellationToken.None);
+
+            result.IsFailed.ShouldBeTrue();
+        }
+
+        [Fact]
+        public async Task FileDomainEventHandler_FileLineAddedEvent_MediatorExceptionIsPropagated()
+        {
+            IMediatorImposter mediator = new IMediatorImposter();
+            mediator.Send(Arg<IRequest<Result>>.Any(), Arg<CancellationToken>.Any())
+                .ThrowsAsync(new InvalidOperationException("Mediator failed"));
+            FileDomainEventHandler eventHandler = new(mediator.Instance());
+
+            InvalidOperationException exception = await Should.ThrowAsync<InvalidOperationException>(
+                () => eventHandler.Handle(TestData.FileLineAddedEvent, CancellationToken.None));
+
+            exception.Message.ShouldBe("Mediator failed");
+        }
+
         [Fact]
         public void FileDomainEventHandler_FileLineAddedEvent_EventIsHandled()
         {
             IMediatorImposter mediator = new IMediatorImposter();
+            mediator.Send(Arg<IRequest<Result>>.Any(), Arg<CancellationToken>.Any()).ReturnsAsync(Result.Success());
             FileDomainEventHandler eventHandler = new FileDomainEventHandler(mediator.Instance());
             FileLineAddedEvent fileLineAddedEvent = TestData.FileLineAddedEvent;
             Should.NotThrow(async () =>
@@ -35,6 +65,7 @@ public void FileDomainEventHandler_FileLineAddedEvent_EventIsHandled()
         public void FileDomainEventHandler_FileAddedToImportLogEvent_EventIsHandled()
         {
             IMediatorImposter mediator = new IMediatorImposter();
+            mediator.Send(Arg<IRequest<Result>>.Any(), Arg<CancellationToken>.Any()).ReturnsAsync(Result.Success());
             FileDomainEventHandler eventHandler = new FileDomainEventHandler(mediator.Instance());
             FileAddedToImportLogEvent fileAddedToImportLogEvent = TestData.FileAddedToImportLogEvent;
             Should.NotThrow(async () =>

FileProcessor.BusinessLogic.Tests/FileProcessorDomainServiceTests.cs

@@ -49,6 +49,7 @@ public class FileProcessorDomainServiceTests
     private FileProcessorDomainService FileProcessorDomainService;
 
     private MockFileSystem FileSystem;
+    private CapturingLogger<FileProcessorDomainService> DiagnosticLogger;
     public FileProcessorDomainServiceTests()
     {
         IConfigurationRoot configurationRoot = new ConfigurationBuilder().AddInMemoryCollection(TestData.DefaultAppSettings).Build();
@@ -65,6 +66,7 @@ public FileProcessorDomainServiceTests()
         this.SecurityServiceClient = new ISecurityServiceClientImposter();
         this.FileFormatHandler = new IFileFormatHandlerImposter();
         this.FileSystem = new MockFileSystem();
+        this.DiagnosticLogger = new CapturingLogger<FileProcessorDomainService>();
 
         Func<String, IFileFormatHandler> fileFormatHandlerResolver = (format) =>
                                                                      {
@@ -78,7 +80,7 @@ public FileProcessorDomainServiceTests()
                                                                          this.SecurityServiceClient.Instance(),
                                                                          fileFormatHandlerResolver,
                                                                          this.FileSystem);
-        Logger.Initialise(NullLogger.Instance);
+        Logger.Initialise(this.DiagnosticLogger);
     }
 
     [Fact]
@@ -552,6 +554,9 @@ public async Task FileRequestHandler_ProcessTransactionForFileLineRequest_SaveFa
 
         Result result = await this.FileProcessorDomainService.ProcessTransactionForFileLine(TestData.ProcessTransactionForFileLineCommand, CancellationToken.None);
         result.IsFailed.ShouldBeTrue();
+        this.DiagnosticLogger.Messages.ShouldContain(message => message.Contains("file-line-state-persisted/failed") &&
+                                                                 message.Contains(TestData.FileId.ToString()) &&
+                                                                 message.Contains(TestData.ProcessTransactionForFileLineCommand.LineNumber.ToString()));
     }
 
     [Theory]
@@ -810,6 +815,11 @@ public async Task FileRequestHandler_ProcessTransactionForFileLineRequest_NoMerc
         var result = await this.FileProcessorDomainService.ProcessTransactionForFileLine(TestData.ProcessTransactionForFileLineCommand, CancellationToken.None);
         result.IsFailed.ShouldBeTrue();
         result.Status.ShouldBe(ResultStatus.NotFound);
+        this.DiagnosticLogger.Messages.ShouldContain(message => message.Contains("contract-lookup") &&
+                                                                 message.Contains(TestData.FileId.ToString()) &&
+                                                                 message.Contains(TestData.ProcessTransactionForFileLineCommand.LineNumber.ToString()));
+        this.TransactionProcessorClient.PerformTransaction(Arg<String>.Any(), Arg<SaleTransactionRequest>.Any(), Arg<CancellationToken>.Any())
+            .Called(Count.Never());
     }
 
     [Fact]
@@ -944,6 +954,9 @@ public async Task FileRequestHandler_ProcessTransactionForFileLineRequest_Transa
         var result = await this.FileProcessorDomainService.ProcessTransactionForFileLine(TestData.ProcessTransactionForFileLineCommand, CancellationToken.None);
         result.IsFailed.ShouldBeTrue();
         result.Status.ShouldBe(ResultStatus.Failure);
+        this.DiagnosticLogger.Messages.ShouldContain(message => message.Contains("transaction-dispatch-failed") &&
+                                                                 message.Contains("PerformTransaction") &&
+                                                                 message.Contains(TestData.FileId.ToString()));
     }
 
     [Fact]
@@ -970,6 +983,9 @@ public async Task FileRequestHandler_ProcessTransactionForFileLineRequest_Transa
         var result = await this.FileProcessorDomainService.ProcessTransactionForFileLine(TestData.ProcessTransactionForFileLineCommand, CancellationToken.None);
         result.IsFailed.ShouldBeTrue();
         result.Status.ShouldBe(ResultStatus.Failure);
+        this.DiagnosticLogger.Messages.ShouldContain(message => message.Contains("transaction-dispatch-completed") &&
+                                                                 message.Contains(TestData.ResponseCodeFailed) &&
+                                                                 message.Contains(TestData.FileId.ToString()));
     }
 
 

FileProcessor.BusinessLogic/Common/FileLineProcessingDiagnostics.cs

@@ -0,0 +1,148 @@
+using System;
+using FileProcessor.BusinessLogic.Requests;
+using FileProcessor.File.DomainEvents;
+using FileProcessor.FileAggregate;
+using FileProcessor.Models;
+using Shared.Logger;
+using SimpleResults;
+using TransactionProcessor.DataTransferObjects;
+
+namespace FileProcessor.BusinessLogic.Common;
+
+internal enum FileLineProcessingStage
+{
+    FileAggregateLoad,
+    FileLineLookup,
+    FileProfileLookup,
+    LineIgnoreEvaluation,
+    TransactionDetailsParsing,
+    TokenAcquisition,
+    MerchantLookup,
+    ContractLookup,
+    ContractOperatorMatch,
+    VariableValueProductLookup,
+    MerchantDeviceResolution,
+    TransactionDetailsResolved,
+    TransactionDispatchStarted,
+    TransactionDispatchCompleted,
+    FileLineStateUpdate,
+    FileLineStatePersisted
+}
+
+internal sealed class FileLineProcessingContext
+{
+    public FileLineProcessingContext(FileCommands.ProcessTransactionForFileLineCommand command)
+    {
+        this.Command = command;
+    }
+
+    public FileCommands.ProcessTransactionForFileLineCommand Command { get; }
+
+    public FileLineProcessingStage Stage { get; set; } = FileLineProcessingStage.FileAggregateLoad;
+
+    public Boolean TransactionDispatchAttempted { get; set; }
+
+    public Boolean TransactionDispatchSucceeded { get; set; }
+
+    public Guid EstateId { get; set; }
+
+    public Guid MerchantId { get; set; }
+
+    public Guid FileProfileId { get; set; }
+
+    public String OperatorName { get; set; }
+
+    public String ResponseCode { get; set; }
+}
+
+internal static class FileLineProcessingDiagnostics
+{
+    public static void LineProcessingStarted(FileLineProcessingContext context)
+    {
+        Logger.LogInformation($"line-processing-started FileId={context.Command.FileId} LineNumber={context.Command.LineNumber} EstateId={context.EstateId} MerchantId={context.MerchantId} FileProfileId={context.FileProfileId}");
+    }
+
+    public static void LineProcessingSkipped(FileLineProcessingContext context, ProcessingResult processingResult)
+    {
+        Logger.LogInformation($"file-line-processing-skipped FileId={context.Command.FileId} LineNumber={context.Command.LineNumber} ProcessingResult={processingResult}");
+    }
+
+    public static void LineIgnored(FileLineProcessingContext context)
+    {
+        Logger.LogInformation($"file-line-ignored FileId={context.Command.FileId} LineNumber={context.Command.LineNumber} EstateId={context.EstateId} MerchantId={context.MerchantId} Operator={context.OperatorName} Reason=Ignored by file format handler");
+    }
+
+    public static void LineRejected(FileLineProcessingContext context, String reason)
+    {
+        Logger.LogWarning($"file-line-rejected FileId={context.Command.FileId} LineNumber={context.Command.LineNumber} EstateId={context.EstateId} MerchantId={context.MerchantId} Operator={context.OperatorName} Reason={reason}");
+    }
+
+    public static void LineStateDetermined(FileLineProcessingContext context, ProcessingResult processingResult)
+    {
+        Logger.LogInformation($"file-line-state-determined FileId={context.Command.FileId} LineNumber={context.Command.LineNumber} ProcessingResult={processingResult} TransactionDispatchAttempted={context.TransactionDispatchAttempted} TransactionDispatchSucceeded={context.TransactionDispatchSucceeded} ResponseCode={context.ResponseCode}");
+    }
+
+    public static void ProcessingFailed(FileLineProcessingContext context, Result result)
+    {
+        String stage = context.Stage == FileLineProcessingStage.FileLineStatePersisted
+            ? "file-line-state-persisted/failed"
+            : GetStageName(context.Stage);
+        Logger.LogError($"{stage} failed FileId={context.Command.FileId} LineNumber={context.Command.LineNumber} EstateId={context.EstateId} MerchantId={context.MerchantId} FileProfileId={context.FileProfileId} Operator={context.OperatorName} TransactionDispatchAttempted={context.TransactionDispatchAttempted} TransactionDispatchSucceeded={context.TransactionDispatchSucceeded} ResponseCode={context.ResponseCode} ResultStatus={result.Status} Error={result.Message}");
+    }
+
+    public static void LineStatePersisted(FileLineProcessingContext context)
+    {
+        Logger.LogInformation($"file-line-state-persisted FileId={context.Command.FileId} LineNumber={context.Command.LineNumber} EstateId={context.EstateId} MerchantId={context.MerchantId} FileProfileId={context.FileProfileId} Operator={context.OperatorName} TransactionDispatchAttempted={context.TransactionDispatchAttempted} TransactionDispatchSucceeded={context.TransactionDispatchSucceeded} ResponseCode={context.ResponseCode}");
+    }
+
+    public static void TransactionDispatchStarted(FileLineProcessingContext context)
+    {
+        Logger.LogInformation($"transaction-dispatch-started FileId={context.Command.FileId} LineNumber={context.Command.LineNumber} EstateId={context.EstateId} MerchantId={context.MerchantId} Operator={context.OperatorName} ClientOperation=PerformTransaction");
+    }
+
+    public static void TransactionDispatchFailed(FileLineProcessingContext context, Result<SaleTransactionResponse> result)
+    {
+        Logger.LogError($"transaction-dispatch-failed FileId={context.Command.FileId} LineNumber={context.Command.LineNumber} EstateId={context.EstateId} MerchantId={context.MerchantId} Operator={context.OperatorName} ClientOperation=PerformTransaction ResultStatus={result.Status} Error={result.Message}");
+    }
+
+    public static void TransactionDispatchCompleted(FileLineProcessingContext context, SaleTransactionResponse response)
+    {
+        Logger.LogInformation($"transaction-dispatch-completed FileId={context.Command.FileId} LineNumber={context.Command.LineNumber} EstateId={context.EstateId} MerchantId={context.MerchantId} Operator={context.OperatorName} ClientOperation=PerformTransaction TransactionId={response.TransactionId} ResponseCode={response.ResponseCode} ResponseMessage={response.ResponseMessage}");
+    }
+
+    public static void EventHandlerDispatchFailed(FileLineAddedEvent domainEvent, Result result)
+    {
+        Logger.LogError($"event-handler-dispatch-failed FileId={domainEvent.FileId} LineNumber={domainEvent.LineNumber} EstateId={domainEvent.EstateId} MerchantId={domainEvent.MerchantId} EventType={nameof(FileLineAddedEvent)} ResultStatus={result.Status} Error={result.Message}");
+    }
+
+    public static void EventHandlerDispatchCompleted(FileLineAddedEvent domainEvent)
+    {
+        Logger.LogDebug($"event-handler-dispatch-completed FileId={domainEvent.FileId} LineNumber={domainEvent.LineNumber} EstateId={domainEvent.EstateId} MerchantId={domainEvent.MerchantId} EventType={nameof(FileLineAddedEvent)}");
+    }
+
+    public static void EventHandlerDispatchThrew(FileLineAddedEvent domainEvent, Exception exception)
+    {
+        Logger.LogError($"event-handler-dispatch-threw FileId={domainEvent.FileId} LineNumber={domainEvent.LineNumber} EstateId={domainEvent.EstateId} MerchantId={domainEvent.MerchantId} EventType={nameof(FileLineAddedEvent)} Exception={exception}");
+    }
+
+    private static String GetStageName(FileLineProcessingStage stage) => stage switch
+    {
+        FileLineProcessingStage.FileAggregateLoad => "file-aggregate-load",
+        FileLineProcessingStage.FileLineLookup => "file-line-lookup",
+        FileLineProcessingStage.FileProfileLookup => "file-profile-lookup",
+        FileLineProcessingStage.LineIgnoreEvaluation => "line-ignore-evaluation",
+        FileLineProcessingStage.TransactionDetailsParsing => "transaction-details-parsing",
+        FileLineProcessingStage.TokenAcquisition => "token-acquisition",
+        FileLineProcessingStage.MerchantLookup => "merchant-lookup",
+        FileLineProcessingStage.ContractLookup => "contract-lookup",
+        FileLineProcessingStage.ContractOperatorMatch => "contract-operator-match",
+        FileLineProcessingStage.VariableValueProductLookup => "variable-value-product-lookup",
+        FileLineProcessingStage.MerchantDeviceResolution => "merchant-device-resolution",
+        FileLineProcessingStage.TransactionDetailsResolved => "transaction-details-resolved",
+        FileLineProcessingStage.TransactionDispatchStarted => "transaction-dispatch-started",
+        FileLineProcessingStage.TransactionDispatchCompleted => "transaction-dispatch-completed",
+        FileLineProcessingStage.FileLineStateUpdate => "file-line-state-update",
+        FileLineProcessingStage.FileLineStatePersisted => "file-line-state-persisted",
+        _ => throw new ArgumentOutOfRangeException(nameof(stage), stage, "Unknown file-line processing stage")
+    };
+}

FileProcessor.BusinessLogic/EventHandling/FileDomainEventHandler.cs

@@ -1,6 +1,7 @@
 using System.Threading.Tasks;
-using Shared.Logger;
+using System;
 using SimpleResults;
+using FileProcessor.BusinessLogic.Common;
 
 namespace FileProcessor.BusinessLogic.EventHandling
 {
@@ -62,8 +63,25 @@ private async Task<Result> HandleSpecificDomainEvent(FileLineAddedEvent domainEv
                                                     CancellationToken cancellationToken)
         {
             FileCommands.ProcessTransactionForFileLineCommand command = new (domainEvent.FileId, domainEvent.LineNumber, domainEvent.FileLine);
+            try
+            {
+                Result result = await this.Mediator.Send(command, cancellationToken);
+                if (result.IsFailed)
+                {
+                    FileLineProcessingDiagnostics.EventHandlerDispatchFailed(domainEvent, result);
+                }
+                else
+                {
+                    FileLineProcessingDiagnostics.EventHandlerDispatchCompleted(domainEvent);
+                }
 
-            return await this.Mediator.Send(command, cancellationToken);
+                return result;
+            }
+            catch (Exception ex)
+            {
+                FileLineProcessingDiagnostics.EventHandlerDispatchThrew(domainEvent, ex);
+                throw;
+            }
         }
 
         /// <summary>