Add log traces for integration event handling

src/Services/Basket/Basket.API/Controllers/BasketController.cs

@@ -82,13 +82,13 @@ namespace Microsoft.eShopOnContainers.Services.Basket.API.Controllers
             {
                 try
                 {
-                    _logger.LogInformation("----- BasketController - Publishing integration event: {IntegrationEventId} ({@IntegrationEvent})", eventMessage.Id, eventMessage);
+                    _logger.LogInformation("----- Publishing integration event: {IntegrationEventId} at {AppShortName} - ({@IntegrationEvent})", eventMessage.Id, Program.AppShortName, eventMessage);
 
                     _eventBus.Publish(eventMessage);
                 }
                 catch (Exception ex)
                 {
-                    _logger.LogError(ex, "----- BasketController - ERROR Publishing integration event");
+                    _logger.LogError(ex, "----- ERROR Publishing integration event: {IntegrationEventId} at {AppShortName} - ({@IntegrationEvent})", eventMessage.Id, Program.AppShortName, eventMessage);
 
                     throw;
                 }

src/Services/Basket/Basket.API/IntegrationEvents/EventHandling/ProductPriceChangedIntegrationEventHandler.cs

@@ -26,7 +26,7 @@ namespace Microsoft.eShopOnContainers.Services.Basket.API.IntegrationEvents.Even
         {
             using (LogContext.PushProperty("IntegrationEventId", @event.Id))
             {
-                _logger.LogInformation("----- ProductPriceChangedIntegrationEventHandler - Handling integration event: {IntegrationEventId} ({@IntegrationEvent})", @event.Id, @event);
+                _logger.LogInformation("----- Handling integration event: {IntegrationEventId} at {AppShortName} - ({@IntegrationEvent})", @event.Id, Program.AppShortName, @event);
 
                 var userIds = _repository.GetUsers();
 

src/Services/Basket/Basket.API/Program.cs

@@ -13,7 +13,7 @@ namespace Microsoft.eShopOnContainers.Services.Basket.API
     public class Program
     {
         public static readonly string AppName = typeof(Program).Namespace;
-        public static readonly string ShortAppName = AppName.Substring(AppName.LastIndexOf('.', AppName.LastIndexOf('.') - 1) + 1);
+        public static readonly string AppShortName = AppName.Substring(AppName.LastIndexOf('.', AppName.LastIndexOf('.') - 1) + 1);
 
         public static int Main(string[] args)
         {

src/Services/Catalog/Catalog.API/IntegrationEvents/CatalogIntegrationEventService.cs

@@ -4,6 +4,7 @@ using Microsoft.eShopOnContainers.BuildingBlocks.EventBus.Abstractions;
 using Microsoft.eShopOnContainers.BuildingBlocks.EventBus.Events;
 using Microsoft.eShopOnContainers.BuildingBlocks.IntegrationEventLogEF.Services;
 using Microsoft.eShopOnContainers.BuildingBlocks.IntegrationEventLogEF.Utilities;
+using Microsoft.eShopOnContainers.Services.Catalog.API;
 using Microsoft.eShopOnContainers.Services.Catalog.API.Infrastructure;
 using Microsoft.Extensions.Logging;
 using Serilog.Context;
@@ -40,7 +41,7 @@ namespace Catalog.API.IntegrationEvents
             {
                 try
                 {
-                    _logger.LogInformation("----- CatalogIntegrationEventService - Publishing integration event: {IntegrationEventId} ({@IntegrationEvent})", evt.Id, evt);
+                    _logger.LogInformation("----- Publishing integration event: {IntegrationEventId} at {AppShortName} - ({@IntegrationEvent})", evt.Id, Program.AppShortName, evt);
 
                     await _eventLogService.MarkEventAsInProgressAsync(evt.Id);
                     _eventBus.Publish(evt);
@@ -48,7 +49,7 @@ namespace Catalog.API.IntegrationEvents
                 }
                 catch (Exception ex)
                 {
-                    _logger.LogError(ex, "----- CatalogIntegrationEventService - ERROR Publishing integration event");
+                    _logger.LogError(ex, "----- ERROR Publishing integration event: {IntegrationEventId} at {AppShortName} - ({@IntegrationEvent})", evt.Id, Program.AppShortName, evt);
                     await _eventLogService.MarkEventAsFailedAsync(evt.Id);
                 }
             }

src/Services/Catalog/Catalog.API/Program.cs

@@ -15,7 +15,7 @@ namespace Microsoft.eShopOnContainers.Services.Catalog.API
     public class Program
     {
         public static readonly string AppName = typeof(Program).Namespace;
-        public static readonly string ShortAppName = AppName.Substring(AppName.LastIndexOf('.', AppName.LastIndexOf('.') - 1) + 1);
+        public static readonly string AppShortName = AppName.Substring(AppName.LastIndexOf('.', AppName.LastIndexOf('.') - 1) + 1);
 
         public static int Main(string[] args)
         {

src/Services/Ordering/Ordering.API/Application/Behaviors/BehaviorsHelperExtensions.cs

@@ -0,0 +1,29 @@
+using System;
+using System.Collections.Generic;
+using System.Linq;
+using System.Threading.Tasks;
+
+namespace Ordering.API.Application.Behaviors
+{
+    internal static class BehaviorsHelperExtensions
+    {
+        internal static string GetTypeName(this object @object)
+        {
+            var typeName = string.Empty;
+            var type = @object.GetType();
+
+            if (type.IsGenericType)
+            {
+                var genericTypes = string.Join(",", type.GetGenericArguments().Select(t => t.Name).ToArray());
+                typeName = $"{type.Name.Remove(type.Name.IndexOf('`'))}<{genericTypes}>";
+            }
+            else
+            {
+                typeName = type.Name;
+            }
+
+            return typeName;
+        }
+
+    }
+}

src/Services/Ordering/Ordering.API/Application/Behaviors/LoggingBehavior.cs

@@ -1,9 +1,10 @@
 using MediatR;
 using Microsoft.Extensions.Logging;
+using System.Linq;
 using System.Threading;
 using System.Threading.Tasks;
 
-namespace Ordering.API.Infrastructure.Behaviors
+namespace Ordering.API.Application.Behaviors
 {
     public class LoggingBehavior<TRequest, TResponse> : IPipelineBehavior<TRequest, TResponse>
     {
@@ -12,9 +13,10 @@ namespace Ordering.API.Infrastructure.Behaviors
 
         public async Task<TResponse> Handle(TRequest request, CancellationToken cancellationToken, RequestHandlerDelegate<TResponse> next)
         {
-            _logger.LogInformation($"Handling {typeof(TRequest).Name}");
+            _logger.LogInformation("----- Handling command {CommandName} ({@Command})", request.GetTypeName(), request);
             var response = await next();
-            _logger.LogInformation($"Handled {typeof(TResponse).Name}");
+            _logger.LogInformation("----- Command {CommandName} handled - response: {@Response}", request.GetTypeName(), response);
+
             return response;
         }
     }

src/Services/Ordering/Ordering.API/Application/Behaviors/TransactionBehaviour.cs

@@ -4,8 +4,6 @@ using Microsoft.eShopOnContainers.Services.Ordering.Infrastructure;
 using Microsoft.Extensions.Logging;
 using Ordering.API.Application.IntegrationEvents;
 using System;
-using System.Collections.Generic;
-using System.Linq;
 using System.Threading;
 using System.Threading.Tasks;
 
@@ -29,13 +27,15 @@ namespace Ordering.API.Application.Behaviors
         public async Task<TResponse> Handle(TRequest request, CancellationToken cancellationToken, RequestHandlerDelegate<TResponse> next)
         {
             TResponse response = default(TResponse);
+            var typeName = request.GetTypeName();
 
             try
             {
                 var strategy = _dbContext.Database.CreateExecutionStrategy();
-                await strategy.ExecuteAsync(async () => 
+
+                await strategy.ExecuteAsync(async () =>
                 {
-                    _logger.LogInformation($"Begin transaction {typeof(TRequest).Name}");
+                    _logger.LogInformation("----- Begin transaction for {CommandName} ({@Command})", typeName, request);
 
                     await _dbContext.BeginTransactionAsync();
 
@@ -43,16 +43,16 @@ namespace Ordering.API.Application.Behaviors
 
                     await _dbContext.CommitTransactionAsync();
 
-                    _logger.LogInformation($"Committed transaction {typeof(TRequest).Name}");
+                    _logger.LogInformation("----- Transaction commited for {CommandName}", typeName);
 
                     await _orderingIntegrationEventService.PublishEventsThroughEventBusAsync();
                 });
 
                 return response;
             }
-            catch (Exception)
+            catch (Exception ex)
             {
-                _logger.LogInformation($"Rollback transaction executed {typeof(TRequest).Name}");
+                _logger.LogError(ex, "----- ERROR Handling transaction for {CommandName} ({@Command})", typeName, request);
 
                 _dbContext.RollbackTransaction();
                 throw;

src/Services/Ordering/Ordering.API/Application/Behaviors/ValidatorBehavior.cs

@@ -1,20 +1,30 @@
 using FluentValidation;
 using MediatR;
+using Microsoft.Extensions.Logging;
 using Ordering.Domain.Exceptions;
-using System;
 using System.Linq;
 using System.Threading;
 using System.Threading.Tasks;
 
-namespace Ordering.API.Infrastructure.Behaviors
+namespace Ordering.API.Application.Behaviors
 {
     public class ValidatorBehavior<TRequest, TResponse> : IPipelineBehavior<TRequest, TResponse>
     {
+        private readonly ILogger<ValidatorBehavior<TRequest, TResponse>> _logger;
         private readonly IValidator<TRequest>[] _validators;
-        public ValidatorBehavior(IValidator<TRequest>[] validators) => _validators = validators;
+
+        public ValidatorBehavior(IValidator<TRequest>[] validators, ILogger<ValidatorBehavior<TRequest, TResponse>> logger)
+        {
+            _validators = validators;
+            _logger = logger;
+        }
 
         public async Task<TResponse> Handle(TRequest request, CancellationToken cancellationToken, RequestHandlerDelegate<TResponse> next)
         {
+            var typeName = request.GetTypeName();
+
+            _logger.LogInformation("----- Validating command {CommandType}", typeName);
+
             var failures = _validators
                 .Select(v => v.Validate(request))
                 .SelectMany(result => result.Errors)
@@ -23,12 +33,13 @@ namespace Ordering.API.Infrastructure.Behaviors
 
             if (failures.Any())
             {
+                _logger.LogWarning("----- Validation errors - {CommandType} - Command: {@Command} - Errors: {@ValidationErrors}", typeName, request, failures);
+
                 throw new OrderingDomainException(
                     $"Command Validation Errors for type {typeof(TRequest).Name}", new ValidationException("Validation exception", failures));
             }
 
-            var response = await next();
-            return response;
+            return await next();
         }
     }
-}
+}

src/Services/Ordering/Ordering.API/Application/IntegrationEvents/EventHandling/UserCheckoutAcceptedIntegrationEventHandler.cs

@@ -6,6 +6,7 @@ using Microsoft.eShopOnContainers.Services.Ordering.API.Application.Commands;
 using Microsoft.Extensions.Logging;
 using Ordering.API.Application.IntegrationEvents.Events;
 using Serilog.Context;
+using Microsoft.eShopOnContainers.Services.Ordering.API;
 
 namespace Ordering.API.Application.IntegrationEvents.EventHandling
 {
@@ -35,34 +36,38 @@ namespace Ordering.API.Application.IntegrationEvents.EventHandling
         {
             using (LogContext.PushProperty("IntegrationEventId", eventMsg.Id))
             {
-                _logger.LogInformation("----- UserCheckoutAcceptedIntegrationEventHandler - Handling integration event: {IntegrationEventId} ({@IntegrationEvent})", eventMsg.Id, eventMsg);
+                _logger.LogInformation("----- Handling integration event: {IntegrationEventId} at {AppShortName} - ({@IntegrationEvent})", eventMsg.Id, Program.AppShortName, eventMsg);
 
                 var result = false;
 
                 if (eventMsg.RequestId != Guid.Empty)
                 {
-                    var createOrderCommand = new CreateOrderCommand(eventMsg.Basket.Items, eventMsg.UserId, eventMsg.UserName, eventMsg.City, eventMsg.Street,
-                        eventMsg.State, eventMsg.Country, eventMsg.ZipCode,
-                        eventMsg.CardNumber, eventMsg.CardHolderName, eventMsg.CardExpiration,
-                        eventMsg.CardSecurityNumber, eventMsg.CardTypeId);
+                    using (LogContext.PushProperty("IdentifiedCommandId", eventMsg.RequestId))
+                    {
+                        var createOrderCommand = new CreateOrderCommand(eventMsg.Basket.Items, eventMsg.UserId, eventMsg.UserName, eventMsg.City, eventMsg.Street,
+                            eventMsg.State, eventMsg.Country, eventMsg.ZipCode,
+                            eventMsg.CardNumber, eventMsg.CardHolderName, eventMsg.CardExpiration,
+                            eventMsg.CardSecurityNumber, eventMsg.CardTypeId);
 
-                    _logger.LogInformation("----- UserCheckoutAcceptedIntegrationEventHandler - CreateOrderCommand: {@CreateOrderCommand}", createOrderCommand);
+                        var requestCreateOrder = new IdentifiedCommand<CreateOrderCommand, bool>(createOrderCommand, eventMsg.RequestId);
 
-                    var requestCreateOrder = new IdentifiedCommand<CreateOrderCommand, bool>(createOrderCommand, eventMsg.RequestId);
-                    result = await _mediator.Send(requestCreateOrder);
+                        _logger.LogInformation("----- IdentifiedCreateOrderCommand: {@IdentifiedCreateOrderCommand}", requestCreateOrder);
 
-                    if (result)
-                    {
-                        _logger.LogInformation("----- UserCheckoutAcceptedIntegrationEventHandler - CreateOrderCommand suceeded - RequestId: {RequestId}", eventMsg.RequestId);
-                    }
-                    else
-                    {
-                        _logger.LogWarning("----- UserCheckoutAcceptedIntegrationEventHandler - CreateOrderCommand failed - RequestId: {RequestId}", eventMsg.RequestId);
+                        result = await _mediator.Send(requestCreateOrder);
+
+                        if (result)
+                        {
+                            _logger.LogInformation("----- CreateOrderCommand suceeded - RequestId: {RequestId}", eventMsg.RequestId);
+                        }
+                        else
+                        {
+                            _logger.LogWarning("----- CreateOrderCommand failed - RequestId: {RequestId}", eventMsg.RequestId);
+                        }
                     }
                 }
                 else
                 {
-                    _logger.LogWarning("----- UserCheckoutAcceptedIntegrationEventHandler - Invalid IntegrationEvent - RequestId is missing}");
+                    _logger.LogWarning("----- Invalid IntegrationEvent - RequestId is missing - {@IntegrationEvent}", eventMsg);
                 }
             }
         }

src/Services/Ordering/Ordering.API/Application/IntegrationEvents/OrderingIntegrationEventService.cs

@@ -22,7 +22,7 @@ namespace Ordering.API.Application.IntegrationEvents
         private readonly IntegrationEventLogContext _eventLogContext;
         private readonly IIntegrationEventLogService _eventLogService;
 
-        public OrderingIntegrationEventService(IEventBus eventBus, 
+        public OrderingIntegrationEventService(IEventBus eventBus,
             OrderingContext orderingContext,
             IntegrationEventLogContext eventLogContext,
             Func<DbConnection, IIntegrationEventLogService> integrationEventLogServiceFactory)
@@ -48,7 +48,7 @@ namespace Ordering.API.Application.IntegrationEvents
                 catch (Exception)
                 {
                     await _eventLogService.MarkEventAsFailedAsync(logEvt.EventId);
-                }                
+                }
             }
         }
 

src/Services/Ordering/Ordering.API/Program.cs

@@ -16,7 +16,7 @@ namespace Microsoft.eShopOnContainers.Services.Ordering.API
     public class Program
     {
         public static readonly string AppName = typeof(Program).Namespace;
-        public static readonly string ShortAppName = AppName.Substring(AppName.LastIndexOf('.', AppName.LastIndexOf('.') - 1) + 1);
+        public static readonly string AppShortName = AppName.Substring(AppName.LastIndexOf('.', AppName.LastIndexOf('.') - 1) + 1);
 
         public static int Main(string[] args)
         {

src/Services/Ordering/Ordering.API/Startup.cs

@@ -125,7 +125,6 @@
             eventBus.Subscribe<OrderPaymentSuccededIntegrationEvent, IIntegrationEventHandler<OrderPaymentSuccededIntegrationEvent>>();
         }
 
-
         protected virtual void ConfigureAuth(IApplicationBuilder app)
         {
             if (Configuration.GetValue<bool>("UseLoadTest"))