[Work Item #11] Extend the library to make use of Application Insights logging.

src/ClearHostedEndpoint.Tests/Behaviors/TimingBehaviorTests.cs

@@ -0,0 +1,138 @@
+using ClearMeasure.HostedEndpoint.Behaviors;
+using FluentAssertions;
+using Moq;
+using NServiceBus.Pipeline;
+using Serilog;
+using Xunit;
+
+namespace ClearHostedEndpoint.Tests.Behaviors;
+
+public class TimingBehaviorTests
+{
+    [Fact]
+    public void Constructor_WithValidLogger_ShouldNotThrow()
+    {
+        var logger = Mock.Of<ILogger>();
+
+        var act = () => new TimingBehavior(logger);
+
+        act.Should().NotThrow();
+    }
+
+    [Fact]
+    public void Constructor_WithNullLogger_ShouldThrowArgumentNullException()
+    {
+        var act = () => new TimingBehavior(null!);
+
+        act.Should().Throw<ArgumentNullException>()
+            .WithParameterName("logger");
+    }
+
+    [Fact]
+    public async Task Invoke_ShouldLogStartAndCompletion()
+    {
+        var loggerMock = new Mock<ILogger>();
+        var behavior = new TimingBehavior(loggerMock.Object);
+        var context = CreateMockContext();
+        var nextCalled = false;
+
+        await behavior.Invoke(context, () =>
+        {
+            nextCalled = true;
+            return Task.CompletedTask;
+        });
+
+        nextCalled.Should().BeTrue();
+
+        loggerMock.Verify(
+            l => l.Information(
+                It.Is<string>(s => s.Contains("starting to process")),
+                It.IsAny<object[]>()),
+            Times.Once);
+
+        loggerMock.Verify(
+            l => l.Information(
+                It.Is<string>(s => s.Contains("completed processing")),
+                It.IsAny<object[]>()),
+            Times.Once);
+    }
+
+    [Fact]
+    public async Task Invoke_WhenHandlerThrows_ShouldLogErrorAndRethrow()
+    {
+        var loggerMock = new Mock<ILogger>();
+        var behavior = new TimingBehavior(loggerMock.Object);
+        var context = CreateMockContext();
+        var expectedException = new InvalidOperationException("Test exception");
+
+        var act = async () => await behavior.Invoke(context, () => throw expectedException);
+
+        await act.Should().ThrowAsync<InvalidOperationException>()
+            .WithMessage("Test exception");
+
+        loggerMock.Verify(
+            l => l.Error(
+                It.IsAny<Exception>(),
+                It.Is<string>(s => s.Contains("failed processing")),
+                It.IsAny<object[]>()),
+            Times.Once);
+    }
+
+    [Fact]
+    public async Task Invoke_ShouldCaptureElapsedTime()
+    {
+        var loggerMock = new Mock<ILogger>();
+        var behavior = new TimingBehavior(loggerMock.Object);
+        var context = CreateMockContext();
+
+        await behavior.Invoke(context, async () =>
+        {
+            await Task.Delay(50);
+        });
+
+        loggerMock.Verify(
+            l => l.Information(
+                It.Is<string>(s => s.Contains("completed processing") && s.Contains("ElapsedMilliseconds")),
+                It.IsAny<object[]>()),
+            Times.Once);
+    }
+
+    [Fact]
+    public async Task Invoke_ShouldIncludeHandlerAndMessageTypeInLogs()
+    {
+        var loggerMock = new Mock<ILogger>();
+        var behavior = new TimingBehavior(loggerMock.Object);
+        var context = CreateMockContext();
+
+        await behavior.Invoke(context, () => Task.CompletedTask);
+
+        loggerMock.Verify(
+            l => l.Information(
+                It.Is<string>(s => s.Contains("HandlerType") && s.Contains("MessageType")),
+                It.IsAny<object[]>()),
+            Times.AtLeastOnce);
+    }
+
+    private static IInvokeHandlerContext CreateMockContext()
+    {
+        var message = new TestMessage();
+        var handler = new TestHandler();
+
+        var messageHandlerMock = new Mock<MessageHandler>();
+        messageHandlerMock.Setup(h => h.Instance).Returns(handler);
+
+        var contextMock = new Mock<IInvokeHandlerContext>();
+        contextMock.Setup(c => c.MessageBeingHandled).Returns(message);
+        contextMock.Setup(c => c.MessageHandler).Returns(messageHandlerMock.Object);
+
+        return contextMock.Object;
+    }
+
+    private class TestMessage
+    {
+    }
+
+    private class TestHandler
+    {
+    }
+}

src/ClearHostedEndpoint/Behaviors/TimingBehavior.cs

@@ -0,0 +1,63 @@
+using NServiceBus.Pipeline;
+using Serilog;
+using System.Diagnostics;
+
+namespace ClearMeasure.HostedEndpoint.Behaviors;
+
+/// <summary>
+/// NServiceBus pipeline behavior that captures and logs handler execution timing metrics.
+/// </summary>
+public class TimingBehavior : Behavior<IInvokeHandlerContext>
+{
+    private readonly ILogger _logger;
+
+    /// <summary>
+    /// Initializes a new instance of the <see cref="TimingBehavior"/> class.
+    /// </summary>
+    /// <param name="logger">The Serilog logger instance.</param>
+    public TimingBehavior(ILogger logger)
+    {
+        _logger = logger ?? throw new ArgumentNullException(nameof(logger));
+    }
+
+    /// <summary>
+    /// Invoked when a message is being handled.
+    /// </summary>
+    public override async Task Invoke(IInvokeHandlerContext context, Func<Task> next)
+    {
+        var stopwatch = Stopwatch.StartNew();
+        var messageType = context.MessageBeingHandled.GetType().Name;
+        var handlerType = context.MessageHandler.Instance.GetType().Name;
+
+        try
+        {
+            _logger.Information(
+                "Handler {HandlerType} starting to process message {MessageType}",
+                handlerType,
+                messageType);
+
+            await next();
+
+            stopwatch.Stop();
+
+            _logger.Information(
+                "Handler {HandlerType} completed processing message {MessageType} in {ElapsedMilliseconds}ms",
+                handlerType,
+                messageType,
+                stopwatch.ElapsedMilliseconds);
+        }
+        catch (Exception ex)
+        {
+            stopwatch.Stop();
+
+            _logger.Error(
+                ex,
+                "Handler {HandlerType} failed processing message {MessageType} after {ElapsedMilliseconds}ms",
+                handlerType,
+                messageType,
+                stopwatch.ElapsedMilliseconds);
+
+            throw;
+        }
+    }
+}

src/ClearHostedEndpoint/ClearHostedEndpoint.cs

@@ -1,5 +1,6 @@
 using Microsoft.Extensions.DependencyInjection;
 using System.Data.Common;
+using ClearMeasure.HostedEndpoint.Behaviors;
 using ClearMeasure.HostedEndpoint.Exceptions;
 using ClearMeasure.HostedService;
 using Microsoft.Data.SqlClient;
@@ -17,7 +18,7 @@
     private IEndpointInstance? _endpointInstance;
     private IServiceCollection? _nsbServiceCollection;
 
     protected ClearHostedEndpoint(IConfiguration configuration) : base(configuration)
     {
     }
 
@@ -138,6 +139,11 @@
         // Configure concurrency
         endpointConfiguration.LimitMessageProcessingConcurrencyTo(EndpointOptions.MaxConcurrency);
 
+        // Register timing behavior for metrics
+        endpointConfiguration.Pipeline.Register(
+            behavior: typeof(TimingBehavior),
+            description: "Captures and logs handler execution timing metrics");
+
         return endpointConfiguration;
     }
 

src/ClearHostedEndpoint/ClearMeasure.HostedEndpoint.csproj

@@ -17,6 +17,7 @@
 
   <ItemGroup>
     <PackageReference Include="NServiceBus" Version="9.2.5" />
+    <PackageReference Include="NServiceBus.Metrics" Version="5.0.0" />
     <PackageReference Include="NServiceBus.Persistence.Sql" Version="8.2.0" />
     <PackageReference Include="Microsoft.Data.SqlClient" Version="6.0.1" />
   </ItemGroup>

src/ClearHostedService.Tests/ClearHostedService.Tests.csproj

@@ -17,6 +17,7 @@
     </PackageReference>
     <PackageReference Include="Moq" Version="4.20.72" />
     <PackageReference Include="FluentAssertions" Version="7.0.0" />
+    <PackageReference Include="Serilog.Sinks.ApplicationInsights" Version="4.0.0" />
   </ItemGroup>
 
   <ItemGroup>

src/ClearHostedService.Tests/Infrastructure/Configuration/LoggingOptionsTests.cs

@@ -0,0 +1,91 @@
+using ClearMeasure.HostedService.Configuration;
+using FluentAssertions;
+using Serilog;
+using Serilog.Events;
+using Xunit;
+
+namespace QuickHostedService.Tests.Infrastructure.Configuration;
+
+public class LoggingOptionsTests
+{
+    [Fact]
+    public void DefaultValues_ShouldBeSetCorrectly()
+    {
+        var options = new LoggingOptions();
+
+        options.LogLevel.Should().Be(LogEventLevel.Information);
+        options.LogDirectory.Should().Be("logs");
+        options.RollingInterval.Should().Be(RollingInterval.Day);
+        options.EnableConsoleLogging.Should().BeTrue();
+        options.EnableFileLogging.Should().BeTrue();
+        options.EnableApplicationInsights.Should().BeFalse();
+        options.ApplicationInsightsConnectionString.Should().BeNull();
+        options.OutputTemplate.Should().NotBeNullOrEmpty();
+    }
+
+    [Fact]
+    public void ApplicationInsightsConnectionString_CanBeSet()
+    {
+        var options = new LoggingOptions
+        {
+            ApplicationInsightsConnectionString = "InstrumentationKey=12345678-1234-1234-1234-123456789012"
+        };
+
+        options.ApplicationInsightsConnectionString.Should().Be("InstrumentationKey=12345678-1234-1234-1234-123456789012");
+    }
+
+    [Fact]
+    public void EnableApplicationInsights_CanBeSet()
+    {
+        var options = new LoggingOptions
+        {
+            EnableApplicationInsights = true
+        };
+
+        options.EnableApplicationInsights.Should().BeTrue();
+    }
+
+    [Fact]
+    public void ApplicationInsightsConnectionString_CanBeNull()
+    {
+        var options = new LoggingOptions
+        {
+            ApplicationInsightsConnectionString = null
+        };
+
+        options.ApplicationInsightsConnectionString.Should().BeNull();
+    }
+
+    [Fact]
+    public void LogLevel_CanBeChanged()
+    {
+        var options = new LoggingOptions
+        {
+            LogLevel = LogEventLevel.Debug
+        };
+
+        options.LogLevel.Should().Be(LogEventLevel.Debug);
+    }
+
+    [Fact]
+    public void EnableConsoleLogging_CanBeDisabled()
+    {
+        var options = new LoggingOptions
+        {
+            EnableConsoleLogging = false
+        };
+
+        options.EnableConsoleLogging.Should().BeFalse();
+    }
+
+    [Fact]
+    public void EnableFileLogging_CanBeDisabled()
+    {
+        var options = new LoggingOptions
+        {
+            EnableFileLogging = false
+        };
+
+        options.EnableFileLogging.Should().BeFalse();
+    }
+}

src/ClearHostedService.Tests/Infrastructure/ConfigurationTests.cs

@@ -21,7 +21,7 @@ public void Constructor_ShouldSetDefaultValues()
         options.EnableConsoleLogging.Should().BeTrue();
         options.EnableFileLogging.Should().BeTrue();
         options.EnableApplicationInsights.Should().BeFalse();
-        options.ApplicationInsightsInstrumentationKey.Should().BeNull();
+        options.ApplicationInsightsConnectionString.Should().BeNull();
     }
 
     [Fact]
@@ -37,7 +37,7 @@ public void Properties_ShouldBeSettable()
         options.EnableConsoleLogging = false;
         options.EnableFileLogging = false;
         options.EnableApplicationInsights = true;
-        options.ApplicationInsightsInstrumentationKey = "test-key";
+        options.ApplicationInsightsConnectionString = "InstrumentationKey=test-key";
 
         // Assert
         options.LogLevel.Should().Be(LogEventLevel.Debug);
@@ -46,7 +46,7 @@ public void Properties_ShouldBeSettable()
         options.EnableConsoleLogging.Should().BeFalse();
         options.EnableFileLogging.Should().BeFalse();
         options.EnableApplicationInsights.Should().BeTrue();
-        options.ApplicationInsightsInstrumentationKey.Should().Be("test-key");
+        options.ApplicationInsightsConnectionString.Should().Be("InstrumentationKey=test-key");
     }
 }