Merge pull request #16 from fiskaltrust/user/tsc/50265-verbose-logging

#50265 - Added trace logging

queue/src/fiskaltrust.Middleware.Localization.QueueDE/SignProcessorDE.cs

@@ -22,26 +22,31 @@ public class SignProcessorDE : IMarketSpecificSignProcessor
         private readonly ITransactionPayloadFactory _transactionPayloadFactory;
         private readonly IDESSCDProvider _deSSCDProvider;
         private readonly IRequestCommandFactory _requestCommandFactory;
+        private readonly ILogger<SignProcessorDE> _logger;
 
-        public SignProcessorDE(
+        public SignProcessorDE(            
             IConfigurationRepository configurationRepository,
             IDESSCDProvider dESSCDProvider,
             ITransactionPayloadFactory transactionPayloadFactory,
-            IRequestCommandFactory requestCommandFactory)
+            IRequestCommandFactory requestCommandFactory,
+            ILogger<SignProcessorDE> logger)
         {
             _configurationRepository = configurationRepository;
             _deSSCDProvider = dESSCDProvider;
             _transactionPayloadFactory = transactionPayloadFactory;
             _requestCommandFactory = requestCommandFactory;
+            _logger = logger;
         }
 
         public async Task<(ReceiptResponse receiptResponse, List<ftActionJournal> actionJournals)> ProcessAsync(ReceiptRequest request, ftQueue queue, ftQueueItem queueItem)
         {
+            _logger.LogTrace("SignProcessorDE.ProcessAsync called.");
             if (string.IsNullOrEmpty(request.cbReceiptReference) && !request.IsFailTransactionReceipt() && !string.IsNullOrEmpty(request.ftReceiptCaseData) && !request.ftReceiptCaseData.Contains("CurrentStartedTransactionNumbers"))
             {
                 throw new ArgumentException($"CbReceiptReference must be set for one transaction! If you want to close multiple transactions, pass an array value for 'CurrentStartedTransactionNumbers' via ftReceiptCaseData.");
             }
 
+            _logger.LogTrace("SignProcessorDE.ProcessAsync: Getting QueueDE from database.");
             var queueDE = await _configurationRepository.GetQueueDEAsync(queueItem.ftQueueId).ConfigureAwait(false);
 
             if (!queueDE.ftSignaturCreationUnitDEId.HasValue && !queue.IsActive())
@@ -58,6 +63,7 @@ public SignProcessorDE(
 
         private async Task<RequestCommandResponse> PerformReceiptRequest(ReceiptRequest request, ftQueueItem queueItem, ftQueue queue, ftQueueDE queueDE, IDESSCD client)
         {
+            _logger.LogTrace("SignProcessorDE.PerformReceiptRequest called.");
             var (processType, payload) = _transactionPayloadFactory.CreateReceiptPayload(request);
 
             RequestCommand command;
@@ -70,6 +76,7 @@ private async Task<RequestCommandResponse> PerformReceiptRequest(ReceiptRequest
                 throw new ArgumentException($"ReceiptCase {request.ftReceiptCase:X} unknown. ProcessType {processType}, ProcessData {payload}");
             }
 
+            _logger.LogTrace("SignProcessorDE.PerformReceiptRequest: Executing command {CommandName}.", command.ReceiptName);
             return await command.ExecuteAsync(queue, queueDE, client, request, queueItem);
         }
     }

queue/src/fiskaltrust.Middleware.Queue.EF/version.json

@@ -1,5 +1,5 @@
 {
-  "version": "1.3.29",
+  "version": "1.3.30",
   "releaseBranches": [
     "^refs/heads/main$",
     "^refs/tags/queue/ef/v\\d+(?:\\.\\d+)*(?:-.*)?$"

queue/src/fiskaltrust.Middleware.Queue.InMemory/version.json

@@ -1,5 +1,5 @@
 {
-  "version": "1.3.29",
+  "version": "1.3.30",
   "releaseBranches": [
     "^refs/heads/main$",
     "^refs/tags/queue/inmemory/v\\d+(?:\\.\\d+)*(?:-.*)?$"

queue/src/fiskaltrust.Middleware.Queue.MySQL/version.json

@@ -1,5 +1,5 @@
 {
-  "version": "1.3.29",
+  "version": "1.3.30",
   "releaseBranches": [
     "^refs/heads/main$",
     "^refs/tags/queue/mysql/v\\d+(?:\\.\\d+)*(?:-.*)?$"

queue/src/fiskaltrust.Middleware.Queue.PostgreSQL/version.json

@@ -1,5 +1,5 @@
 {
-  "version": "1.3.29-rc1",
+  "version": "1.3.30-rc1",
   "releaseBranches": [
     "^refs/heads/main$",
     "^refs/tags/queue/postgresql/v\\d+(?:\\.\\d+)*(?:-.*)?$"

queue/src/fiskaltrust.Middleware.Queue.SQLite/version.json

@@ -1,5 +1,5 @@
 {
-  "version": "1.3.29",
+  "version": "1.3.30",
   "releaseBranches": [
     "^refs/heads/main$",
     "^refs/tags/queue/sqlite/v\\d+(?:\\.\\d+)*(?:-.*)?$"

queue/src/fiskaltrust.Middleware.Queue/Bootstrapper/QueueBootstrapper.cs

@@ -9,6 +9,7 @@
 using fiskaltrust.Middleware.QueueSynchronizer;
 using fiskaltrust.storage.V0;
 using Microsoft.Extensions.DependencyInjection;
+using Microsoft.Extensions.Logging;
 using Newtonsoft.Json;
 
 namespace fiskaltrust.Middleware.Queue.Bootstrapper
@@ -37,7 +38,7 @@ public void ConfigureServices(IServiceCollection services)
             services.AddSingleton(middlewareConfiguration);
             services.AddScoped<ICryptoHelper, CryptoHelper>();
             services.AddScoped<SignProcessor>();
-            services.AddScoped<ISignProcessor>(x => new LocalQueueSynchronizationDecorator(x.GetRequiredService<SignProcessor>()));
+            services.AddScoped<ISignProcessor>(x => new LocalQueueSynchronizationDecorator(x.GetRequiredService<SignProcessor>(), x.GetRequiredService<ILogger<LocalQueueSynchronizationDecorator>>()));
             services.AddScoped<IJournalProcessor, JournalProcessor>();
             services.AddScoped<IPOS, Queue>();
 

queue/src/fiskaltrust.Middleware.Queue/SignProcessor.cs

@@ -1,6 +1,5 @@
 using System;
 using System.Collections.Generic;
-using System.IO;
 using System.Linq;
 using System.Threading.Tasks;
 using fiskaltrust.ifPOS.v1;
@@ -23,8 +22,8 @@ public class SignProcessor : ISignProcessor
         private readonly IReceiptJournalRepository _receiptJournalRepository;
         private readonly IActionJournalRepository _actionJournalRepository;
         private readonly ICryptoHelper _cryptoHelper;
-        private Guid _queueId = Guid.Empty;
-        private Guid _cashBoxId = Guid.Empty;
+        private readonly Guid _queueId = Guid.Empty;
+        private readonly Guid _cashBoxId = Guid.Empty;
         private readonly bool _isSandbox;
         private readonly int _receiptRequestMode = 0;
         private readonly SignatureFactory _signatureFactory;
@@ -55,6 +54,7 @@ public SignProcessor(
 
         public async Task<ReceiptResponse> ProcessAsync(ReceiptRequest request)
         {
+            _logger.LogTrace("SignProcessor.ProcessAsync called.");
             try
             {
                 if (request == null)
@@ -82,13 +82,14 @@ public async Task<ReceiptResponse> ProcessAsync(ReceiptRequest request)
 
         private async Task<ReceiptResponse> InternalSign(ftQueue queue, ReceiptRequest data)
         {
+            _logger.LogTrace("SignProcessor.InternalSign called.");
             if ((data.ftReceiptCase & 0x0000800000000000L) > 0)
             {
                 try
                 {
                     var foundQueueItem = await GetExistingQueueItemOrNullAsync(data).ConfigureAwait(false);
                     if (foundQueueItem != null)
-                    {
+                    {                        
                         var message = $"Queue {_queueId} found cbReceiptReference \"{foundQueueItem.cbReceiptReference}\"";
                         _logger.LogWarning(message);
                         await CreateActionJournalAsync(message, "", foundQueueItem.ftQueueItemId).ConfigureAwait(false);
@@ -134,14 +135,18 @@ private async Task<ReceiptResponse> InternalSign(ftQueue queue, ReceiptRequest d
             queueItem.version = ReceiptRequestHelper.GetRequestVersion(data);
             queueItem.request = JsonConvert.SerializeObject(data);
             queueItem.requestHash = _cryptoHelper.GenerateBase64Hash(queueItem.request);
+            _logger.LogTrace("SignProcessor.InternalSign: Adding QueueItem to database.");
             await _queueItemRepository.InsertOrUpdateAsync(queueItem).ConfigureAwait(false);
+            _logger.LogTrace("SignProcessor.InternalSign: Updating Queue in database.");
             await _configurationRepository.InsertOrUpdateQueueAsync(queue).ConfigureAwait(false);
 
             var actionjournals = new List<ftActionJournal>();
             try
             {
                 queueItem.ftWorkMoment = DateTime.UtcNow;
+                _logger.LogTrace("SignProcessor.InternalSign: Calling country specific SignProcessor.");
                 (var receiptResponse, var countrySpecificActionJournals) = await _countrySpecificSignProcessor.ProcessAsync(data, queue, queueItem).ConfigureAwait(false);
+                _logger.LogTrace("SignProcessor.InternalSign: Country specific SignProcessor finished.");
 
                 actionjournals.AddRange(countrySpecificActionJournals);
 
@@ -155,9 +160,13 @@ private async Task<ReceiptResponse> InternalSign(ftQueue queue, ReceiptRequest d
                 queueItem.ftDoneMoment = DateTime.UtcNow;
                 queue.ftCurrentRow++;
 
+                _logger.LogTrace("SignProcessor.InternalSign: Updating QueueItem in database.");
                 await _queueItemRepository.InsertOrUpdateAsync(queueItem).ConfigureAwait(false);
+                _logger.LogTrace("SignProcessor.InternalSign: Updating Queue in database.");
                 await _configurationRepository.InsertOrUpdateQueueAsync(queue).ConfigureAwait(false);
+                _logger.LogTrace("SignProcessor.InternalSign: Adding ReceiptJournal to database.");
                 await CreateReceiptJournalAsync(queue, queueItem, data).ConfigureAwait(false);
+
                 return receiptResponse;
             }
             finally
@@ -171,6 +180,7 @@ private async Task<ReceiptResponse> InternalSign(ftQueue queue, ReceiptRequest d
 
         private async Task<ftQueueItem> GetExistingQueueItemOrNullAsync(ReceiptRequest data)
         {
+            _logger.LogTrace("SignProcessor.GetExistingQueueItemOrNullAsync called.");
             var queueItems = (await _queueItemRepository.GetByReceiptReferenceAsync(data.cbReceiptReference, data.cbTerminalID).ToListAsync().ConfigureAwait(false))
                 .OrderByDescending(x => x.TimeStamp);
 

queue/src/fiskaltrust.Middleware.QueueSynchronizer/LocalQueueSynchronizationDecorator.cs

@@ -5,18 +5,21 @@
 using System.Threading.Tasks;
 using fiskaltrust.ifPOS.v1;
 using fiskaltrust.Middleware.Contracts;
+using Microsoft.Extensions.Logging;
 
 namespace fiskaltrust.Middleware.QueueSynchronizer
 {
     public sealed class LocalQueueSynchronizationDecorator : ISignProcessor, IDisposable
     {
         private readonly ISignProcessor _signProcessor;
+        private readonly ILogger<LocalQueueSynchronizationDecorator> _logger;
         private readonly BlockingCollection<(Guid identifier, ReceiptRequest request)> _concurrentQueue;
         private readonly ConcurrentDictionary<Guid, SynchronizedResult> _stateDictionary;
 
-        public LocalQueueSynchronizationDecorator(ISignProcessor signProcessor)
+        public LocalQueueSynchronizationDecorator(ISignProcessor signProcessor, ILogger<LocalQueueSynchronizationDecorator> logger)
         {
             _signProcessor = signProcessor;
+            _logger = logger;
             _concurrentQueue = new BlockingCollection<(Guid, ReceiptRequest)>(new ConcurrentQueue<(Guid, ReceiptRequest)>());
             _stateDictionary = new ConcurrentDictionary<Guid, SynchronizedResult>();
 
@@ -25,18 +28,21 @@ public LocalQueueSynchronizationDecorator(ISignProcessor signProcessor)
 
         public async Task<ReceiptResponse> ProcessAsync(ReceiptRequest receiptRequest)
         {
+            _logger.LogTrace("LocalQueueSynchronizationDecorator.ProcessAsync called.");
             var identifier = Guid.NewGuid();
             var syncResult = new SynchronizedResult();
             _stateDictionary.TryAdd(identifier, syncResult);
             _concurrentQueue.Add((identifier, receiptRequest));
 
+            _logger.LogTrace("LocalQueueSynchronizationDecorator.ProcessAsync: Waiting until result is available.");
             syncResult.AutoResetEvent.WaitOne();
             if (!_stateDictionary.TryRemove(identifier, out var synchronizedResult))
             {
                 throw new KeyNotFoundException(identifier.ToString());
             }
 
-            if(synchronizedResult.ExceptionDispatchInfo != null)
+            _logger.LogTrace("LocalQueueSynchronizationDecorator.ProcessAsync: Got receipt result.");
+            if (synchronizedResult.ExceptionDispatchInfo != null)
             {
                 synchronizedResult.ExceptionDispatchInfo.Throw();
             }
@@ -48,6 +54,7 @@ private async Task ProcessReceipts()
         {
             while (!_concurrentQueue.IsCompleted && _concurrentQueue.TryTake(out var tuple, -1))
             {
+                _logger.LogTrace("LocalQueueSynchronizationDecorator.ProcessReceipts: Processing a new receipt.");
                 try
                 {
                     var response = await _signProcessor.ProcessAsync(tuple.request).ConfigureAwait(false);

queue/src/fiskaltrust.Middleware.QueueSynchronizer/fiskaltrust.Middleware.QueueSynchronizer.csproj

@@ -1,15 +1,19 @@
 <Project Sdk="Microsoft.NET.Sdk">
 
-  <PropertyGroup>
-    <TargetFrameworks>net461;netstandard2.0;netstandard2.1;net6</TargetFrameworks>
-  </PropertyGroup>
+    <PropertyGroup>
+        <TargetFrameworks>net461;netstandard2.0;netstandard2.1;net6</TargetFrameworks>
+    </PropertyGroup>
 
-  <ItemGroup Condition="'$(TargetFramework)' != 'netstandard2.1'">
-    <PackageReference Include="System.ValueTuple" Version="4.5.0" />
-  </ItemGroup>
+    <ItemGroup Condition="'$(TargetFramework)' != 'netstandard2.1'">
+        <PackageReference Include="System.ValueTuple" Version="4.5.0" />
+    </ItemGroup>
 
-  <ItemGroup>
-    <ProjectReference Include="..\fiskaltrust.Middleware.Contracts\fiskaltrust.Middleware.Contracts.csproj" />
-  </ItemGroup>
+    <ItemGroup>
+        <PackageReference Include="Microsoft.Extensions.Logging.Abstractions" Version="3.1.4" />
+    </ItemGroup>
+
+    <ItemGroup>
+        <ProjectReference Include="..\fiskaltrust.Middleware.Contracts\fiskaltrust.Middleware.Contracts.csproj" />
+    </ItemGroup>
 
 </Project>

queue/test/fiskaltrust.Middleware.Localization.QueueDE.IntegrationTest/SignProcessorDETests/Helpers/RequestCommandFactoryHelper.cs

@@ -70,7 +70,8 @@ public static SignProcessorDE ConstructSignProcessor(
                 configurationRepository,
                 dESSCDProvider,
                 transactionPayloadFactory,
-                new RequestCommandFactory(services.BuildServiceProvider())
+                new RequestCommandFactory(services.BuildServiceProvider()),
+                logger
             );
 
             return signProcessor;

queue/test/fiskaltrust.Middleware.Queue.AcceptanceTest/QueueBootstrapperUnitTests.cs

@@ -9,6 +9,7 @@
 using fiskaltrust.storage.V0;
 using FluentAssertions;
 using Microsoft.Extensions.DependencyInjection;
+using Microsoft.Extensions.Logging;
 using Newtonsoft.Json;
 using Xunit;
 
@@ -57,7 +58,7 @@ public void QueueBootstrapper_AddQueueServices_ShouldReturnServiceCollection()
 
             var signProcessorConfiguration = ServiceDescriptor.Singleton(typeof(MiddlewareConfiguration), implementationInstance: signProcessorConfig);
             var cryptoHelper = new ServiceDescriptor(typeof(ICryptoHelper), typeof(CryptoHelper), ServiceLifetime.Scoped);
-            var signProcessorDecorator =  new ServiceDescriptor(typeof(ISignProcessor), x => new LocalQueueSynchronizationDecorator(x.GetRequiredService<ISignProcessor>()), ServiceLifetime.Scoped);
+            var signProcessorDecorator =  new ServiceDescriptor(typeof(ISignProcessor), x => new LocalQueueSynchronizationDecorator(x.GetRequiredService<ISignProcessor>(), x.GetRequiredService<ILogger<LocalQueueSynchronizationDecorator>>()), ServiceLifetime.Scoped);
             var signProcessor =  new ServiceDescriptor(typeof(SignProcessor), typeof(SignProcessor), ServiceLifetime.Scoped);
             var journalProcessor = new ServiceDescriptor(typeof(IJournalProcessor), typeof(JournalProcessor), ServiceLifetime.Scoped);
             var iPos = new ServiceDescriptor(typeof(IPOS), typeof(Queue), ServiceLifetime.Scoped);

queue/test/fiskaltrust.Middleware.QueueSynchronizer.AcceptanceTest/LocalQueueSynchronizerTests.cs

@@ -1,10 +1,12 @@
 using fiskaltrust.Middleware.Contracts;
+using Microsoft.Extensions.Logging;
+using Moq;
 
 namespace fiskaltrust.Middleware.QueueSynchronizer.AcceptanceTest
 {
     public class LocalQueueSynchronizerTests : AbstractQueueSynchronizerTests
     {
         public override ISignProcessor CreateDecorator(ISignProcessor signProcessor) =>
-            new LocalQueueSynchronizationDecorator(signProcessor);
+            new LocalQueueSynchronizationDecorator(signProcessor, Mock.Of<ILogger<LocalQueueSynchronizationDecorator>>());
     }
 }

queue/version.json

@@ -1,5 +1,5 @@
 {
-  "version": "1.3.29",
+  "version": "1.3.30",
   "releaseBranches": [
     "^refs/tags/queue/.*",
     "^refs/heads/main$"