diff --git a/Examples/08-MessageHandlerLogging/08-MessageHandlerLogging.csproj b/Examples/08-MessageHandlerLogging/08-MessageHandlerLogging.csproj new file mode 100644 index 0000000..12b218e --- /dev/null +++ b/Examples/08-MessageHandlerLogging/08-MessageHandlerLogging.csproj @@ -0,0 +1,22 @@ + + + + Exe + netcoreapp3.1 + _08_MessageHandlerLogging + + + + + + + + + + + + + + + + diff --git a/Examples/08-MessageHandlerLogging/Program.cs b/Examples/08-MessageHandlerLogging/Program.cs new file mode 100644 index 0000000..2937dd9 --- /dev/null +++ b/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(); + + + var helper = new ExampleConsoleApp(dependencyResolver); + helper.Run(MainAsync); + + seriLogger.Dispose(); + } + + + internal static async Task MainAsync(IDependencyResolver dependencyResolver, Func 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(); + await publisher.Publish(new PublishSubscribeMessage + { + Greeting = "Hello message handler logging!" + }); + + await subscriber.Resume(); + await waitForDone(); + } + } +} diff --git a/Examples/08-MessageHandlerLogging/SlowMessageController.cs b/Examples/08-MessageHandlerLogging/SlowMessageController.cs new file mode 100644 index 0000000..33695b2 --- /dev/null +++ b/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(); + } + } +} \ No newline at end of file diff --git a/Examples/08-MessageHandlerLogging/SpeedyMessageController.cs b/Examples/08-MessageHandlerLogging/SpeedyMessageController.cs new file mode 100644 index 0000000..0409d10 --- /dev/null +++ b/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); + } + } +} \ No newline at end of file diff --git a/Tapeti.Serilog/ConfigExtensions.cs b/Tapeti.Serilog/ConfigExtensions.cs new file mode 100644 index 0000000..23ba4f9 --- /dev/null +++ b/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 +{ + /// + /// ITapetiConfigBuilder extension for enabling message handler logging. + /// + public static class ConfigExtensions + { + /// + /// Enables message handler logging. + /// + /// + /// The time (in milliseconds) a message handler is allowed to run without a warning being logged + /// The default log level when a message handler completes within the elapsedWarningTreshold + /// + public static ITapetiConfigBuilder WithMessageHandlerLogging(this ITapetiConfigBuilder config, + double elapsedWarningTreshold = 500, LogEventLevel defaultLevel = LogEventLevel.Debug) + { + config.Use(new MessageHandlerLoggingBindingMiddleware(elapsedWarningTreshold, defaultLevel)); + return config; + } + } +} diff --git a/Tapeti.Serilog/Default/DiagnosticContext.cs b/Tapeti.Serilog/Default/DiagnosticContext.cs new file mode 100644 index 0000000..3c9f849 --- /dev/null +++ b/Tapeti.Serilog/Default/DiagnosticContext.cs @@ -0,0 +1,61 @@ +using System.Collections.Generic; +using Serilog.Core; +using Serilog.Events; + +namespace Tapeti.Serilog.Default +{ + /// + /// Implements the IDiagnosticContext interface for a Serilog ILogger. + /// + public class DiagnosticContext : IDiagnosticContext + { + private readonly global::Serilog.ILogger logger; + private readonly List properties = new List(); + + + /// + /// Creates a new instance of a DiagnosticContext + /// + /// The Serilog ILogger which will be enriched + 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); + } + + + /// + /// Returns a Serilog ILogger which is enriched with the properties set by this DiagnosticContext + /// + public global::Serilog.ILogger GetEnrichedLogger() + { + return properties.Count > 0 + ? logger.ForContext(new LogEventPropertiesEnricher(properties)) + : logger; + } + + + private class LogEventPropertiesEnricher : ILogEventEnricher + { + private readonly IEnumerable properties; + + public LogEventPropertiesEnricher(IEnumerable properties) + { + this.properties = properties; + } + + + public void Enrich(LogEvent logEvent, ILogEventPropertyFactory propertyFactory) + { + foreach (var property in properties) + logEvent.AddOrUpdateProperty(property); + } + } + } +} diff --git a/Tapeti.Serilog/DiagnosticContextPayload.cs b/Tapeti.Serilog/DiagnosticContextPayload.cs new file mode 100644 index 0000000..4bd932f --- /dev/null +++ b/Tapeti.Serilog/DiagnosticContextPayload.cs @@ -0,0 +1,23 @@ +using Tapeti.Config; + +namespace Tapeti.Serilog +{ + /// + /// Stores the IDiagnosticContext for a message handler. + /// + public class DiagnosticContextPayload : IMessageContextPayload + { + /// + /// Initializes a DiagnosticContext payload. + /// + public DiagnosticContextPayload(IDiagnosticContext diagnosticContext) + { + DiagnosticContext = diagnosticContext; + } + + /// + /// The diagnostic context for the current message handler. + /// + public IDiagnosticContext DiagnosticContext { get; } + } +} diff --git a/Tapeti.Serilog/IDiagnosticContext.cs b/Tapeti.Serilog/IDiagnosticContext.cs new file mode 100644 index 0000000..544c395 --- /dev/null +++ b/Tapeti.Serilog/IDiagnosticContext.cs @@ -0,0 +1,23 @@ +namespace Tapeti.Serilog +{ + /// + /// Collects diagnostic information for message handler logging when using the + /// MessageHandlerLogging middleware. + /// + /// + /// 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. + /// + public interface IDiagnosticContext + { + /// + /// 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. + /// + /// The name of the property. Must be non-empty. + /// The property value. + /// 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. + void Set(string propertyName, object value, bool destructureObjects = false); + } +} diff --git a/Tapeti.Serilog/Middleware/MessageHandlerLoggingBindingMiddleware.cs b/Tapeti.Serilog/Middleware/MessageHandlerLoggingBindingMiddleware.cs new file mode 100644 index 0000000..d3ba51d --- /dev/null +++ b/Tapeti.Serilog/Middleware/MessageHandlerLoggingBindingMiddleware.cs @@ -0,0 +1,53 @@ +using System; +using System.Linq; +using Serilog.Events; +using Tapeti.Config; + +namespace Tapeti.Serilog.Middleware +{ + /// + /// Implements the middleware which binds any IDiagnosticContext parameter in message handlers. + /// + public class MessageHandlerLoggingBindingMiddleware : IControllerBindingMiddleware + { + private readonly IControllerMessageMiddleware controllerMessageMiddleware; + + + /// + /// Creates a new instance of the middleware which binds any IDiagnosticContext parameter in message handlers. + /// + /// + /// + public MessageHandlerLoggingBindingMiddleware(double elapsedWarningTreshold = 500, LogEventLevel defaultLevel = LogEventLevel.Debug) + { + controllerMessageMiddleware = new MessageHandlerLoggingMessageMiddleware(elapsedWarningTreshold, defaultLevel); + } + + + /// + 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(out var diagnosticContextPayload) + ? diagnosticContextPayload.DiagnosticContext + : null; + } + } +} diff --git a/Tapeti.Serilog/Middleware/MessageHandlerLoggingMessageMiddleware.cs b/Tapeti.Serilog/Middleware/MessageHandlerLoggingMessageMiddleware.cs new file mode 100644 index 0000000..c8e6e73 --- /dev/null +++ b/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 +{ + /// + /// Implements the message handler logging middleware which provides an IDiagnosticContext for + /// the message handler and logs the result. + /// + public class MessageHandlerLoggingMessageMiddleware : IControllerMessageMiddleware + { + private readonly double elapsedWarningTreshold; + private readonly LogEventLevel defaultLevel; + + /// + /// Creates a new instance of the message handler logging middleware which provides an IDiagnosticContext + /// for the message handler and logs the result. + /// + /// The time (in milliseconds) a message handler is allowed to run without a warning being logged + /// The default log level when a message handler completes within the elapsedWarningTreshold + public MessageHandlerLoggingMessageMiddleware(double elapsedWarningTreshold = 500, LogEventLevel defaultLevel = LogEventLevel.Debug) + { + this.elapsedWarningTreshold = elapsedWarningTreshold; + this.defaultLevel = defaultLevel; + } + + /// + public async Task Handle(IMessageContext context, Func next) + { + var logger = context.Config.DependencyResolver.Resolve(); + + 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(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); + } + } +} diff --git a/Tapeti.Serilog/Tapeti.Serilog.csproj b/Tapeti.Serilog/Tapeti.Serilog.csproj index 69efdee..73171f4 100644 --- a/Tapeti.Serilog/Tapeti.Serilog.csproj +++ b/Tapeti.Serilog/Tapeti.Serilog.csproj @@ -33,6 +33,6 @@ - + diff --git a/Tapeti.sln b/Tapeti.sln index 528cc7f..40be3b4 100644 --- a/Tapeti.sln +++ b/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}