Added Message Handler performance logging to Tapeti.Serilog

Examples/08-MessageHandlerLogging/08-MessageHandlerLogging.csproj

@@ -0,0 +1,22 @@
+<Project Sdk="Microsoft.NET.Sdk">
+
+  <PropertyGroup>
+    <OutputType>Exe</OutputType>
+    <TargetFramework>netcoreapp3.1</TargetFramework>
+    <RootNamespace>_08_MessageHandlerLogging</RootNamespace>
+  </PropertyGroup>
+
+  <ItemGroup>
+    <PackageReference Include="Serilog.Sinks.Console" Version="4.0.0" />
+    <PackageReference Include="SimpleInjector" Version="5.3.0" />
+  </ItemGroup>
+
+  <ItemGroup>
+    <ProjectReference Include="..\..\Tapeti.Serilog\Tapeti.Serilog.csproj" />
+    <ProjectReference Include="..\ExampleLib\ExampleLib.csproj" />
+    <ProjectReference Include="..\Messaging.TapetiExample\Messaging.TapetiExample.csproj" />
+    <ProjectReference Include="..\..\Tapeti.SimpleInjector\Tapeti.SimpleInjector.csproj" />
+    <ProjectReference Include="..\..\Tapeti\Tapeti.csproj" />
+  </ItemGroup>
+
+</Project>

Examples/08-MessageHandlerLogging/Program.cs

@@ -0,0 +1,62 @@
+using System;
+using System.Threading.Tasks;
+using ExampleLib;
+using Messaging.TapetiExample;
+using Serilog;
+using Serilog.Events;
+using SimpleInjector;
+using Tapeti;
+using Tapeti.Serilog;
+using Tapeti.SimpleInjector;
+using ILogger = Tapeti.ILogger;
+
+namespace _08_MessageHandlerLogging
+{
+    public class Program
+    {
+        public static void Main()
+        {
+            var container = new Container();
+            var dependencyResolver = new SimpleInjectorDependencyResolver(container);
+
+            var seriLogger = new LoggerConfiguration()
+                .MinimumLevel.Debug()
+                
+                // Include {Properties} or specific keys in the output template to see properties added to the diagnostic context
+                .WriteTo.Console(outputTemplate: "[{Timestamp:HH:mm:ss} {Level:u3}] {Message:lj} {Properties}{NewLine}{Exception}")
+                .CreateLogger();
+
+            container.RegisterInstance((Serilog.ILogger)seriLogger);
+            container.Register<ILogger, TapetiSeriLogger.WithMessageLogging>();
+            
+
+            var helper = new ExampleConsoleApp(dependencyResolver);
+            helper.Run(MainAsync);
+
+            seriLogger.Dispose();
+        }
+
+
+        internal static async Task MainAsync(IDependencyResolver dependencyResolver, Func<Task> waitForDone)
+        {
+            var config = new TapetiConfig(dependencyResolver)
+                .WithMessageHandlerLogging()
+                .RegisterAllControllers()
+                .Build();
+
+
+            await using var connection = new TapetiConnection(config);
+            var subscriber = await connection.Subscribe(false);
+
+
+            var publisher = dependencyResolver.Resolve<IPublisher>();
+            await publisher.Publish(new PublishSubscribeMessage
+            {
+                Greeting = "Hello message handler logging!"
+            });
+            
+            await subscriber.Resume();
+            await waitForDone();
+        }
+    }
+}

Examples/08-MessageHandlerLogging/SlowMessageController.cs

@@ -0,0 +1,31 @@
+using System;
+using System.Threading.Tasks;
+using ExampleLib;
+using Messaging.TapetiExample;
+using Tapeti.Annotations;
+
+namespace _08_MessageHandlerLogging
+{
+    [MessageController]
+    [DynamicQueue("tapeti.example.08.slow")]
+    public class SlowMessageController
+    {
+        private readonly IExampleState exampleState;
+
+
+        public SlowMessageController(IExampleState exampleState)
+        {
+            this.exampleState = exampleState;
+        }
+
+
+        public async Task GimmeASec(PublishSubscribeMessage message)
+        {
+            Console.WriteLine("Received message (in slow controller): " + message.Greeting);
+
+            await Task.Delay(1000);
+            
+            exampleState.Done();
+        }
+    }
+}

Examples/08-MessageHandlerLogging/SpeedyMessageController.cs

@@ -0,0 +1,20 @@
+using System;
+using Messaging.TapetiExample;
+using Tapeti.Annotations;
+using Tapeti.Serilog;
+
+namespace _08_MessageHandlerLogging
+{
+    [MessageController]
+    [DynamicQueue("tapeti.example.08.speedy")]
+    public class SpeedyMessageController
+    {
+        // ReSharper disable once InconsistentNaming
+        public void IAmSpeed(PublishSubscribeMessage message, IDiagnosticContext diagnosticContext)
+        {
+            diagnosticContext.Set("PropertySetByMessageHandler", 42);
+            
+            Console.WriteLine("Received message (in speedy controller): " + message.Greeting);
+        }
+    }
+}

Tapeti.Serilog/ConfigExtensions.cs

@@ -0,0 +1,28 @@
+using Serilog.Events;
+using Tapeti.Config;
+using Tapeti.Serilog.Middleware;
+
+// ReSharper disable UnusedMember.Global - public API
+
+namespace Tapeti.Serilog
+{
+    /// <summary>
+    /// ITapetiConfigBuilder extension for enabling message handler logging.
+    /// </summary>
+    public static class ConfigExtensions
+    {
+        /// <summary>
+        /// Enables message handler logging.
+        /// </summary>
+        /// <param name="config"></param>
+        /// <param name="elapsedWarningTreshold">The time (in milliseconds) a message handler is allowed to run without a warning being logged</param>
+        /// <param name="defaultLevel">The default log level when a message handler completes within the elapsedWarningTreshold</param>
+        /// <returns></returns>
+        public static ITapetiConfigBuilder WithMessageHandlerLogging(this ITapetiConfigBuilder config, 
+            double elapsedWarningTreshold = 500, LogEventLevel defaultLevel = LogEventLevel.Debug)
+        {
+            config.Use(new MessageHandlerLoggingBindingMiddleware(elapsedWarningTreshold, defaultLevel));
+            return config;
+        }
+    }
+}

Tapeti.Serilog/Default/DiagnosticContext.cs

@@ -0,0 +1,61 @@
+using System.Collections.Generic;
+using Serilog.Core;
+using Serilog.Events;
+
+namespace Tapeti.Serilog.Default
+{
+    /// <summary>
+    /// Implements the IDiagnosticContext interface for a Serilog ILogger.
+    /// </summary>
+    public class DiagnosticContext : IDiagnosticContext
+    {
+        private readonly global::Serilog.ILogger logger;
+        private readonly List<LogEventProperty> properties = new List<LogEventProperty>();
+
+        
+        /// <summary>
+        /// Creates a new instance of a DiagnosticContext
+        /// </summary>
+        /// <param name="logger">The Serilog ILogger which will be enriched</param>
+        public DiagnosticContext(global::Serilog.ILogger logger)
+        {
+            this.logger = logger;
+        }
+        
+
+        public void Set(string propertyName, object value, bool destructureObjects = false)
+        {
+            if (logger.BindProperty(propertyName, value, destructureObjects, out var logEventProperty))
+                properties.Add(logEventProperty);
+        }
+
+
+        /// <summary>
+        /// Returns a Serilog ILogger which is enriched with the properties set by this DiagnosticContext
+        /// </summary>
+        public global::Serilog.ILogger GetEnrichedLogger()
+        {
+            return properties.Count > 0
+                ? logger.ForContext(new LogEventPropertiesEnricher(properties))
+                : logger;
+        }
+
+
+        private class LogEventPropertiesEnricher : ILogEventEnricher
+        {
+            private readonly IEnumerable<LogEventProperty> properties;
+
+            public LogEventPropertiesEnricher(IEnumerable<LogEventProperty> properties)
+            {
+                this.properties = properties;
+            }
+            
+            
+            public void Enrich(LogEvent logEvent, ILogEventPropertyFactory propertyFactory)
+            {
+                foreach (var property in properties)
+                    logEvent.AddOrUpdateProperty(property);
+            }
+        }
+    }
+}

Tapeti.Serilog/DiagnosticContextPayload.cs

@@ -0,0 +1,23 @@
+using Tapeti.Config;
+
+namespace Tapeti.Serilog
+{
+    /// <summary>
+    /// Stores the IDiagnosticContext for a message handler.
+    /// </summary>
+    public class DiagnosticContextPayload : IMessageContextPayload
+    {
+        /// <summary>
+        /// Initializes a DiagnosticContext payload.
+        /// </summary>
+        public DiagnosticContextPayload(IDiagnosticContext diagnosticContext)
+        {
+            DiagnosticContext = diagnosticContext;
+        }
+
+        /// <summary>
+        /// The diagnostic context for the current message handler.
+        /// </summary>
+        public IDiagnosticContext DiagnosticContext { get; }
+    }
+}

Tapeti.Serilog/IDiagnosticContext.cs

@@ -0,0 +1,23 @@
+namespace Tapeti.Serilog
+{
+    /// <summary>
+    /// Collects diagnostic information for message handler logging when using the
+    /// MessageHandlerLogging middleware.
+    /// </summary>
+    /// <remarks>
+    /// This is a one-to-one copy of the IDiagnosticContext in Serilog.Extensions.Hosting which
+    /// saves a reference to that package while allowing similar usage within Tapeti message handlers.
+    /// </remarks>
+    public interface IDiagnosticContext
+    {
+        /// <summary>
+        /// Set the specified property on the current diagnostic context. The property will be collected
+        /// and attached to the event emitted at the completion of the context.
+        /// </summary>
+        /// <param name="propertyName">The name of the property. Must be non-empty.</param>
+        /// <param name="value">The property value.</param>
+        /// <param name="destructureObjects">If true, the value will be serialized as structured
+        /// data if possible; if false, the object will be recorded as a scalar or simple array.</param>
+        void Set(string propertyName, object value, bool destructureObjects = false);
+    }
+}

Tapeti.Serilog/Middleware/MessageHandlerLoggingBindingMiddleware.cs

@@ -0,0 +1,53 @@
+using System;
+using System.Linq;
+using Serilog.Events;
+using Tapeti.Config;
+
+namespace Tapeti.Serilog.Middleware
+{
+    /// <summary>
+    /// Implements the middleware which binds any IDiagnosticContext parameter in message handlers.
+    /// </summary>
+    public class MessageHandlerLoggingBindingMiddleware : IControllerBindingMiddleware
+    {
+        private readonly IControllerMessageMiddleware controllerMessageMiddleware;
+
+
+        /// <summary>
+        /// Creates a new instance of the middleware which binds any IDiagnosticContext parameter in message handlers.
+        /// </summary>
+        /// <param name="elapsedWarningTreshold"></param>
+        /// <param name="defaultLevel"></param>
+        public MessageHandlerLoggingBindingMiddleware(double elapsedWarningTreshold = 500, LogEventLevel defaultLevel = LogEventLevel.Debug)
+        {
+            controllerMessageMiddleware = new MessageHandlerLoggingMessageMiddleware(elapsedWarningTreshold, defaultLevel);
+        }
+        
+        
+        /// <inheritdoc />
+        public void Handle(IControllerBindingContext context, Action next)
+        {
+            RegisterDiagnosticContextParameter(context);
+            
+            // All state is contained within the message context, using a single middleware instance is safe
+            context.Use(controllerMessageMiddleware);
+
+            next();
+        }
+        
+        
+        private static void RegisterDiagnosticContextParameter(IControllerBindingContext context)
+        {
+            foreach (var parameter in context.Parameters.Where(p => !p.HasBinding && p.Info.ParameterType == typeof(IDiagnosticContext)))
+                parameter.SetBinding(DiagnosticContextFactory);
+        }
+
+
+        private static object DiagnosticContextFactory(IMessageContext context)
+        {
+            return context.TryGet<DiagnosticContextPayload>(out var diagnosticContextPayload)
+                ? diagnosticContextPayload.DiagnosticContext
+                : null;
+        }
+    }
+}

Tapeti.Serilog/Middleware/MessageHandlerLoggingMessageMiddleware.cs

@@ -0,0 +1,63 @@
+using System;
+using System.Diagnostics;
+using System.Threading.Tasks;
+using Serilog.Events;
+using Tapeti.Config;
+using Tapeti.Serilog.Default;
+
+namespace Tapeti.Serilog.Middleware
+{
+    /// <summary>
+    /// Implements the message handler logging middleware which provides an IDiagnosticContext for
+    /// the message handler and logs the result.
+    /// </summary>
+    public class MessageHandlerLoggingMessageMiddleware : IControllerMessageMiddleware
+    {
+        private readonly double elapsedWarningTreshold;
+        private readonly LogEventLevel defaultLevel;
+
+        /// <summary>
+        /// Creates a new instance of the message handler logging middleware which provides an IDiagnosticContext
+        /// for the message handler and logs the result.
+        /// </summary>
+        /// <param name="elapsedWarningTreshold">The time (in milliseconds) a message handler is allowed to run without a warning being logged</param>
+        /// <param name="defaultLevel">The default log level when a message handler completes within the elapsedWarningTreshold</param>
+        public MessageHandlerLoggingMessageMiddleware(double elapsedWarningTreshold = 500, LogEventLevel defaultLevel = LogEventLevel.Debug)
+        {
+            this.elapsedWarningTreshold = elapsedWarningTreshold;
+            this.defaultLevel = defaultLevel;
+        }
+        
+        /// <inheritdoc />
+        public async Task Handle(IMessageContext context, Func<Task> next)
+        {
+            var logger = context.Config.DependencyResolver.Resolve<global::Serilog.ILogger>();
+            
+            var diagnosticContext = new DiagnosticContext(logger);
+            context.Store(new DiagnosticContextPayload(diagnosticContext));
+            
+            var stopwatch = new Stopwatch();
+            stopwatch.Start();
+            
+            await next();
+
+            stopwatch.Stop();
+
+            
+            var controllerName = "Unknown";
+            var methodName = "Unknown";
+
+            if (context.TryGet<ControllerMessageContextPayload>(out var controllerMessageContextPayload))
+            {
+                controllerName = controllerMessageContextPayload.Binding.Controller.Name;
+                methodName = controllerMessageContextPayload.Binding.Method.Name;
+            }
+            
+            var level = stopwatch.ElapsedMilliseconds > elapsedWarningTreshold ? LogEventLevel.Warning : defaultLevel;
+            var enrichedLogger = diagnosticContext.GetEnrichedLogger();
+            
+            enrichedLogger.Write(level, "Tapeti: {controller}.{method} completed in {elapsedMilliseconds} ms", 
+                controllerName, methodName, stopwatch.ElapsedMilliseconds);
+        }
+    }
+}

Tapeti.sln

@@ -59,7 +59,9 @@ Project("{9A19103F-16F7-4668-BE54-9A1E7A4F7556}") = "Tapeti.Cmd", "Tapeti.Cmd\Ta
 EndProject
 Project("{9A19103F-16F7-4668-BE54-9A1E7A4F7556}") = "06-StatelessRequestResponse", "Examples\06-StatelessRequestResponse\06-StatelessRequestResponse.csproj", "{152227AA-3165-4550-8997-6EA80C84516E}"
 EndProject
-Project("{FAE04EC0-301F-11D3-BF4B-00C04F79EFBC}") = "07-ParallelizationTest", "Examples\07-ParallelizationTest\07-ParallelizationTest.csproj", "{E69E6BA5-68E7-4A4D-A38C-B2526AA66E96}"
+Project("{9A19103F-16F7-4668-BE54-9A1E7A4F7556}") = "07-ParallelizationTest", "Examples\07-ParallelizationTest\07-ParallelizationTest.csproj", "{E69E6BA5-68E7-4A4D-A38C-B2526AA66E96}"
+EndProject
+Project("{9A19103F-16F7-4668-BE54-9A1E7A4F7556}") = "08-MessageHandlerLogging", "Examples\08-MessageHandlerLogging\08-MessageHandlerLogging.csproj", "{906605A6-2CAB-4B29-B0DD-B735BF265E39}"
 EndProject
 Global
 	GlobalSection(SolutionConfigurationPlatforms) = preSolution
@@ -163,6 +165,10 @@ Global
 		{E69E6BA5-68E7-4A4D-A38C-B2526AA66E96}.Debug|Any CPU.Build.0 = Debug|Any CPU
 		{E69E6BA5-68E7-4A4D-A38C-B2526AA66E96}.Release|Any CPU.ActiveCfg = Release|Any CPU
 		{E69E6BA5-68E7-4A4D-A38C-B2526AA66E96}.Release|Any CPU.Build.0 = Release|Any CPU
+		{906605A6-2CAB-4B29-B0DD-B735BF265E39}.Debug|Any CPU.ActiveCfg = Debug|Any CPU
+		{906605A6-2CAB-4B29-B0DD-B735BF265E39}.Debug|Any CPU.Build.0 = Debug|Any CPU
+		{906605A6-2CAB-4B29-B0DD-B735BF265E39}.Release|Any CPU.ActiveCfg = Release|Any CPU
+		{906605A6-2CAB-4B29-B0DD-B735BF265E39}.Release|Any CPU.Build.0 = Release|Any CPU
 	EndGlobalSection
 	GlobalSection(SolutionProperties) = preSolution
 		HideSolutionNode = FALSE
@@ -191,6 +197,7 @@ Global
 		{C8728BFC-7F97-41BC-956B-690A57B634EC} = {62002327-46B0-4B72-B95A-594CE7F8C80D}
 		{152227AA-3165-4550-8997-6EA80C84516E} = {266B9B94-A4D2-41C2-860C-24A7C3B63B56}
 		{E69E6BA5-68E7-4A4D-A38C-B2526AA66E96} = {266B9B94-A4D2-41C2-860C-24A7C3B63B56}
+		{906605A6-2CAB-4B29-B0DD-B735BF265E39} = {266B9B94-A4D2-41C2-860C-24A7C3B63B56}
 	EndGlobalSection
 	GlobalSection(ExtensibilityGlobals) = postSolution
 		SolutionGuid = {B09CC2BF-B2AF-4CB6-8728-5D1D8E5C50FA}