Merge pull request #955 from dotnet-architecture/enhancement/improve-event-bus-logging

Add logging of subscription events

src/Services/Ordering/Ordering.API/Application/Behaviors/BehaviorsHelperExtensions.cs → src/BuildingBlocks/EventBus/EventBus/Extensions/GenericTypeExtensions.cs

@@ -3,14 +3,13 @@ using System.Collections.Generic;
 using System.Linq;
 using System.Threading.Tasks;
 
-namespace Ordering.API.Application.Behaviors
+namespace Microsoft.eShopOnContainers.BuildingBlocks.EventBus.Extensions
 {
-    internal static class BehaviorsHelperExtensions
+    public static class GenericTypeExtensions
     {
-        internal static string GetGenericTypeName(this object @object)
+        public static string GetGenericTypeName(this Type type)
         {
             var typeName = string.Empty;
-            var type = @object.GetType();
 
             if (type.IsGenericType)
             {
@@ -25,5 +24,9 @@ namespace Ordering.API.Application.Behaviors
             return typeName;
         }
 
+        public static string GetGenericTypeName(this object @object)
+        {
+            return @object.GetType().GetGenericTypeName();
+        }
     }
 }

src/BuildingBlocks/EventBus/EventBusRabbitMQ/EventBusRabbitMQ.cs

@@ -2,6 +2,7 @@
 using Microsoft.eShopOnContainers.BuildingBlocks.EventBus;
 using Microsoft.eShopOnContainers.BuildingBlocks.EventBus.Abstractions;
 using Microsoft.eShopOnContainers.BuildingBlocks.EventBus.Events;
+using Microsoft.eShopOnContainers.BuildingBlocks.EventBus.Extensions;
 using Microsoft.Extensions.Logging;
 using Newtonsoft.Json;
 using Newtonsoft.Json.Linq;
@@ -107,6 +108,8 @@ namespace Microsoft.eShopOnContainers.BuildingBlocks.EventBusRabbitMQ
         public void SubscribeDynamic<TH>(string eventName)
             where TH : IDynamicIntegrationEventHandler
         {
+            _logger.LogInformation("Subscribing to dynamic event {EventName} with {EventHandler}", eventName, typeof(TH).GetGenericTypeName());
+
             DoInternalSubscription(eventName);
             _subsManager.AddDynamicSubscription<TH>(eventName);
         }
@@ -117,6 +120,9 @@ namespace Microsoft.eShopOnContainers.BuildingBlocks.EventBusRabbitMQ
         {
             var eventName = _subsManager.GetEventKey<T>();
             DoInternalSubscription(eventName);
+
+            _logger.LogInformation("Subscribing to event {EventName} with {EventHandler}", eventName, typeof(TH).GetGenericTypeName());
+
             _subsManager.AddSubscription<T, TH>();
         }
 
@@ -140,9 +146,13 @@ namespace Microsoft.eShopOnContainers.BuildingBlocks.EventBusRabbitMQ
         }
 
         public void Unsubscribe<T, TH>()
-            where TH : IIntegrationEventHandler<T>
             where T : IntegrationEvent
+            where TH : IIntegrationEventHandler<T>
         {
+            var eventName = _subsManager.GetEventKey<T>();
+
+            _logger.LogInformation("Unsubscribing from event {EventName}", eventName);
+
             _subsManager.RemoveSubscription<T, TH>();
         }
 
@@ -215,7 +225,7 @@ namespace Microsoft.eShopOnContainers.BuildingBlocks.EventBusRabbitMQ
                     foreach (var subscription in subscriptions)
                     {
                         if (subscription.IsDynamic)
-                        { 
+                        {
                             var handler = scope.ResolveOptional(subscription.HandlerType) as IDynamicIntegrationEventHandler;
                             if (handler == null) continue;
                             dynamic eventData = JObject.Parse(message);

src/BuildingBlocks/EventBus/EventBusServiceBus/EventBusServiceBus.cs

@@ -27,7 +27,7 @@
             ILifetimeScope autofac)
         {
             _serviceBusPersisterConnection = serviceBusPersisterConnection;
-            _logger = logger;
+            _logger = logger ?? throw new ArgumentNullException(nameof(logger));
             _subsManager = subsManager ?? new InMemoryEventBusSubscriptionsManager();
 
             _subscriptionClient = new SubscriptionClient(serviceBusPersisterConnection.ServiceBusConnectionStringBuilder,
@@ -61,6 +61,8 @@
         public void SubscribeDynamic<TH>(string eventName)
             where TH : IDynamicIntegrationEventHandler
         {
+            _logger.LogInformation("Subscribing to dynamic event {EventName} with {EventHandler}", eventName, nameof(TH));
+
             _subsManager.AddDynamicSubscription<TH>(eventName);
         }
 
@@ -87,6 +89,8 @@
                 }
             }
 
+            _logger.LogInformation("Subscribing to event {EventName} with {EventHandler}", eventName, nameof(TH));
+
             _subsManager.AddSubscription<T, TH>();
         }
 
@@ -108,12 +112,16 @@
                 _logger.LogWarning("The messaging entity {eventName} Could not be found.", eventName);
             }
 
+            _logger.LogInformation("Unsubscribing from event {EventName}", eventName);
+
             _subsManager.RemoveSubscription<T, TH>();
         }
 
         public void UnsubscribeDynamic<TH>(string eventName)
             where TH : IDynamicIntegrationEventHandler
         {
+            _logger.LogInformation("Unsubscribing from dynamic event {EventName}", eventName);
+
             _subsManager.RemoveDynamicSubscription<TH>(eventName);
         }
 
@@ -136,17 +144,16 @@
                         await _subscriptionClient.CompleteAsync(message.SystemProperties.LockToken);
                     }
                 },
-               new MessageHandlerOptions(ExceptionReceivedHandler) { MaxConcurrentCalls = 10, AutoComplete = false });
+                new MessageHandlerOptions(ExceptionReceivedHandler) { MaxConcurrentCalls = 10, AutoComplete = false });
         }
 
         private Task ExceptionReceivedHandler(ExceptionReceivedEventArgs exceptionReceivedEventArgs)
         {
-            Console.WriteLine($"Message handler encountered an exception {exceptionReceivedEventArgs.Exception}.");
+            var ex = exceptionReceivedEventArgs.Exception;
             var context = exceptionReceivedEventArgs.ExceptionReceivedContext;
-            Console.WriteLine("Exception context for troubleshooting:");
-            Console.WriteLine($"- Endpoint: {context.Endpoint}");
-            Console.WriteLine($"- Entity Path: {context.EntityPath}");
-            Console.WriteLine($"- Executing Action: {context.Action}");
+
+            _logger.LogError(ex, "ERROR handling message: {ExceptionMessage} - Context: {@ExceptionContext}", ex.Message, context);
+
             return Task.CompletedTask;
         }
 
@@ -172,7 +179,7 @@
                             var handler = scope.ResolveOptional(subscription.HandlerType);
                             if (handler == null) continue;
                             var eventType = _subsManager.GetEventTypeByName(eventName);
-                            var integrationEvent = JsonConvert.DeserializeObject(message, eventType);                            
+                            var integrationEvent = JsonConvert.DeserializeObject(message, eventType);
                             var concreteType = typeof(IIntegrationEventHandler<>).MakeGenericType(eventType);
                             await (Task)concreteType.GetMethod("Handle").Invoke(handler, new object[] { integrationEvent });
                         }

src/Services/Basket/Basket.FunctionalTests/BasketScenarios.cs

@@ -5,7 +5,7 @@ using System;
 using System.Net.Http;
 using System.Text;
 using System.Threading.Tasks;
-using WebMVC.ServicesModelDTOs;
+using WebMVC.Services.ModelDTOs;
 using Xunit;
 
 namespace Basket.FunctionalTests

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

@@ -3,6 +3,7 @@ using Microsoft.Extensions.Logging;
 using System.Linq;
 using System.Threading;
 using System.Threading.Tasks;
+using Microsoft.eShopOnContainers.BuildingBlocks.EventBus.Extensions;
 
 namespace Ordering.API.Application.Behaviors
 {

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

@@ -1,5 +1,6 @@
 using MediatR;
 using Microsoft.EntityFrameworkCore;
+using Microsoft.eShopOnContainers.BuildingBlocks.EventBus.Extensions;
 using Microsoft.eShopOnContainers.Services.Ordering.Infrastructure;
 using Microsoft.Extensions.Logging;
 using Ordering.API.Application.IntegrationEvents;

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

@@ -5,6 +5,7 @@ using Ordering.Domain.Exceptions;
 using System.Linq;
 using System.Threading;
 using System.Threading.Tasks;
+using Microsoft.eShopOnContainers.BuildingBlocks.EventBus.Extensions;
 
 namespace Ordering.API.Application.Behaviors
 {

src/Services/Ordering/Ordering.API/Application/Commands/IdentifiedCommandHandler.cs

@@ -1,4 +1,5 @@
 using MediatR;
+using Microsoft.eShopOnContainers.BuildingBlocks.EventBus.Extensions;
 using Microsoft.eShopOnContainers.Services.Ordering.Infrastructure.Idempotency;
 using Microsoft.Extensions.Logging;
 using Ordering.API.Application.Behaviors;

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

@@ -1,5 +1,6 @@
 using MediatR;
 using Microsoft.eShopOnContainers.BuildingBlocks.EventBus.Abstractions;
+using Microsoft.eShopOnContainers.BuildingBlocks.EventBus.Extensions;
 using Microsoft.eShopOnContainers.Services.Ordering.API;
 using Microsoft.eShopOnContainers.Services.Ordering.Domain.AggregatesModel.OrderAggregate;
 using Microsoft.Extensions.Logging;

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

@@ -2,6 +2,7 @@
 {
     using MediatR;
     using Microsoft.eShopOnContainers.BuildingBlocks.EventBus.Abstractions;
+    using Microsoft.eShopOnContainers.BuildingBlocks.EventBus.Extensions;
     using Microsoft.eShopOnContainers.Services.Ordering.API;
     using Microsoft.eShopOnContainers.Services.Ordering.Domain.AggregatesModel.OrderAggregate;
     using Microsoft.Extensions.Logging;
@@ -9,8 +10,8 @@
     using Ordering.API.Application.Commands;
     using Ordering.API.Application.IntegrationEvents.Events;
     using Serilog.Context;
-    using System;
     using System.Threading.Tasks;
+    using System;
 
     public class OrderPaymentFailedIntegrationEventHandler : 
         IIntegrationEventHandler<OrderPaymentFailedIntegrationEvent>

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

@@ -2,6 +2,7 @@
 {
     using MediatR;
     using Microsoft.eShopOnContainers.BuildingBlocks.EventBus.Abstractions;
+    using Microsoft.eShopOnContainers.BuildingBlocks.EventBus.Extensions;
     using Microsoft.eShopOnContainers.Services.Ordering.API;
     using Microsoft.eShopOnContainers.Services.Ordering.Domain.AggregatesModel.OrderAggregate;
     using Microsoft.Extensions.Logging;

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

@@ -1,6 +1,7 @@
 namespace Ordering.API.Application.IntegrationEvents.EventHandling
 {
     using Microsoft.eShopOnContainers.BuildingBlocks.EventBus.Abstractions;
+    using Microsoft.eShopOnContainers.BuildingBlocks.EventBus.Extensions;
     using System.Threading.Tasks;
     using Events;
     using Microsoft.eShopOnContainers.Services.Ordering.Domain.AggregatesModel.OrderAggregate;

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

@@ -1,6 +1,7 @@
 namespace Ordering.API.Application.IntegrationEvents.EventHandling
 {
     using Microsoft.eShopOnContainers.BuildingBlocks.EventBus.Abstractions;
+    using Microsoft.eShopOnContainers.BuildingBlocks.EventBus.Extensions;
     using System.Threading.Tasks;
     using Events;
     using System.Linq;

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

@@ -1,13 +1,14 @@
-using System;
-using MediatR;
+using MediatR;
 using Microsoft.eShopOnContainers.BuildingBlocks.EventBus.Abstractions;
-using System.Threading.Tasks;
+using Microsoft.eShopOnContainers.BuildingBlocks.EventBus.Extensions;
 using Microsoft.eShopOnContainers.Services.Ordering.API.Application.Commands;
+using Microsoft.eShopOnContainers.Services.Ordering.API;
 using Microsoft.Extensions.Logging;
+using Ordering.API.Application.Behaviors;
 using Ordering.API.Application.IntegrationEvents.Events;
 using Serilog.Context;
-using Microsoft.eShopOnContainers.Services.Ordering.API;
-using Ordering.API.Application.Behaviors;
+using System.Threading.Tasks;
+using System;
 
 namespace Ordering.API.Application.IntegrationEvents.EventHandling
 {

src/Services/Ordering/Ordering.API/Controllers/OrdersController.cs

@@ -1,6 +1,7 @@
 using MediatR;
 using Microsoft.AspNetCore.Authorization;
 using Microsoft.AspNetCore.Mvc;
+using Microsoft.eShopOnContainers.BuildingBlocks.EventBus.Extensions;
 using Microsoft.eShopOnContainers.Services.Ordering.API.Application.Commands;
 using Microsoft.eShopOnContainers.Services.Ordering.API.Application.Queries;
 using Microsoft.eShopOnContainers.Services.Ordering.API.Infrastructure.Services;

src/Services/Ordering/Ordering.FunctionalTests/OrderingScenarios.cs

@@ -3,7 +3,7 @@ using System.Net;
 using System.Net.Http;
 using System.Text;
 using System.Threading.Tasks;
-using WebMVC.ServicesModelDTOs;
+using WebMVC.Services.ModelDTOs;
 using Xunit;
 
 namespace Ordering.FunctionalTests