Skip to content

Commit

Permalink
NLogRequestLoggingMiddleware - Added support for custom ShouldLogRequ…
Browse files Browse the repository at this point in the history 
…est-delegate (#783)

* NLogRequestLoggingMiddleware - Added support for custom ShouldLogRequest-delegate

* NLogRequestLoggingModule - Improved unit-test-coverage
  • Loading branch information
@snakefoot
snakefoot authored May 29, 2022
1 parent 55a7fca commit 6bb5747
Show file tree
Hide file tree
Showing 6 changed files with 306 additions and 84 deletions.
77 changes: 16 additions & 61 deletions src/NLog.Web.AspNetCore/NLogRequestLoggingMiddleware.cs
View file
Original file line number Diff line number Diff line change
@@ -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
Expand Down Expand Up @@ -60,76 +59,32 @@ public async Task Invoke(HttpContext httpContext)
/// </summary>
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<object>());
}
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<IHttpRequestFeature>()?.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<object>());
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<object>());
break;
}
}

return _options.ExcludeRequestPaths.Contains(requestPath);
}

return false;
return false; // Exception Filter should not suppress the Exception
}
}
}
95 changes: 92 additions & 3 deletions src/NLog.Web.AspNetCore/NLogRequestLoggingOptions.cs
View file
Original file line number Diff line number Diff line change
@@ -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
{
Expand All @@ -9,6 +12,14 @@ public sealed class NLogRequestLoggingOptions
{
internal static readonly NLogRequestLoggingOptions Default = new NLogRequestLoggingOptions();

/// <summary>
/// Initializes a new instance of the <see cref="NLogRequestLoggingOptions" /> class.
/// </summary>
public NLogRequestLoggingOptions()
{
ShouldLogRequest = ShouldLogRequestDefault;
}

/// <summary>
/// Logger-name used for logging http-requests
/// </summary>
Expand All @@ -17,14 +28,92 @@ public sealed class NLogRequestLoggingOptions
/// <summary>
/// Get or set duration time in milliseconds, before a HttpRequest is seen as slow (Logged as warning)
/// </summary>
public int DurationThresholdMs { get; set; } = 300;
public int DurationThresholdMs { get => (int)_durationThresholdMs.TotalMilliseconds; set => _durationThresholdMs = TimeSpan.FromMilliseconds(value); }
private TimeSpan _durationThresholdMs = TimeSpan.FromMilliseconds(300);

/// <summary>
/// Gets or sets request-paths where LogLevel should be reduced (Logged as debug)
/// </summary>
/// <remarks>
/// Example '/healthcheck'
/// </remarks>
public ISet<string> ExcludeRequestPaths { get; } = new HashSet<string>(System.StringComparer.OrdinalIgnoreCase);
public ISet<string> ExcludeRequestPaths { get; } = new HashSet<string>(StringComparer.OrdinalIgnoreCase);

/// <summary>
/// Mapper from HttpContext status to LogLevel
/// </summary>
public Func<HttpContext, Exception, Microsoft.Extensions.Logging.LogLevel> 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<IHttpRequestFeature>()?.Path;
if (string.IsNullOrEmpty(requestPath))
{
requestPath = httpContext.Request?.Path;
if (string.IsNullOrEmpty(requestPath))
{
return false;
}
}

return ExcludeRequestPaths.Contains(requestPath);
}

return false;
}
}
}
46 changes: 32 additions & 14 deletions src/NLog.Web/NLogRequestLoggingModule.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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;

/// <summary>
/// Get or set duration time in milliseconds, before a HttpRequest is seen as slow (Logged as warning)
/// </summary>
public int DurationThresholdMs { get; set; } = 300;
public int DurationThresholdMs { get => (int)_durationThresholdMs.TotalMilliseconds; set => _durationThresholdMs = TimeSpan.FromMilliseconds(value); }
private TimeSpan _durationThresholdMs = TimeSpan.FromMilliseconds(300);

/// <summary>
/// Gets or sets request-paths where LogLevel should be reduced (Logged as debug)
/// </summary>
public HashSet<string> ExcludeRequestPaths { get; } = new HashSet<string>(System.StringComparer.OrdinalIgnoreCase);
public HashSet<string> ExcludeRequestPaths { get; } = new HashSet<string>(StringComparer.OrdinalIgnoreCase);

/// <summary>
/// Initializes new instance of the <see cref="NLogRequestLoggingModule"/> class
/// </summary>
public NLogRequestLoggingModule()
{
_logger = Logger;
}

/// <summary>
/// Initializes new instance of the <see cref="NLogRequestLoggingModule"/> class
/// </summary>
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
{
Expand All @@ -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");
}
}

Expand All @@ -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;
}
Expand Down
Loading

0 comments on commit 6bb5747

Please sign in to comment.