From 48ae11f3b82adaafa0d5a8b9590b69e8450e880d Mon Sep 17 00:00:00 2001 From: Rolf Kristensen Date: Sun, 29 May 2022 20:11:54 +0200 Subject: [PATCH 1/2] NLogRequestLoggingMiddleware - Added support for custom ShouldLogRequest-delegate --- .../NLogRequestLoggingMiddleware.cs | 77 ++++----------- .../NLogRequestLoggingOptions.cs | 95 ++++++++++++++++++- .../NLogRequestLoggingMiddlewareTests.cs | 94 +++++++++++++++++- 3 files changed, 197 insertions(+), 69 deletions(-) diff --git a/src/NLog.Web.AspNetCore/NLogRequestLoggingMiddleware.cs b/src/NLog.Web.AspNetCore/NLogRequestLoggingMiddleware.cs index ee6d9f3d..2da67f94 100644 --- a/src/NLog.Web.AspNetCore/NLogRequestLoggingMiddleware.cs +++ b/src/NLog.Web.AspNetCore/NLogRequestLoggingMiddleware.cs @@ -1,7 +1,6 @@ using System; using System.Threading.Tasks; using Microsoft.AspNetCore.Http; -using Microsoft.AspNetCore.Http.Features; using Microsoft.Extensions.Logging; namespace NLog.Web @@ -60,76 +59,32 @@ public async Task Invoke(HttpContext httpContext) /// private bool LogHttpRequest(HttpContext httpContext, Exception exception) { - if (exception != null) + var logLevel = _options.ShouldLogRequest?.Invoke(httpContext, exception) ?? Microsoft.Extensions.Logging.LogLevel.None; + if (logLevel != Microsoft.Extensions.Logging.LogLevel.None) { - _logger.LogError(exception, "HttpRequest Exception"); - } - else - { - var statusCode = httpContext.Response?.StatusCode ?? 0; - if (statusCode < 100 || (statusCode >= 400 && statusCode < 600)) - { - _logger.LogWarning("HttpRequest Failed"); - } - else if (IsExcludedHttpRequest(httpContext)) + if (exception != null) { - _logger.LogDebug("HttpRequest Completed"); - } - else if (IsSlowHttpRequest()) - { - _logger.LogWarning("HttpRequest Slow"); + _logger.Log(logLevel, 0, exception, "HttpRequest Exception", Array.Empty()); } else { - _logger.LogInformation("HttpRequest Completed"); - } - } - - return false; // Exception Filter should not suppress the Exception - } - - private bool IsSlowHttpRequest() - { -#if !ASP_NET_CORE2 - var currentActivity = System.Diagnostics.Activity.Current; - var activityStartTime = DateTime.MinValue; - while (currentActivity != null) - { - if (currentActivity.StartTimeUtc > DateTime.MinValue) - activityStartTime = currentActivity.StartTimeUtc; - currentActivity = currentActivity.Parent; - } - if (activityStartTime > DateTime.MinValue) - { - var currentDuration = DateTime.UtcNow - activityStartTime; - if (currentDuration > TimeSpan.FromMilliseconds(_options.DurationThresholdMs)) - { - return true; - } - } -#endif - - return false; - } - - private bool IsExcludedHttpRequest(HttpContext httpContext) - { - if (_options.ExcludeRequestPaths.Count > 0) - { - var requestPath = httpContext.Features.Get()?.Path; - if (string.IsNullOrEmpty(requestPath)) - { - requestPath = httpContext.Request?.Path; - if (string.IsNullOrEmpty(requestPath)) + switch (logLevel) { - return false; + case Microsoft.Extensions.Logging.LogLevel.Trace: + case Microsoft.Extensions.Logging.LogLevel.Debug: + case Microsoft.Extensions.Logging.LogLevel.Information: + _logger.Log(logLevel, 0, null, "HttpRequest Completed", Array.Empty()); + break; + case Microsoft.Extensions.Logging.LogLevel.Warning: + case Microsoft.Extensions.Logging.LogLevel.Error: + case Microsoft.Extensions.Logging.LogLevel.Critical: + _logger.Log(logLevel, 0, null, "HttpRequest Failure", Array.Empty()); + break; } } - - return _options.ExcludeRequestPaths.Contains(requestPath); } - return false; + return false; // Exception Filter should not suppress the Exception } } } diff --git a/src/NLog.Web.AspNetCore/NLogRequestLoggingOptions.cs b/src/NLog.Web.AspNetCore/NLogRequestLoggingOptions.cs index d3630d51..c7437977 100644 --- a/src/NLog.Web.AspNetCore/NLogRequestLoggingOptions.cs +++ b/src/NLog.Web.AspNetCore/NLogRequestLoggingOptions.cs @@ -1,4 +1,7 @@ -using System.Collections.Generic; +using System; +using System.Collections.Generic; +using Microsoft.AspNetCore.Http; +using Microsoft.AspNetCore.Http.Features; namespace NLog.Web { @@ -9,6 +12,14 @@ public sealed class NLogRequestLoggingOptions { internal static readonly NLogRequestLoggingOptions Default = new NLogRequestLoggingOptions(); + /// + /// Initializes a new instance of the class. + /// + public NLogRequestLoggingOptions() + { + ShouldLogRequest = ShouldLogRequestDefault; + } + /// /// Logger-name used for logging http-requests /// @@ -17,7 +28,8 @@ public sealed class NLogRequestLoggingOptions /// /// Get or set duration time in milliseconds, before a HttpRequest is seen as slow (Logged as warning) /// - public int DurationThresholdMs { get; set; } = 300; + public int DurationThresholdMs { get => (int)_durationThresholdMs.TotalMilliseconds; set => _durationThresholdMs = TimeSpan.FromMilliseconds(value); } + private TimeSpan _durationThresholdMs = TimeSpan.FromMilliseconds(300); /// /// Gets or sets request-paths where LogLevel should be reduced (Logged as debug) @@ -25,6 +37,83 @@ public sealed class NLogRequestLoggingOptions /// /// Example '/healthcheck' /// - public ISet ExcludeRequestPaths { get; } = new HashSet(System.StringComparer.OrdinalIgnoreCase); + public ISet ExcludeRequestPaths { get; } = new HashSet(StringComparer.OrdinalIgnoreCase); + + /// + /// Mapper from HttpContext status to LogLevel + /// + public Func ShouldLogRequest { get; set; } + + private Microsoft.Extensions.Logging.LogLevel ShouldLogRequestDefault(HttpContext httpContext, Exception exception) + { + if (exception != null) + { + return Microsoft.Extensions.Logging.LogLevel.Error; + } + else + { + var statusCode = httpContext.Response?.StatusCode ?? 0; + if (statusCode < 100 || (statusCode >= 400 && statusCode < 600)) + { + return Microsoft.Extensions.Logging.LogLevel.Warning; + } + else if (IsExcludedHttpRequest(httpContext)) + { + return Microsoft.Extensions.Logging.LogLevel.Debug; + } + else if (IsSlowHttpRequest()) + { + return Microsoft.Extensions.Logging.LogLevel.Warning; + } + else + { + return Microsoft.Extensions.Logging.LogLevel.Information; + } + } + } + + private bool IsSlowHttpRequest() + { +#if !ASP_NET_CORE2 + var currentActivity = System.Diagnostics.Activity.Current; + var activityStartTime = DateTime.MinValue; + while (currentActivity != null) + { + if (currentActivity.StartTimeUtc > DateTime.MinValue) + activityStartTime = currentActivity.StartTimeUtc; + currentActivity = currentActivity.Parent; + } + if (activityStartTime > DateTime.MinValue) + { + var currentDuration = DateTime.UtcNow - activityStartTime; + if (currentDuration > _durationThresholdMs) + { + return true; + } + } +#endif + + return false; + } + + private bool IsExcludedHttpRequest(HttpContext httpContext) + { + if (ExcludeRequestPaths.Count > 0) + { + var requestPath = httpContext.Features.Get()?.Path; + if (string.IsNullOrEmpty(requestPath)) + { + requestPath = httpContext.Request?.Path; + if (string.IsNullOrEmpty(requestPath)) + { + return false; + } + } + + return ExcludeRequestPaths.Contains(requestPath); + } + + return false; + } } } diff --git a/tests/NLog.Web.AspNetCore.Tests/NLogRequestLoggingMiddlewareTests.cs b/tests/NLog.Web.AspNetCore.Tests/NLogRequestLoggingMiddlewareTests.cs index 7ad3b125..ab8564cc 100644 --- a/tests/NLog.Web.AspNetCore.Tests/NLogRequestLoggingMiddlewareTests.cs +++ b/tests/NLog.Web.AspNetCore.Tests/NLogRequestLoggingMiddlewareTests.cs @@ -2,7 +2,6 @@ using System.Collections.Generic; using System.IO; using System.Linq; -using System.Text; using Microsoft.AspNetCore.Http; using NLog.Extensions.Logging; using Xunit; @@ -11,9 +10,95 @@ namespace NLog.Web.Tests { public class NLogRequestLoggingMiddlewareTests { -#if !ASP_NET_CORE2 [Fact] - public void ExceptionFilterTest() + public void HttpRequestCompletedTest() + { + // Arrange + DefaultHttpContext defaultContext = new DefaultHttpContext(); + defaultContext.Response.Body = new MemoryStream(); + defaultContext.Request.Path = "/"; + + var testTarget = new NLog.Targets.MemoryTarget() { Layout = "${level}|${message}" }; + var nlogFactory = new LogFactory().Setup().LoadConfiguration(builder => + { + builder.ForLogger().WriteTo(testTarget); + }).LogFactory; + var loggerFactory = new NLogLoggerFactory(new NLogLoggerProvider(new NLogProviderOptions(), nlogFactory)); + + var middlewareInstance = new NLogRequestLoggingMiddleware(next: (innerHttpContext) => + { + return System.Threading.Tasks.Task.CompletedTask; + }, loggerFactory: loggerFactory); + + // Act + middlewareInstance.Invoke(defaultContext).ConfigureAwait(false).GetAwaiter().GetResult(); + + // Assert + Assert.Single(testTarget.Logs); + Assert.Equal("Info|HttpRequest Completed", testTarget.Logs[0]); + } + + [Fact] + public void HttpRequestExcludedTest() + { + // Arrange + DefaultHttpContext defaultContext = new DefaultHttpContext(); + defaultContext.Response.Body = new MemoryStream(); + defaultContext.Request.Path = "/documentation/"; + + var testTarget = new NLog.Targets.MemoryTarget() { Layout = "${level}|${message}" }; + var nlogFactory = new LogFactory().Setup().LoadConfiguration(builder => + { + builder.ForLogger().WriteTo(testTarget); + }).LogFactory; + var loggerFactory = new NLogLoggerFactory(new NLogLoggerProvider(new NLogProviderOptions(), nlogFactory)); + + var options = new NLogRequestLoggingOptions(); + options.ExcludeRequestPaths.Add("/documentation/"); + var middlewareInstance = new NLogRequestLoggingMiddleware(next: (innerHttpContext) => + { + return System.Threading.Tasks.Task.CompletedTask; + }, loggerFactory: loggerFactory, options: options); + + // Act + middlewareInstance.Invoke(defaultContext).ConfigureAwait(false).GetAwaiter().GetResult(); + + // Assert + Assert.Single(testTarget.Logs); + Assert.Equal("Debug|HttpRequest Completed", testTarget.Logs[0]); + } + + [Fact] + public void HttpRequestFailedTest() + { + // Arrange + DefaultHttpContext defaultContext = new DefaultHttpContext(); + defaultContext.Response.Body = new MemoryStream(); + defaultContext.Request.Path = "/"; + + var testTarget = new NLog.Targets.MemoryTarget() { Layout = "${level}|${message}" }; + var nlogFactory = new LogFactory().Setup().LoadConfiguration(builder => + { + builder.ForLogger().WriteTo(testTarget); + }).LogFactory; + var loggerFactory = new NLogLoggerFactory(new NLogLoggerProvider(new NLogProviderOptions(), nlogFactory)); + + var middlewareInstance = new NLogRequestLoggingMiddleware(next: (innerHttpContext) => + { + innerHttpContext.Response.StatusCode = 503; + return System.Threading.Tasks.Task.CompletedTask; + }, loggerFactory: loggerFactory); + + // Act + middlewareInstance.Invoke(defaultContext).ConfigureAwait(false).GetAwaiter().GetResult(); + + // Assert + Assert.Single(testTarget.Logs); + Assert.Equal("Warn|HttpRequest Failure", testTarget.Logs[0]); + } + + [Fact] + public void HttpRequestExceptionFilterTest() { // Arrange DefaultHttpContext defaultContext = new DefaultHttpContext(); @@ -24,7 +109,7 @@ public void ExceptionFilterTest() { builder.ForLogger().WriteTo(new NLog.Targets.MemoryTarget() { Name = "TestTarget", Layout = "${scopeproperty:RequestId} ${exception:format=message}" }); }).LogFactory; - var loggerFactory = Microsoft.Extensions.Logging.LoggerFactory.Create(builder => builder.AddNLog(provider => nlogFactory)); + var loggerFactory = new NLogLoggerFactory(new NLogLoggerProvider(new NLogProviderOptions(), nlogFactory)); // Act var middlewareInstance = new NLogRequestLoggingMiddleware(next: (innerHttpContext) => @@ -53,6 +138,5 @@ public void ExceptionFilterTest() } }); } -#endif } } From eb5ed6a4bf2da037515150463b738bff7837f293 Mon Sep 17 00:00:00 2001 From: Rolf Kristensen Date: Sun, 29 May 2022 20:27:19 +0200 Subject: [PATCH 2/2] NLogRequestLoggingModule - Improved unit-test-coverage --- src/NLog.Web/NLogRequestLoggingModule.cs | 46 +++++++---- .../NLogRequestLoggingModuleTests.cs | 76 +++++++++++++++++++ .../TestInvolvingAspNetHttpContext.cs | 2 +- 3 files changed, 109 insertions(+), 15 deletions(-) create mode 100644 tests/NLog.Web.Tests/NLogRequestLoggingModuleTests.cs diff --git a/src/NLog.Web/NLogRequestLoggingModule.cs b/src/NLog.Web/NLogRequestLoggingModule.cs index d8407b89..99a45cd9 100644 --- a/src/NLog.Web/NLogRequestLoggingModule.cs +++ b/src/NLog.Web/NLogRequestLoggingModule.cs @@ -10,31 +10,49 @@ namespace NLog.Web public class NLogRequestLoggingModule : IHttpModule { private static readonly NLog.Logger Logger = NLog.LogManager.GetLogger("NLogRequestLogging"); + private readonly NLog.Logger _logger; /// /// Get or set duration time in milliseconds, before a HttpRequest is seen as slow (Logged as warning) /// - public int DurationThresholdMs { get; set; } = 300; + public int DurationThresholdMs { get => (int)_durationThresholdMs.TotalMilliseconds; set => _durationThresholdMs = TimeSpan.FromMilliseconds(value); } + private TimeSpan _durationThresholdMs = TimeSpan.FromMilliseconds(300); /// /// Gets or sets request-paths where LogLevel should be reduced (Logged as debug) /// - public HashSet ExcludeRequestPaths { get; } = new HashSet(System.StringComparer.OrdinalIgnoreCase); + public HashSet ExcludeRequestPaths { get; } = new HashSet(StringComparer.OrdinalIgnoreCase); + + /// + /// Initializes new instance of the class + /// + public NLogRequestLoggingModule() + { + _logger = Logger; + } + + /// + /// Initializes new instance of the class + /// + internal NLogRequestLoggingModule(Logger logger) + { + _logger = logger; + } void IHttpModule.Init(HttpApplication context) { - context.EndRequest += LogHttpRequest; + context.EndRequest += (sender, args) => OnEndRequest((sender as HttpApplication)?.Context); } - private void LogHttpRequest(object sender, EventArgs e) + internal void OnEndRequest(HttpContext context) { Exception exception = null; int statusCode = 0; try { - exception = HttpContext.Current?.Server?.GetLastError(); - statusCode = HttpContext.Current?.Response?.StatusCode ?? 0; + exception = context?.Server?.GetLastError(); + statusCode = context?.Response?.StatusCode ?? 0; } catch { @@ -43,15 +61,15 @@ private void LogHttpRequest(object sender, EventArgs e) finally { if (exception != null) - Logger.Error(exception, "HttpRequest Exception"); + _logger.Error(exception, "HttpRequest Exception"); else if (statusCode < 100 || (statusCode >= 400 && statusCode < 600)) - Logger.Warn("HttpRequest Failed"); - else if (IsExcludedHttpRequest(HttpContext.Current)) - Logger.Debug("HttpRequest Completed"); - else if (IsSlowHttpRequest(HttpContext.Current)) - Logger.Warn("HttpRequest Slow"); + _logger.Warn("HttpRequest Failure"); + else if (IsExcludedHttpRequest(context)) + _logger.Debug("HttpRequest Completed"); + else if (IsSlowHttpRequest(context)) + _logger.Warn("HttpRequest Slow"); else - Logger.Info("HttpRequest Completed"); + _logger.Info("HttpRequest Completed"); } } @@ -68,7 +86,7 @@ private bool IsSlowHttpRequest(HttpContext httpContext) if (timestamp > DateTime.MinValue) { var currentDuration = DateTime.UtcNow - timestamp.ToUniversalTime(); - if (currentDuration > TimeSpan.FromMilliseconds(DurationThresholdMs)) + if (currentDuration > _durationThresholdMs) { return true; } diff --git a/tests/NLog.Web.Tests/NLogRequestLoggingModuleTests.cs b/tests/NLog.Web.Tests/NLogRequestLoggingModuleTests.cs new file mode 100644 index 00000000..28e0abbe --- /dev/null +++ b/tests/NLog.Web.Tests/NLogRequestLoggingModuleTests.cs @@ -0,0 +1,76 @@ +using System; +using NLog.Web.Tests.LayoutRenderers; +using Xunit; + +namespace NLog.Web.Tests +{ + public class NLogRequestLoggingModuleTests : TestInvolvingAspNetHttpContext + { + [Fact] + public void HttpRequestCompletedTest() + { + var testTarget = new NLog.Targets.MemoryTarget() { Layout = "${level}|${message}${exception}" }; + var logFactory = new LogFactory().Setup().LoadConfiguration(builder => + { + builder.ForLogger().WriteTo(testTarget); + }).LogFactory; + var httpContext = SetUpFakeHttpContext(); + var httpModule = new NLogRequestLoggingModule(logFactory.GetCurrentClassLogger()) { DurationThresholdMs = 5000 }; + httpModule.OnEndRequest(httpContext); + + Assert.Single(testTarget.Logs); + Assert.Equal("Info|HttpRequest Completed", testTarget.Logs[0]); + } + + [Fact] + public void HttpRequestSlowTest() + { + var testTarget = new NLog.Targets.MemoryTarget() { Layout = "${level}|${message}${exception}" }; + var logFactory = new LogFactory().Setup().LoadConfiguration(builder => + { + builder.ForLogger().WriteTo(testTarget); + }).LogFactory; + var httpContext = SetUpFakeHttpContext(); + var httpModule = new NLogRequestLoggingModule(logFactory.GetCurrentClassLogger()) { DurationThresholdMs = 50 }; + System.Threading.Thread.Sleep(50); + httpModule.OnEndRequest(httpContext); + + Assert.Single(testTarget.Logs); + Assert.Equal("Warn|HttpRequest Slow", testTarget.Logs[0]); + } + + [Fact] + public void HttpRequestFailedTest() + { + var testTarget = new NLog.Targets.MemoryTarget() { Layout = "${level}|${message}${exception}" }; + var logFactory = new LogFactory().Setup().LoadConfiguration(builder => + { + builder.ForLogger().WriteTo(testTarget); + }).LogFactory; + var httpContext = SetUpFakeHttpContext(); + httpContext.Response.StatusCode = 503; + var httpModule = new NLogRequestLoggingModule(logFactory.GetCurrentClassLogger()); + httpModule.OnEndRequest(httpContext); + + Assert.Single(testTarget.Logs); + Assert.Equal("Warn|HttpRequest Failure", testTarget.Logs[0]); + } + + [Fact] + public void HttpRequestExcludedTest() + { + var testTarget = new NLog.Targets.MemoryTarget() { Layout = "${level}|${message}${exception}" }; + var logFactory = new LogFactory().Setup().LoadConfiguration(builder => + { + builder.ForLogger().WriteTo(testTarget); + }).LogFactory; + var httpContext = SetUpFakeHttpContext(); + var httpModule = new NLogRequestLoggingModule(logFactory.GetCurrentClassLogger()); + httpModule.ExcludeRequestPaths.Add("/documentation/"); + httpModule.OnEndRequest(httpContext); + + Assert.Single(testTarget.Logs); + Assert.Equal("Debug|HttpRequest Completed", testTarget.Logs[0]); + } + } +} diff --git a/tests/Shared/LayoutRenderers/TestInvolvingAspNetHttpContext.cs b/tests/Shared/LayoutRenderers/TestInvolvingAspNetHttpContext.cs index 7b414030..d30d5661 100644 --- a/tests/Shared/LayoutRenderers/TestInvolvingAspNetHttpContext.cs +++ b/tests/Shared/LayoutRenderers/TestInvolvingAspNetHttpContext.cs @@ -14,7 +14,7 @@ namespace NLog.Web.Tests.LayoutRenderers { public abstract class TestInvolvingAspNetHttpContext : TestBase { - private static readonly Uri DefaultTestUri = new Uri("http://stackoverflow.com/"); + private static readonly Uri DefaultTestUri = new Uri("https://nlog-project.org/documentation/"); protected HttpContext HttpContext;