Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

NLogRequestLoggingMiddleware - Added support for custom ShouldLogRequest-delegate #783

Merged
merged 2 commits into from
May 29, 2022
Merged

NLogRequestLoggingMiddleware - Added support for custom ShouldLogRequest-delegate #783

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
2 commits
Select commit Hold shift + click to select a range
48ae11f
NLogRequestLoggingMiddleware - Added support for custom ShouldLogRequ…
snakefoot May 29, 2022
eb5ed6a
NLogRequestLoggingModule - Improved unit-test-coverage
snakefoot May 29, 2022
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
77 changes: 16 additions & 61 deletions src/NLog.Web.AspNetCore/NLogRequestLoggingMiddleware.cs
View file
Open in desktop
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
Open in desktop
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
Open in desktop
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