From f89c978e42aa36e39067c6a731a251d359ba2ad5 Mon Sep 17 00:00:00 2001 From: Burak Akgerman Date: Sun, 11 Dec 2022 21:43:26 -0500 Subject: [PATCH 1/6] Move AspNetBufferingTargetWrapper.cs to Shared folder from NLog.Web --- .../Targets/Wrappers/AspNetBufferingTargetWrapper.cs | 0 1 file changed, 0 insertions(+), 0 deletions(-) rename src/{NLog.Web => Shared}/Targets/Wrappers/AspNetBufferingTargetWrapper.cs (100%) diff --git a/src/NLog.Web/Targets/Wrappers/AspNetBufferingTargetWrapper.cs b/src/Shared/Targets/Wrappers/AspNetBufferingTargetWrapper.cs similarity index 100% rename from src/NLog.Web/Targets/Wrappers/AspNetBufferingTargetWrapper.cs rename to src/Shared/Targets/Wrappers/AspNetBufferingTargetWrapper.cs From c91420cfcad0ba21bddcce52929cc566d01338c2 Mon Sep 17 00:00:00 2001 From: Burak Akgerman Date: Sun, 11 Dec 2022 21:45:17 -0500 Subject: [PATCH 2/6] Complete AspNetBufferTargetWrapper changes as a single commit. --- .../NLogBufferingTargetWrapperMiddleware.cs | 53 +++++ src/NLog.Web/NLogHttpModule.cs | 49 ++--- .../Internal/LogEventInfoBuffer.cs | 51 +++-- .../Wrappers/AspNetBufferingTargetWrapper.cs | 206 +++++++++++++----- .../AspNetCoreTests.cs | 3 +- ...ogBufferingTargetWrapperMiddlewareTests.cs | 152 +++++++++++++ tests/NLog.Web.Tests/NLogHttpModuleTests.cs | 79 +++++++ 7 files changed, 484 insertions(+), 109 deletions(-) create mode 100644 src/NLog.Web.AspNetCore/NLogBufferingTargetWrapperMiddleware.cs rename src/{NLog.Web => Shared}/Internal/LogEventInfoBuffer.cs (92%) create mode 100644 tests/NLog.Web.AspNetCore.Tests/NLogBufferingTargetWrapperMiddlewareTests.cs create mode 100644 tests/NLog.Web.Tests/NLogHttpModuleTests.cs diff --git a/src/NLog.Web.AspNetCore/NLogBufferingTargetWrapperMiddleware.cs b/src/NLog.Web.AspNetCore/NLogBufferingTargetWrapperMiddleware.cs new file mode 100644 index 00000000..78a86dcc --- /dev/null +++ b/src/NLog.Web.AspNetCore/NLogBufferingTargetWrapperMiddleware.cs @@ -0,0 +1,53 @@ +using System.Threading.Tasks; +using Microsoft.AspNetCore.Http; +using NLog.Web.Targets.Wrappers; + +namespace NLog.Web +{ + /// + /// This class is to intercept the HTTP pipeline and to allow the AspNetBufferingTargetWrapper to function properly + /// + /// Usage: app.UseMiddleware<NLogBufferingTargetWrapperMiddleware>(); where app is an IApplicationBuilder + /// + public class NLogBufferingTargetWrapperMiddleware + { + private readonly RequestDelegate _next; + + /// + /// Initializes new instance of the class + /// + /// + /// Use the following in Startup.cs: + /// + /// public void Configure(IApplicationBuilder app, IWebHostEnvironment env) + /// { + /// app.UseMiddleware<NLog.Web.NLogBufferingTargetWrapperMiddleware>(); + /// } + /// + /// + public NLogBufferingTargetWrapperMiddleware(RequestDelegate next) + { + _next = next; + } + + /// + /// This allows interception of the HTTP pipeline for logging purposes + /// + /// The HttpContext + /// + public async Task Invoke(HttpContext context) + { + try + { + AspNetBufferingTargetWrapper.OnBeginRequest(context); + + // Execute the next class in the HTTP pipeline, this can be the next middleware or the actual handler + await _next(context).ConfigureAwait(false); + } + finally + { + AspNetBufferingTargetWrapper.OnEndRequest(context); + } + } + } +} diff --git a/src/NLog.Web/NLogHttpModule.cs b/src/NLog.Web/NLogHttpModule.cs index 958e9622..0409afeb 100644 --- a/src/NLog.Web/NLogHttpModule.cs +++ b/src/NLog.Web/NLogHttpModule.cs @@ -1,33 +1,24 @@ -using System; +using NLog.Web.Targets.Wrappers; +using System; using System.Web; namespace NLog.Web { /// - /// ASP.NET HttpModule that enables NLog to hook BeginRequest and EndRequest events easily. + /// ASP.NET IHttpModule that enables AspNetBufferingTargetWrapper proper functioning /// public class NLogHttpModule : IHttpModule { - /// - /// Event to be raised at the end of each HTTP Request. - /// - public static event EventHandler EndRequest; - - /// - /// Event to be raised at the beginning of each HTTP Request. - /// - public static event EventHandler BeginRequest; - /// /// Initializes the HttpModule. /// - /// + /// /// ASP.NET application. /// - public void Init(HttpApplication application) + public void Init(HttpApplication context) { - application.BeginRequest += BeginRequestHandler; - application.EndRequest += EndRequestHandler; + Initialize(context); + context.EndRequest += EndRequestEventHandler; } /// @@ -35,22 +26,28 @@ public void Init(HttpApplication application) /// public void Dispose() { + // Method intentionally left empty. } - private void BeginRequestHandler(object sender, EventArgs args) + internal void Initialize(HttpApplication application) { - if (BeginRequest != null) - { - BeginRequest(sender, args); - } + Initialize(application.Context); + } + + internal void Initialize(HttpContext context) + { + AspNetBufferingTargetWrapper.OnBeginRequest(new HttpContextWrapper(context)); + } + + internal void EndRequestEventHandler(object sender, EventArgs args) + { + + Flush((sender as HttpApplication)?.Context); } - private void EndRequestHandler(object sender, EventArgs args) + internal void Flush(HttpContext context) { - if (EndRequest != null) - { - EndRequest(sender, args); - } + AspNetBufferingTargetWrapper.OnEndRequest(new HttpContextWrapper(context)); } } } diff --git a/src/NLog.Web/Internal/LogEventInfoBuffer.cs b/src/Shared/Internal/LogEventInfoBuffer.cs similarity index 92% rename from src/NLog.Web/Internal/LogEventInfoBuffer.cs rename to src/Shared/Internal/LogEventInfoBuffer.cs index dd846daf..92aaff2b 100644 --- a/src/NLog.Web/Internal/LogEventInfoBuffer.cs +++ b/src/Shared/Internal/LogEventInfoBuffer.cs @@ -1,35 +1,35 @@ -// +// // Copyright (c) 2004-2021 Jaroslaw Kowalski , Kim Christensen, Julian Verdurmen -// +// // All rights reserved. -// -// Redistribution and use in source and binary forms, with or without -// modification, are permitted provided that the following conditions +// +// Redistribution and use in source and binary forms, with or without +// modification, are permitted provided that the following conditions // are met: -// -// * Redistributions of source code must retain the above copyright notice, -// this list of conditions and the following disclaimer. -// +// +// * Redistributions of source code must retain the above copyright notice, +// this list of conditions and the following disclaimer. +// // * Redistributions in binary form must reproduce the above copyright notice, // this list of conditions and the following disclaimer in the documentation -// and/or other materials provided with the distribution. -// -// * Neither the name of Jaroslaw Kowalski nor the names of its +// and/or other materials provided with the distribution. +// +// * Neither the name of Jaroslaw Kowalski nor the names of its // contributors may be used to endorse or promote products derived from this -// software without specific prior written permission. -// +// software without specific prior written permission. +// // THIS SOFTWARE IS PROVIDED BY THE COPYRIGHT HOLDERS AND CONTRIBUTORS "AS IS" -// AND ANY EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT LIMITED TO, THE -// IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS FOR A PARTICULAR PURPOSE -// ARE DISCLAIMED. IN NO EVENT SHALL THE COPYRIGHT OWNER OR CONTRIBUTORS BE -// LIABLE FOR ANY DIRECT, INDIRECT, INCIDENTAL, SPECIAL, EXEMPLARY, OR +// AND ANY EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT LIMITED TO, THE +// IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS FOR A PARTICULAR PURPOSE +// ARE DISCLAIMED. IN NO EVENT SHALL THE COPYRIGHT OWNER OR CONTRIBUTORS BE +// LIABLE FOR ANY DIRECT, INDIRECT, INCIDENTAL, SPECIAL, EXEMPLARY, OR // CONSEQUENTIAL DAMAGES (INCLUDING, BUT NOT LIMITED TO, PROCUREMENT OF -// SUBSTITUTE GOODS OR SERVICES; LOSS OF USE, DATA, OR PROFITS; OR BUSINESS -// INTERRUPTION) HOWEVER CAUSED AND ON ANY THEORY OF LIABILITY, WHETHER IN -// CONTRACT, STRICT LIABILITY, OR TORT (INCLUDING NEGLIGENCE OR OTHERWISE) -// ARISING IN ANY WAY OUT OF THE USE OF THIS SOFTWARE, EVEN IF ADVISED OF +// SUBSTITUTE GOODS OR SERVICES; LOSS OF USE, DATA, OR PROFITS; OR BUSINESS +// INTERRUPTION) HOWEVER CAUSED AND ON ANY THEORY OF LIABILITY, WHETHER IN +// CONTRACT, STRICT LIABILITY, OR TORT (INCLUDING NEGLIGENCE OR OTHERWISE) +// ARISING IN ANY WAY OUT OF THE USE OF THIS SOFTWARE, EVEN IF ADVISED OF // THE POSSIBILITY OF SUCH DAMAGE. -// +// namespace NLog.Web.Internal { @@ -132,8 +132,11 @@ public AsyncLogEventInfo[] GetEventsAndClear() { int cnt = _count; if (cnt == 0) +#if NET35 return new AsyncLogEventInfo[0]; - +#else + return Array.Empty(); +#endif var returnValue = new AsyncLogEventInfo[cnt]; for (int i = 0; i < cnt; ++i) diff --git a/src/Shared/Targets/Wrappers/AspNetBufferingTargetWrapper.cs b/src/Shared/Targets/Wrappers/AspNetBufferingTargetWrapper.cs index 1a4e5f63..c56e6e03 100644 --- a/src/Shared/Targets/Wrappers/AspNetBufferingTargetWrapper.cs +++ b/src/Shared/Targets/Wrappers/AspNetBufferingTargetWrapper.cs @@ -1,10 +1,16 @@ using System; +using System.Collections.Generic; using System.ComponentModel; -using System.Web; using NLog.Common; using NLog.Targets; using NLog.Targets.Wrappers; -using NLog.Web.Internal; +#if !ASP_NET_CORE +using System.Web; +#else +using HttpContextBase = Microsoft.AspNetCore.Http.HttpContext; +using Microsoft.AspNetCore.Http; +using NLog.Web.DependencyInjection; +#endif namespace NLog.Web.Targets.Wrappers { @@ -21,7 +27,7 @@ namespace NLog.Web.Targets.Wrappers /// to apply after all logs for a page have been generated. ///

///

- /// To use this target, you need to add an entry in the httpModules section of + /// To use this target, for classic ASP.NET you need to add an entry in the httpModules section of /// web.config: ///

/// @@ -29,12 +35,18 @@ namespace NLog.Web.Targets.Wrappers /// /// /// - /// + /// /// /// /// /// ]]> /// + /// to use this target, for ASP.NET Core, you need to add a line fo code to involve the proper middleware + /// + /// (); + /// ]]> + /// /// /// ///

To set up the ASP.NET Buffering target wrapper configuration file, put @@ -61,9 +73,6 @@ namespace NLog.Web.Targets.Wrappers [Target("AspNetBufferingWrapper", IsWrapper = true)] public class AspNetBufferingTargetWrapper : WrapperTargetBase { - private readonly object dataSlot = new object(); - private int growLimit; - ///

/// Initializes a new instance of the class. /// @@ -88,8 +97,9 @@ public AspNetBufferingTargetWrapper(Target wrappedTarget) /// Size of the buffer. public AspNetBufferingTargetWrapper(Target wrappedTarget, int bufferSize) { - WrappedTarget = wrappedTarget; - BufferSize = bufferSize; + + WrappedTarget = wrappedTarget; + BufferSize = bufferSize; GrowBufferAsNeeded = true; } @@ -112,104 +122,184 @@ public AspNetBufferingTargetWrapper(Target wrappedTarget, int bufferSize) [DefaultValue(false)] public bool GrowBufferAsNeeded { get; set; } + /// + /// Limits the amount of slots that the buffer should grow + /// + private int _bufferGrowLimit; + /// /// Gets or sets the maximum number of log events that the buffer can keep. /// /// public int BufferGrowLimit { - get - { - return growLimit; - } + get => _bufferGrowLimit; set { - growLimit = value; + _bufferGrowLimit = value; GrowBufferAsNeeded = (value >= BufferSize); } } /// - /// Initializes the target by hooking up the NLogHttpModule BeginRequest and EndRequest events. + /// Context for DI /// - protected override void InitializeTarget() + private IHttpContextAccessor _httpContextAccessor; + + /// + /// Provides access to the current request HttpContext. + /// + /// HttpContextAccessor or null + internal IHttpContextAccessor HttpContextAccessor { - base.InitializeTarget(); + get => _httpContextAccessor ?? (_httpContextAccessor = RetrieveHttpContextAccessor()); + set => _httpContextAccessor = value; + } - // Prevent double subscribe - NLogHttpModule.BeginRequest -= OnBeginRequest; - NLogHttpModule.EndRequest -= OnEndRequest; + private IHttpContextAccessor RetrieveHttpContextAccessor() + { +#if ASP_NET_CORE + return ServiceLocator.ResolveService(ResolveService(), LoggingConfiguration); +#else + return new DefaultHttpContextAccessor(); +#endif + } - NLogHttpModule.BeginRequest += OnBeginRequest; - NLogHttpModule.EndRequest += OnEndRequest; + /// + /// Must be called by the HttpModule/Middleware upon starting. + /// This creates the dictionary in the HttpContext.Items with the proper key. + /// + /// + internal static void OnBeginRequest(HttpContextBase context) + { + if (context == null) + { + return; + } + + var bufferDictionary = GetBufferDictionary(context); - if (HttpContext.Current != null) + // If the dictionary is missing, create that first + if (bufferDictionary == null) { - // we are in the context already, it's too late for OnBeginRequest to be called, so let's - // just call it ourselves - OnBeginRequest(null, null); + SetBufferDictionary(context); } } /// - /// Closes the target by flushing pending events in the buffer (if any). + /// Called from the HttpModule or Middleware upon the end of the HTTP pipeline + /// Flushes all instances of this class registered in the HttpContext /// - protected override void CloseTarget() + /// + internal static void OnEndRequest(HttpContextBase context) { - NLogHttpModule.BeginRequest -= OnBeginRequest; - NLogHttpModule.EndRequest -= OnEndRequest; - base.CloseTarget(); + var bufferDictionary = GetBufferDictionary(context); + if (bufferDictionary == null) + { + return; + } + foreach (var bufferKeyValuePair in bufferDictionary) + { + bufferKeyValuePair.Key?.Flush(bufferKeyValuePair.Value); + } } /// - /// Adds the specified log event to the buffer. + /// Called by the above static Flush method. /// - /// The log event. - protected override void Write(AsyncLogEventInfo logEvent) + /// + private void Flush(Internal.LogEventInfoBuffer buffer) { - var buffer = GetRequestBuffer(); - if (buffer != null) + if (buffer == null) { - WrappedTarget.PrecalculateVolatileLayouts(logEvent.LogEvent); - - buffer.Append(logEvent); - InternalLogger.Trace("Appending log event {0} to ASP.NET request buffer.", logEvent.LogEvent.SequenceID); - } - else - { - InternalLogger.Trace("ASP.NET request buffer does not exist. Passing to wrapped target."); - WrappedTarget.WriteAsyncLogEvent(logEvent); + return; } + InternalLogger.Trace("Sending buffered events to wrapped target: {0}.", WrappedTarget); + WrappedTarget?.WriteAsyncLogEvents(buffer.GetEventsAndClear()); } - private NLog.Web.Internal.LogEventInfoBuffer GetRequestBuffer() + /// + /// Obtains a slot in the buffer dictionary for 'this' class instance + /// If that does not exist, that is created first + /// if the dictionary does not exist, that is created first + /// + /// + /// + private Internal.LogEventInfoBuffer GetOrCreateRequestBuffer(HttpContextBase context) { - HttpContext context = HttpContext.Current; + // If the context is missing, stop if (context == null) { return null; } - return context.Items[dataSlot] as NLog.Web.Internal.LogEventInfoBuffer; + var bufferDictionary = GetBufferDictionary(context); + + // If the dictionary is missing, stop + if (bufferDictionary == null) + { + return null; + } + + lock (bufferDictionary) + { + if (!bufferDictionary.TryGetValue(this, out var buffer)) + { + buffer = new Internal.LogEventInfoBuffer(BufferSize, GrowBufferAsNeeded, BufferGrowLimit); + bufferDictionary.Add(this, buffer); + } + + return buffer; + } + } + + /// + /// The Key for the buffer dictionary in the HttpContext.Items collection + /// + private static readonly object HttpContextItemsKey = new object(); + + /// + /// Return the buffer dictionary from the HttpContext.Items using HttpContextItemsKey + /// + /// + /// + private static Dictionary GetBufferDictionary(HttpContextBase context) + { + return context?.Items?[HttpContextItemsKey] as + Dictionary; } - private void OnBeginRequest(object sender, EventArgs args) + /// + /// Create the buffer dictionary in the HttpContext.Items using HttpContextItemsKey + /// + /// + /// + private static void SetBufferDictionary(HttpContextBase context) { - InternalLogger.Trace("Setting up ASP.NET request buffer."); - HttpContext context = HttpContext.Current; - context.Items[dataSlot] = new NLog.Web.Internal.LogEventInfoBuffer(BufferSize, GrowBufferAsNeeded, BufferGrowLimit); + context.Items[HttpContextItemsKey] = new Dictionary(); } - private void OnEndRequest(object sender, EventArgs args) + /// + /// Adds the specified log event to the buffer. + /// NOTE: if Write is never called, this instance will not be registered in the buffer dictionary in HttpContext.Items. + /// That is expected normal behavior. + /// + /// The log event. + protected override void Write(AsyncLogEventInfo logEvent) { - var buffer = GetRequestBuffer(); + var buffer = GetOrCreateRequestBuffer(HttpContextAccessor.HttpContext); if (buffer != null) { - InternalLogger.Trace("Sending buffered events to wrapped target: {0}.", WrappedTarget); - AsyncLogEventInfo[] events = buffer.GetEventsAndClear(); - WrappedTarget.WriteAsyncLogEvents(events); + WrappedTarget?.PrecalculateVolatileLayouts(logEvent.LogEvent); + InternalLogger.Trace("Appending log event {0} to ASP.NET request buffer.", logEvent.LogEvent.SequenceID); + buffer.Append(logEvent); + } + else + { + InternalLogger.Trace("ASP.NET request buffer does not exist. Passing to wrapped target."); + WrappedTarget?.WriteAsyncLogEvent(logEvent); } } } -} \ No newline at end of file +} diff --git a/tests/NLog.Web.AspNetCore.Tests/AspNetCoreTests.cs b/tests/NLog.Web.AspNetCore.Tests/AspNetCoreTests.cs index bfd1f0b3..f4cdde44 100644 --- a/tests/NLog.Web.AspNetCore.Tests/AspNetCoreTests.cs +++ b/tests/NLog.Web.AspNetCore.Tests/AspNetCoreTests.cs @@ -17,6 +17,7 @@ using NLog.Layouts; using NLog.Targets; using ILoggerFactory = Microsoft.Extensions.Logging.ILoggerFactory; +using NLog.Web.Targets.Wrappers; namespace NLog.Web.Tests { @@ -242,7 +243,7 @@ public void UseNLog_LoadConfigurationFromSection() logger.LogError("error1"); var loggerProvider = host.Services.GetService() as NLogLoggerProvider; - var logged = loggerProvider.LogFactory.Configuration.FindTargetByName("inMemory").Logs; + var logged = loggerProvider.LogFactory.Configuration.FindTargetByName("inMemory").Logs; Assert.Single(logged); Assert.Equal("logger1|error1|Memory", logged[0]); diff --git a/tests/NLog.Web.AspNetCore.Tests/NLogBufferingTargetWrapperMiddlewareTests.cs b/tests/NLog.Web.AspNetCore.Tests/NLogBufferingTargetWrapperMiddlewareTests.cs new file mode 100644 index 00000000..2263a35e --- /dev/null +++ b/tests/NLog.Web.AspNetCore.Tests/NLogBufferingTargetWrapperMiddlewareTests.cs @@ -0,0 +1,152 @@ +using System.Collections.Generic; +using System.Linq; +using System.Threading.Tasks; +using Microsoft.AspNetCore.Http; +using NLog.Web.Internal; +using NLog.Web.Targets.Wrappers; +using Xunit; + +namespace NLog.Web.Tests +{ + public class NLogBufferingTargetWrapperMiddlewareTests + { + private static LogFactory RegisterAspNetCoreBufferingTargetWrapper(string targetName) + { + LogManager.LogFactory.Setup().RegisterNLogWeb().LoadConfigurationFromXml( + $@" + + + + + + + + + "); + return LogManager.LogFactory; + } + + [Fact] + public async Task BufferingMiddlewareInvokeTest() + { + var logFactory = RegisterAspNetCoreBufferingTargetWrapper("first"); + + Assert.NotNull(logFactory?.Configuration?.FindTargetByName("first")); + + DefaultHttpContext context = new DefaultHttpContext(); + + var target = logFactory?.Configuration?.FindTargetByName("first"); + target.HttpContextAccessor = new FakeHttpContextAccessor(context); + + RequestDelegate next = (HttpContext hc) => + { + ILogger logger = logFactory.GetCurrentClassLogger(); + + for(int i = 0; i < 10; i++) + { + logger.Debug("This is a unit test logging."); + } + + return Task.CompletedTask; + }; + + NLogBufferingTargetWrapperMiddleware middleware = new NLogBufferingTargetWrapperMiddleware(next); + + + + await middleware.Invoke(context).ConfigureAwait(false); + + Assert.NotEmpty(context.Items); + + var eventBufferKeyPair = context.Items.First(); + + Assert.NotNull(eventBufferKeyPair.Key); + + var eventBuffer = eventBufferKeyPair.Value; + + Assert.NotNull(eventBuffer); + + var nlogEventBuffer = eventBuffer as Dictionary; + + Assert.NotNull(nlogEventBuffer); + + var secondFactory = RegisterAspNetCoreBufferingTargetWrapper("second"); + + Assert.NotNull(secondFactory?.Configuration?.FindTargetByName("second")); + + target = secondFactory?.Configuration?.FindTargetByName("second"); + target.HttpContextAccessor = new FakeHttpContextAccessor(context); + + await middleware.Invoke(context).ConfigureAwait(false); + + Assert.NotEmpty(context.Items); + + var thirdFactory = RegisterAspNetCoreBufferingTargetWrapper("third"); + + Assert.NotNull(thirdFactory?.Configuration?.FindTargetByName("third")); + + target = thirdFactory?.Configuration?.FindTargetByName("third"); + target.HttpContextAccessor = new FakeHttpContextAccessor(context); + + await middleware.Invoke(context).ConfigureAwait(false); + + Assert.NotEmpty(context.Items); + + LogManager.Shutdown(); + } + + [Fact] + public async Task BufferingMiddlewareInvokeNullContextTest() + { + var logFactory = RegisterAspNetCoreBufferingTargetWrapper("first"); + + Assert.NotNull(logFactory?.Configuration?.FindTargetByName("first")); + var target = logFactory?.Configuration?.FindTargetByName("first"); + target.HttpContextAccessor = new FakeHttpContextAccessor(null); + + // This should not cause exception even if null + DefaultHttpContext context = null; + + RequestDelegate next = (HttpContext hc) => + { + ILogger logger = logFactory.GetCurrentClassLogger(); + + for (int i = 0; i < 10; i++) + { + logger.Debug("This is a unit test logging."); + } + + return Task.CompletedTask; + }; + + NLogBufferingTargetWrapperMiddleware middleware = new NLogBufferingTargetWrapperMiddleware(next); + + await middleware.Invoke(context).ConfigureAwait(false); + + var secondFactory = RegisterAspNetCoreBufferingTargetWrapper("second"); + + Assert.NotNull(secondFactory?.Configuration?.FindTargetByName("second")); + + target = secondFactory?.Configuration?.FindTargetByName("second"); + target.HttpContextAccessor = new FakeHttpContextAccessor(null); + + await middleware.Invoke(context).ConfigureAwait(false); + + var thirdFactory = RegisterAspNetCoreBufferingTargetWrapper("third"); + + Assert.NotNull(thirdFactory?.Configuration?.FindTargetByName("third")); + + target = thirdFactory?.Configuration?.FindTargetByName("third"); + target.HttpContextAccessor = new FakeHttpContextAccessor(null); + + await middleware.Invoke(context).ConfigureAwait(false); + + LogManager.Shutdown(); + } + } +} diff --git a/tests/NLog.Web.Tests/NLogHttpModuleTests.cs b/tests/NLog.Web.Tests/NLogHttpModuleTests.cs new file mode 100644 index 00000000..40fb6af5 --- /dev/null +++ b/tests/NLog.Web.Tests/NLogHttpModuleTests.cs @@ -0,0 +1,79 @@ +using System.Collections.Generic; +using System.Linq; +using System.Web; +using NLog.Web.Targets.Wrappers; +using NLog.Web.Tests.LayoutRenderers; +using Xunit; + +namespace NLog.Web.Tests +{ + public class NLogHttpModuleTests : TestInvolvingAspNetHttpContext + { + private static LogFactory RegisterAspNetBufferingTargetWrapper(string targetName) + { + LogManager.LogFactory.Setup().RegisterNLogWeb().LoadConfigurationFromXml( + $@" + + + + + + + + + "); + return LogManager.LogFactory; + } + + [Fact] + public void SuccessTest() + { + // Arrange + var httpContext = SetUpFakeHttpContext(); + + var logFactory = RegisterAspNetBufferingTargetWrapper("first"); + + Assert.NotNull(logFactory?.Configuration?.FindTargetByName("first")); + + var target = logFactory?.Configuration?.FindTargetByName("first"); + target.HttpContextAccessor = new FakeHttpContextAccessor(new HttpContextWrapper(httpContext)); + + // Act + var httpModule = new NLogHttpModule(); + httpModule.Initialize(httpContext); + + ILogger logger = logFactory.GetCurrentClassLogger(); + + for (int i = 0; i < 10; i++) + { + logger.Debug("This is a unit test logging."); + } + + // Assert + Assert.NotNull(httpContext.Items); + Assert.NotEmpty(httpContext.Items); + Assert.Equal(1, httpContext.Items.Count); + + foreach (var itemValue in httpContext.Items.Values) + { + var bufferDictionary = + itemValue as Dictionary; + Assert.NotNull(bufferDictionary); + Assert.Single(bufferDictionary); + + foreach (var bufferValue in bufferDictionary.Values) + { + Assert.NotNull(bufferValue); + Assert.Equal(9,bufferValue.Count); + } + } + + httpModule.Flush(httpContext); + } + } +} From 605621cf0eb9a33a7207a282dd0a92800ba46d99 Mon Sep 17 00:00:00 2001 From: Burak Akgerman Date: Mon, 12 Dec 2022 23:03:14 -0500 Subject: [PATCH 3/6] Committing changes from snakefoot and made requested change to NLogHttpModule --- src/NLog.Web/NLogHttpModule.cs | 4 +- .../Wrappers/AspNetBufferingTargetWrapper.cs | 171 +++++++----------- 2 files changed, 63 insertions(+), 112 deletions(-) diff --git a/src/NLog.Web/NLogHttpModule.cs b/src/NLog.Web/NLogHttpModule.cs index 0409afeb..abf8b736 100644 --- a/src/NLog.Web/NLogHttpModule.cs +++ b/src/NLog.Web/NLogHttpModule.cs @@ -18,7 +18,7 @@ public class NLogHttpModule : IHttpModule public void Init(HttpApplication context) { Initialize(context); - context.EndRequest += EndRequestEventHandler; + context.EndRequest += OnEndRequest; } /// @@ -39,7 +39,7 @@ internal void Initialize(HttpContext context) AspNetBufferingTargetWrapper.OnBeginRequest(new HttpContextWrapper(context)); } - internal void EndRequestEventHandler(object sender, EventArgs args) + internal void OnEndRequest(object sender, EventArgs args) { Flush((sender as HttpApplication)?.Context); diff --git a/src/Shared/Targets/Wrappers/AspNetBufferingTargetWrapper.cs b/src/Shared/Targets/Wrappers/AspNetBufferingTargetWrapper.cs index c56e6e03..a11f1e5f 100644 --- a/src/Shared/Targets/Wrappers/AspNetBufferingTargetWrapper.cs +++ b/src/Shared/Targets/Wrappers/AspNetBufferingTargetWrapper.cs @@ -1,9 +1,6 @@ using System; using System.Collections.Generic; using System.ComponentModel; -using NLog.Common; -using NLog.Targets; -using NLog.Targets.Wrappers; #if !ASP_NET_CORE using System.Web; #else @@ -11,6 +8,10 @@ using Microsoft.AspNetCore.Http; using NLog.Web.DependencyInjection; #endif +using NLog.Common; +using NLog.Targets; +using NLog.Targets.Wrappers; + namespace NLog.Web.Targets.Wrappers { @@ -35,7 +36,7 @@ namespace NLog.Web.Targets.Wrappers /// /// /// - /// + /// /// /// /// @@ -73,6 +74,9 @@ namespace NLog.Web.Targets.Wrappers [Target("AspNetBufferingWrapper", IsWrapper = true)] public class AspNetBufferingTargetWrapper : WrapperTargetBase { + private static readonly object dataSlot = new object(); + private int growLimit; + /// /// Initializes a new instance of the class. /// @@ -97,9 +101,8 @@ public AspNetBufferingTargetWrapper(Target wrappedTarget) /// Size of the buffer. public AspNetBufferingTargetWrapper(Target wrappedTarget, int bufferSize) { - - WrappedTarget = wrappedTarget; - BufferSize = bufferSize; + WrappedTarget = wrappedTarget; + BufferSize = bufferSize; GrowBufferAsNeeded = true; } @@ -122,40 +125,30 @@ public AspNetBufferingTargetWrapper(Target wrappedTarget, int bufferSize) [DefaultValue(false)] public bool GrowBufferAsNeeded { get; set; } - /// - /// Limits the amount of slots that the buffer should grow - /// - private int _bufferGrowLimit; - /// /// Gets or sets the maximum number of log events that the buffer can keep. /// /// public int BufferGrowLimit { - get => _bufferGrowLimit; + get + { + return growLimit; + } set { - _bufferGrowLimit = value; + growLimit = value; GrowBufferAsNeeded = (value >= BufferSize); } } - /// - /// Context for DI - /// - private IHttpContextAccessor _httpContextAccessor; - - /// - /// Provides access to the current request HttpContext. - /// - /// HttpContextAccessor or null internal IHttpContextAccessor HttpContextAccessor { get => _httpContextAccessor ?? (_httpContextAccessor = RetrieveHttpContextAccessor()); set => _httpContextAccessor = value; } + private IHttpContextAccessor _httpContextAccessor; private IHttpContextAccessor RetrieveHttpContextAccessor() { @@ -167,76 +160,35 @@ private IHttpContextAccessor RetrieveHttpContextAccessor() } /// - /// Must be called by the HttpModule/Middleware upon starting. - /// This creates the dictionary in the HttpContext.Items with the proper key. + /// Adds the specified log event to the buffer. /// - /// - internal static void OnBeginRequest(HttpContextBase context) + /// The log event. + protected override void Write(AsyncLogEventInfo logEvent) { - if (context == null) - { - return; - } - - var bufferDictionary = GetBufferDictionary(context); - - // If the dictionary is missing, create that first - if (bufferDictionary == null) + var buffer = GetRequestBuffer(); + if (buffer != null) { - SetBufferDictionary(context); - } - } + WrappedTarget.PrecalculateVolatileLayouts(logEvent.LogEvent); - /// - /// Called from the HttpModule or Middleware upon the end of the HTTP pipeline - /// Flushes all instances of this class registered in the HttpContext - /// - /// - internal static void OnEndRequest(HttpContextBase context) - { - var bufferDictionary = GetBufferDictionary(context); - if (bufferDictionary == null) - { - return; - } - foreach (var bufferKeyValuePair in bufferDictionary) - { - bufferKeyValuePair.Key?.Flush(bufferKeyValuePair.Value); + buffer.Append(logEvent); + InternalLogger.Trace("Appending log event {0} to ASP.NET request buffer.", logEvent.LogEvent.SequenceID); } - } - - /// - /// Called by the above static Flush method. - /// - /// - private void Flush(Internal.LogEventInfoBuffer buffer) - { - if (buffer == null) + else { - return; + InternalLogger.Trace("ASP.NET request buffer does not exist. Passing to wrapped target."); + WrappedTarget.WriteAsyncLogEvent(logEvent); } - InternalLogger.Trace("Sending buffered events to wrapped target: {0}.", WrappedTarget); - WrappedTarget?.WriteAsyncLogEvents(buffer.GetEventsAndClear()); } - /// - /// Obtains a slot in the buffer dictionary for 'this' class instance - /// If that does not exist, that is created first - /// if the dictionary does not exist, that is created first - /// - /// - /// - private Internal.LogEventInfoBuffer GetOrCreateRequestBuffer(HttpContextBase context) + private NLog.Web.Internal.LogEventInfoBuffer GetRequestBuffer() { - // If the context is missing, stop + var context = HttpContextAccessor.HttpContext; if (context == null) { return null; } var bufferDictionary = GetBufferDictionary(context); - - // If the dictionary is missing, stop if (bufferDictionary == null) { return null; @@ -254,52 +206,51 @@ private Internal.LogEventInfoBuffer GetOrCreateRequestBuffer(HttpContextBase con } } - /// - /// The Key for the buffer dictionary in the HttpContext.Items collection - /// - private static readonly object HttpContextItemsKey = new object(); - - /// - /// Return the buffer dictionary from the HttpContext.Items using HttpContextItemsKey - /// - /// - /// private static Dictionary GetBufferDictionary(HttpContextBase context) { - return context?.Items?[HttpContextItemsKey] as + return context?.Items?[dataSlot] as Dictionary; } - /// - /// Create the buffer dictionary in the HttpContext.Items using HttpContextItemsKey - /// - /// - /// private static void SetBufferDictionary(HttpContextBase context) { - context.Items[HttpContextItemsKey] = new Dictionary(); + context.Items[dataSlot] = new Dictionary(); } - /// - /// Adds the specified log event to the buffer. - /// NOTE: if Write is never called, this instance will not be registered in the buffer dictionary in HttpContext.Items. - /// That is expected normal behavior. - /// - /// The log event. - protected override void Write(AsyncLogEventInfo logEvent) + internal static void OnBeginRequest(HttpContextBase context) { - var buffer = GetOrCreateRequestBuffer(HttpContextAccessor.HttpContext); - if (buffer != null) + if (context == null) { - WrappedTarget?.PrecalculateVolatileLayouts(logEvent.LogEvent); - InternalLogger.Trace("Appending log event {0} to ASP.NET request buffer.", logEvent.LogEvent.SequenceID); - buffer.Append(logEvent); + return; } - else + + var bufferDictionary = GetBufferDictionary(context); + if (bufferDictionary == null) { - InternalLogger.Trace("ASP.NET request buffer does not exist. Passing to wrapped target."); - WrappedTarget?.WriteAsyncLogEvent(logEvent); + InternalLogger.Trace("Setting up ASP.NET request buffer."); + SetBufferDictionary(context); + } + } + + internal static void OnEndRequest(HttpContextBase context) + { + var bufferDictionary = GetBufferDictionary(context); + if (bufferDictionary == null) + { + return; + } + + foreach (var bufferKeyValuePair in bufferDictionary) + { + var wrappedTarget = bufferKeyValuePair.Key; + var buffer = bufferKeyValuePair.Value; + if (buffer != null) + { + InternalLogger.Trace("Sending buffered events to wrapped target: {0}.", wrappedTarget); + AsyncLogEventInfo[] events = buffer.GetEventsAndClear(); + wrappedTarget.WriteAsyncLogEvents(events); + } } } } -} +} \ No newline at end of file From 178073a7f0f8d6acfb7ab52c8a2917b6d8940b0f Mon Sep 17 00:00:00 2001 From: Burak Akgerman Date: Tue, 13 Dec 2022 15:29:32 -0500 Subject: [PATCH 4/6] Minimize changes to NLogHttpModule --- src/NLog.Web/NLogHttpModule.cs | 42 ++++++++++++++------- tests/NLog.Web.Tests/NLogHttpModuleTests.cs | 4 +- 2 files changed, 30 insertions(+), 16 deletions(-) diff --git a/src/NLog.Web/NLogHttpModule.cs b/src/NLog.Web/NLogHttpModule.cs index abf8b736..2639af1e 100644 --- a/src/NLog.Web/NLogHttpModule.cs +++ b/src/NLog.Web/NLogHttpModule.cs @@ -5,20 +5,30 @@ namespace NLog.Web { /// - /// ASP.NET IHttpModule that enables AspNetBufferingTargetWrapper proper functioning + /// ASP.NET HttpModule that enables NLog to hook BeginRequest and EndRequest events easily. /// public class NLogHttpModule : IHttpModule { + /// + /// Event to be raised at the end of each HTTP Request. + /// + public static event EventHandler EndRequest; + + /// + /// Event to be raised at the beginning of each HTTP Request. + /// + public static event EventHandler BeginRequest; + /// /// Initializes the HttpModule. /// - /// + /// /// ASP.NET application. /// - public void Init(HttpApplication context) + public void Init(HttpApplication application) { - Initialize(context); - context.EndRequest += OnEndRequest; + application.BeginRequest += BeginRequestHandler; + application.EndRequest += EndRequestHandler; } /// @@ -26,26 +36,30 @@ public void Init(HttpApplication context) /// public void Dispose() { - // Method intentionally left empty. } - internal void Initialize(HttpApplication application) + private void BeginRequestHandler(object sender, EventArgs args) { - Initialize(application.Context); + if (BeginRequest != null) + { + OnBeginRequest((sender as HttpApplication)?.Context); + } } - internal void Initialize(HttpContext context) + private void EndRequestHandler(object sender, EventArgs args) { - AspNetBufferingTargetWrapper.OnBeginRequest(new HttpContextWrapper(context)); + if (EndRequest != null) + { + OnEndRequest((sender as HttpApplication)?.Context); + } } - internal void OnEndRequest(object sender, EventArgs args) + internal void OnBeginRequest(HttpContext context) { - - Flush((sender as HttpApplication)?.Context); + AspNetBufferingTargetWrapper.OnBeginRequest(new HttpContextWrapper(context)); } - internal void Flush(HttpContext context) + internal void OnEndRequest(HttpContext context) { AspNetBufferingTargetWrapper.OnEndRequest(new HttpContextWrapper(context)); } diff --git a/tests/NLog.Web.Tests/NLogHttpModuleTests.cs b/tests/NLog.Web.Tests/NLogHttpModuleTests.cs index 40fb6af5..86f8aa27 100644 --- a/tests/NLog.Web.Tests/NLogHttpModuleTests.cs +++ b/tests/NLog.Web.Tests/NLogHttpModuleTests.cs @@ -45,7 +45,7 @@ public void SuccessTest() // Act var httpModule = new NLogHttpModule(); - httpModule.Initialize(httpContext); + httpModule.OnBeginRequest(httpContext); ILogger logger = logFactory.GetCurrentClassLogger(); @@ -73,7 +73,7 @@ public void SuccessTest() } } - httpModule.Flush(httpContext); + httpModule.OnEndRequest(httpContext); } } } From 00280cd403bbf13a8235e14b49f7c445223256d8 Mon Sep 17 00:00:00 2001 From: Burak Akgerman Date: Tue, 13 Dec 2022 15:37:01 -0500 Subject: [PATCH 5/6] Fixed for null events on NLogHttpModule --- src/NLog.Web/NLogHttpModule.cs | 13 +++++-------- 1 file changed, 5 insertions(+), 8 deletions(-) diff --git a/src/NLog.Web/NLogHttpModule.cs b/src/NLog.Web/NLogHttpModule.cs index 2639af1e..eaa1f565 100644 --- a/src/NLog.Web/NLogHttpModule.cs +++ b/src/NLog.Web/NLogHttpModule.cs @@ -40,18 +40,15 @@ public void Dispose() private void BeginRequestHandler(object sender, EventArgs args) { - if (BeginRequest != null) - { - OnBeginRequest((sender as HttpApplication)?.Context); - } + BeginRequest?.Invoke(sender, args); + OnBeginRequest((sender as HttpApplication)?.Context); + } private void EndRequestHandler(object sender, EventArgs args) { - if (EndRequest != null) - { - OnEndRequest((sender as HttpApplication)?.Context); - } + EndRequest?.Invoke(sender, args); + OnEndRequest((sender as HttpApplication)?.Context); } internal void OnBeginRequest(HttpContext context) From ac9ae9eb5b9b6646cd62b8d9668c3d2d51230bf6 Mon Sep 17 00:00:00 2001 From: Burak Akgerman Date: Tue, 20 Dec 2022 14:04:48 -0500 Subject: [PATCH 6/6] Significant upgrade of unit tests. New unit tests found 2 defects and fixed defects. --- src/NLog.Web/NLogHttpModule.cs | 19 +- .../Wrappers/AspNetBufferingTargetWrapper.cs | 4 +- ...ogBufferingTargetWrapperMiddlewareTests.cs | 382 +++++++++++++-- tests/NLog.Web.Tests/NLogHttpModuleTests.cs | 436 +++++++++++++++++- 4 files changed, 779 insertions(+), 62 deletions(-) diff --git a/src/NLog.Web/NLogHttpModule.cs b/src/NLog.Web/NLogHttpModule.cs index eaa1f565..dfe69512 100644 --- a/src/NLog.Web/NLogHttpModule.cs +++ b/src/NLog.Web/NLogHttpModule.cs @@ -1,5 +1,6 @@ using NLog.Web.Targets.Wrappers; using System; +using System.Runtime.InteropServices; using System.Web; namespace NLog.Web @@ -53,12 +54,26 @@ private void EndRequestHandler(object sender, EventArgs args) internal void OnBeginRequest(HttpContext context) { - AspNetBufferingTargetWrapper.OnBeginRequest(new HttpContextWrapper(context)); + if (context != null) + { + AspNetBufferingTargetWrapper.OnBeginRequest(new HttpContextWrapper(context)); + } + else + { + AspNetBufferingTargetWrapper.OnBeginRequest(null); + } } internal void OnEndRequest(HttpContext context) { - AspNetBufferingTargetWrapper.OnEndRequest(new HttpContextWrapper(context)); + if (context != null) + { + AspNetBufferingTargetWrapper.OnEndRequest(new HttpContextWrapper(context)); + } + else + { + AspNetBufferingTargetWrapper.OnEndRequest(null); + } } } } diff --git a/src/Shared/Targets/Wrappers/AspNetBufferingTargetWrapper.cs b/src/Shared/Targets/Wrappers/AspNetBufferingTargetWrapper.cs index a11f1e5f..feab085a 100644 --- a/src/Shared/Targets/Wrappers/AspNetBufferingTargetWrapper.cs +++ b/src/Shared/Targets/Wrappers/AspNetBufferingTargetWrapper.cs @@ -182,7 +182,7 @@ protected override void Write(AsyncLogEventInfo logEvent) private NLog.Web.Internal.LogEventInfoBuffer GetRequestBuffer() { - var context = HttpContextAccessor.HttpContext; + var context = HttpContextAccessor?.HttpContext; if (context == null) { return null; @@ -242,7 +242,7 @@ internal static void OnEndRequest(HttpContextBase context) foreach (var bufferKeyValuePair in bufferDictionary) { - var wrappedTarget = bufferKeyValuePair.Key; + var wrappedTarget = bufferKeyValuePair.Key.WrappedTarget; var buffer = bufferKeyValuePair.Value; if (buffer != null) { diff --git a/tests/NLog.Web.AspNetCore.Tests/NLogBufferingTargetWrapperMiddlewareTests.cs b/tests/NLog.Web.AspNetCore.Tests/NLogBufferingTargetWrapperMiddlewareTests.cs index 2263a35e..504f5824 100644 --- a/tests/NLog.Web.AspNetCore.Tests/NLogBufferingTargetWrapperMiddlewareTests.cs +++ b/tests/NLog.Web.AspNetCore.Tests/NLogBufferingTargetWrapperMiddlewareTests.cs @@ -2,6 +2,8 @@ using System.Linq; using System.Threading.Tasks; using Microsoft.AspNetCore.Http; +using NLog.Targets; +using NLog.Targets.Wrappers; using NLog.Web.Internal; using NLog.Web.Targets.Wrappers; using Xunit; @@ -10,46 +12,106 @@ namespace NLog.Web.Tests { public class NLogBufferingTargetWrapperMiddlewareTests { - private static LogFactory RegisterAspNetCoreBufferingTargetWrapper(string targetName) + private static LogFactory RegisterSingleDebugTarget() { LogManager.LogFactory.Setup().RegisterNLogWeb().LoadConfigurationFromXml( - $@" + @" - + - + + + "); + return LogManager.LogFactory; + } + + private static LogFactory RegisterSingleMemoryTarget() + { + LogManager.LogFactory.Setup().RegisterNLogWeb().LoadConfigurationFromXml( + @" + + + + + + + + + "); + return LogManager.LogFactory; + } + + private static LogFactory RegisterMultipleMemoryTargets() + { + LogManager.LogFactory.Setup().RegisterNLogWeb().LoadConfigurationFromXml( + @" + + + + + + + + + + + + + + + "); return LogManager.LogFactory; } [Fact] - public async Task BufferingMiddlewareInvokeTest() + public async Task TestSingleDebugTarget() { - var logFactory = RegisterAspNetCoreBufferingTargetWrapper("first"); + var logFactory = RegisterSingleDebugTarget(); - Assert.NotNull(logFactory?.Configuration?.FindTargetByName("first")); + Assert.NotNull(logFactory?.Configuration?.FindTargetByName("only")); DefaultHttpContext context = new DefaultHttpContext(); - var target = logFactory?.Configuration?.FindTargetByName("first"); + var target = logFactory?.Configuration?.FindTargetByName("only"); target.HttpContextAccessor = new FakeHttpContextAccessor(context); RequestDelegate next = (HttpContext hc) => { ILogger logger = logFactory.GetCurrentClassLogger(); - for(int i = 0; i < 10; i++) + for (int i = 0; i < 10; i++) { - logger.Debug("This is a unit test logging."); + logger.Debug(i.ToString); } return Task.CompletedTask; @@ -57,8 +119,6 @@ public async Task BufferingMiddlewareInvokeTest() NLogBufferingTargetWrapperMiddleware middleware = new NLogBufferingTargetWrapperMiddleware(next); - - await middleware.Invoke(context).ConfigureAwait(false); Assert.NotEmpty(context.Items); @@ -75,50 +135,148 @@ public async Task BufferingMiddlewareInvokeTest() Assert.NotNull(nlogEventBuffer); - var secondFactory = RegisterAspNetCoreBufferingTargetWrapper("second"); + var wrappedTarget = target.WrappedTarget; + var debugTarget = wrappedTarget as DebugTarget; + + Assert.NotNull(debugTarget); + + // Buffer limit is set to 9 above + Assert.Equal(9, debugTarget.Counter); - Assert.NotNull(secondFactory?.Configuration?.FindTargetByName("second")); + Assert.Equal("9", debugTarget.LastMessage); + + LogManager.Shutdown(); + } - target = secondFactory?.Configuration?.FindTargetByName("second"); + [Fact] + public async Task TestSingleMemoryTarget() + { + var logFactory = RegisterSingleMemoryTarget(); + + Assert.NotNull(logFactory?.Configuration?.FindTargetByName("only")); + + DefaultHttpContext context = new DefaultHttpContext(); + + var target = logFactory?.Configuration?.FindTargetByName("only"); target.HttpContextAccessor = new FakeHttpContextAccessor(context); + RequestDelegate next = (HttpContext hc) => + { + ILogger logger = logFactory.GetCurrentClassLogger(); + + for (int i = 0; i < 10; i++) + { + logger.Debug(i.ToString); + } + + return Task.CompletedTask; + }; + + NLogBufferingTargetWrapperMiddleware middleware = new NLogBufferingTargetWrapperMiddleware(next); + await middleware.Invoke(context).ConfigureAwait(false); Assert.NotEmpty(context.Items); - var thirdFactory = RegisterAspNetCoreBufferingTargetWrapper("third"); + var eventBufferKeyPair = context.Items.First(); + + Assert.NotNull(eventBufferKeyPair.Key); + + var eventBuffer = eventBufferKeyPair.Value; + + Assert.NotNull(eventBuffer); + + var nlogEventBuffer = eventBuffer as Dictionary; + + Assert.NotNull(nlogEventBuffer); + + var wrappedTarget = target.WrappedTarget; + var memoryTarget = wrappedTarget as MemoryTarget; + + Assert.NotNull(memoryTarget); + + Assert.NotNull(memoryTarget.Logs); + + Assert.NotEmpty(memoryTarget.Logs); + + Assert.Equal(9, memoryTarget.Logs.Count); + + // We went thru the buffered wrapper where the buffer limit was 9, + // so in this case we have only 9 messages starting at 1, not + // 10 messages starting at 0. + + int j = 1; + foreach (var message in memoryTarget.Logs) + { + Assert.Equal(j.ToString(), message); + j++; + } + + LogManager.Shutdown(); + } - Assert.NotNull(thirdFactory?.Configuration?.FindTargetByName("third")); + [Fact] + public async Task TestSingleDebugTargetWithNullContext() + { + var logFactory = RegisterSingleDebugTarget(); + + Assert.NotNull(logFactory?.Configuration?.FindTargetByName("only")); + + DefaultHttpContext context = null; - target = thirdFactory?.Configuration?.FindTargetByName("third"); + var target = logFactory?.Configuration?.FindTargetByName("only"); target.HttpContextAccessor = new FakeHttpContextAccessor(context); + RequestDelegate next = (HttpContext hc) => + { + ILogger logger = logFactory.GetCurrentClassLogger(); + + for (int i = 0; i < 10; i++) + { + logger.Debug(i.ToString); + } + + return Task.CompletedTask; + }; + + NLogBufferingTargetWrapperMiddleware middleware = new NLogBufferingTargetWrapperMiddleware(next); + await middleware.Invoke(context).ConfigureAwait(false); - Assert.NotEmpty(context.Items); + var wrappedTarget = target.WrappedTarget; + var debugTarget = wrappedTarget as DebugTarget; + + Assert.NotNull(debugTarget); + + // There should be 10 messages even if the buffer limit was 9. + // Due to null http context we skipped the buffering target + // so we should have all 10 messages. + Assert.Equal(10, debugTarget.Counter); + + Assert.Equal("9", debugTarget.LastMessage); LogManager.Shutdown(); } [Fact] - public async Task BufferingMiddlewareInvokeNullContextTest() + public async Task TestSingleMemoryTargetWithNullContext() { - var logFactory = RegisterAspNetCoreBufferingTargetWrapper("first"); + var logFactory = RegisterSingleMemoryTarget(); - Assert.NotNull(logFactory?.Configuration?.FindTargetByName("first")); - var target = logFactory?.Configuration?.FindTargetByName("first"); - target.HttpContextAccessor = new FakeHttpContextAccessor(null); + Assert.NotNull(logFactory?.Configuration?.FindTargetByName("only")); - // This should not cause exception even if null DefaultHttpContext context = null; + var target = logFactory?.Configuration?.FindTargetByName("only"); + target.HttpContextAccessor = new FakeHttpContextAccessor(context); + RequestDelegate next = (HttpContext hc) => { ILogger logger = logFactory.GetCurrentClassLogger(); for (int i = 0; i < 10; i++) { - logger.Debug("This is a unit test logging."); + logger.Debug(i.ToString); } return Task.CompletedTask; @@ -128,25 +286,179 @@ public async Task BufferingMiddlewareInvokeNullContextTest() await middleware.Invoke(context).ConfigureAwait(false); - var secondFactory = RegisterAspNetCoreBufferingTargetWrapper("second"); + var wrappedTarget = target.WrappedTarget; + var memoryTarget = wrappedTarget as MemoryTarget; + + Assert.NotNull(memoryTarget); + + Assert.NotNull(memoryTarget.Logs); + + Assert.NotEmpty(memoryTarget.Logs); + + Assert.Equal(10,memoryTarget.Logs.Count); + + // because we had a null HttpContext, we did not go thru the + // buffered wrapper where the buffer limit was 9, + // so in this case we have all 10 messages starting at 0. + + int j = 0; + foreach (var message in memoryTarget.Logs) + { + Assert.Equal(j.ToString(), message); + j++; + } + + LogManager.Shutdown(); + } + + [Fact] + public async Task TestMultipleMemoryTargets() + { + var logFactory = RegisterMultipleMemoryTargets(); + + Assert.NotNull(logFactory?.Configuration?.FindTargetByName("first")); + Assert.NotNull(logFactory?.Configuration?.FindTargetByName("second")); + Assert.NotNull(logFactory?.Configuration?.FindTargetByName("third")); + + DefaultHttpContext context = new DefaultHttpContext(); + + var firstTarget = logFactory?.Configuration?.FindTargetByName("first"); + firstTarget.HttpContextAccessor = new FakeHttpContextAccessor(context); + + var secondTarget = logFactory?.Configuration?.FindTargetByName("second"); + secondTarget.HttpContextAccessor = new FakeHttpContextAccessor(context); + + var thirdTarget = logFactory?.Configuration?.FindTargetByName("third"); + thirdTarget.HttpContextAccessor = new FakeHttpContextAccessor(context); + + RequestDelegate next = (HttpContext hc) => + { + ILogger logger = logFactory.GetCurrentClassLogger(); + + for (int i = 0; i < 10; i++) + { + logger.Debug(i.ToString); + } - Assert.NotNull(secondFactory?.Configuration?.FindTargetByName("second")); + return Task.CompletedTask; + }; - target = secondFactory?.Configuration?.FindTargetByName("second"); - target.HttpContextAccessor = new FakeHttpContextAccessor(null); + NLogBufferingTargetWrapperMiddleware middleware = new NLogBufferingTargetWrapperMiddleware(next); await middleware.Invoke(context).ConfigureAwait(false); - var thirdFactory = RegisterAspNetCoreBufferingTargetWrapper("third"); + Assert.NotEmpty(context.Items); + + var eventBufferKeyPair = context.Items.First(); + + Assert.NotNull(eventBufferKeyPair.Key); + + var eventBuffer = eventBufferKeyPair.Value; + + Assert.NotNull(eventBuffer); + + var nlogEventBuffer = eventBuffer as Dictionary; + + Assert.NotNull(nlogEventBuffer); + + TestMemoryTargetForMultipleCase(firstTarget); + TestMemoryTargetForMultipleCase(secondTarget); + TestMemoryTargetForMultipleCase(thirdTarget); + + LogManager.Shutdown(); + } + + private void TestMemoryTargetForMultipleCase(WrapperTargetBase target) + { + var wrappedTarget = target.WrappedTarget; + var memoryTarget = wrappedTarget as MemoryTarget; + + Assert.NotNull(memoryTarget); + + Assert.NotNull(memoryTarget.Logs); + + Assert.NotEmpty(memoryTarget.Logs); + + Assert.Equal(9, memoryTarget.Logs.Count); + + // We went thru the buffered wrapper where the buffer limit was 9, + // so in this case we have only 9 messages starting at 1, not + // 10 messages starting at 0. + + int j = 1; + foreach (var message in memoryTarget.Logs) + { + Assert.Equal(j.ToString(), message); + j++; + } + } + + [Fact] + public async Task TestMultipleMemoryTargetsWithNullContext() + { + var logFactory = RegisterMultipleMemoryTargets(); + + Assert.NotNull(logFactory?.Configuration?.FindTargetByName("first")); + Assert.NotNull(logFactory?.Configuration?.FindTargetByName("second")); + Assert.NotNull(logFactory?.Configuration?.FindTargetByName("third")); + + DefaultHttpContext context = null; + + var firstTarget = logFactory?.Configuration?.FindTargetByName("first"); + firstTarget.HttpContextAccessor = new FakeHttpContextAccessor(context); + + var secondTarget = logFactory?.Configuration?.FindTargetByName("second"); + secondTarget.HttpContextAccessor = new FakeHttpContextAccessor(context); + + var thirdTarget = logFactory?.Configuration?.FindTargetByName("third"); + thirdTarget.HttpContextAccessor = new FakeHttpContextAccessor(context); - Assert.NotNull(thirdFactory?.Configuration?.FindTargetByName("third")); + RequestDelegate next = (HttpContext hc) => + { + ILogger logger = logFactory.GetCurrentClassLogger(); + + for (int i = 0; i < 10; i++) + { + logger.Debug(i.ToString); + } + + return Task.CompletedTask; + }; - target = thirdFactory?.Configuration?.FindTargetByName("third"); - target.HttpContextAccessor = new FakeHttpContextAccessor(null); + NLogBufferingTargetWrapperMiddleware middleware = new NLogBufferingTargetWrapperMiddleware(next); await middleware.Invoke(context).ConfigureAwait(false); + TestMemoryTargetForMultipleCaseNullContext(firstTarget); + TestMemoryTargetForMultipleCaseNullContext(secondTarget); + TestMemoryTargetForMultipleCaseNullContext(thirdTarget); + LogManager.Shutdown(); } + + private void TestMemoryTargetForMultipleCaseNullContext(WrapperTargetBase target) + { + var wrappedTarget = target.WrappedTarget; + var memoryTarget = wrappedTarget as MemoryTarget; + + Assert.NotNull(memoryTarget); + + Assert.NotNull(memoryTarget.Logs); + + Assert.NotEmpty(memoryTarget.Logs); + + Assert.Equal(10, memoryTarget.Logs.Count); + + // We went thru the buffered wrapper where the buffer limit was 9, + // so in this case we have only 9 messages starting at 1, not + // 10 messages starting at 0. + + int j = 0; + foreach (var message in memoryTarget.Logs) + { + Assert.Equal(j.ToString(), message); + j++; + } + } } } diff --git a/tests/NLog.Web.Tests/NLogHttpModuleTests.cs b/tests/NLog.Web.Tests/NLogHttpModuleTests.cs index 86f8aa27..1cadf5ec 100644 --- a/tests/NLog.Web.Tests/NLogHttpModuleTests.cs +++ b/tests/NLog.Web.Tests/NLogHttpModuleTests.cs @@ -1,6 +1,11 @@ -using System.Collections.Generic; -using System.Linq; +using System.Collections; +using System.Collections.Generic; +using System.Linq; +using System.Threading.Tasks; using System.Web; +using NLog.Targets; +using NLog.Targets.Wrappers; +using NLog.Web.Internal; using NLog.Web.Targets.Wrappers; using NLog.Web.Tests.LayoutRenderers; using Xunit; @@ -9,71 +14,456 @@ namespace NLog.Web.Tests { public class NLogHttpModuleTests : TestInvolvingAspNetHttpContext { - private static LogFactory RegisterAspNetBufferingTargetWrapper(string targetName) + private static LogFactory RegisterSingleDebugTarget() { LogManager.LogFactory.Setup().RegisterNLogWeb().LoadConfigurationFromXml( - $@" + @" - + - + + + "); + return LogManager.LogFactory; + } + + private static LogFactory RegisterSingleMemoryTarget() + { + LogManager.LogFactory.Setup().RegisterNLogWeb().LoadConfigurationFromXml( + @" + + + + + + + + + "); + return LogManager.LogFactory; + } + + private static LogFactory RegisterMultipleMemoryTargets() + { + LogManager.LogFactory.Setup().RegisterNLogWeb().LoadConfigurationFromXml( + @" + + + + + + + + + + + + + + + "); return LogManager.LogFactory; } [Fact] - public void SuccessTest() + public void TestSingleDebugTarget() { - // Arrange - var httpContext = SetUpFakeHttpContext(); + var logFactory = RegisterSingleDebugTarget(); - var logFactory = RegisterAspNetBufferingTargetWrapper("first"); + Assert.NotNull(logFactory?.Configuration?.FindTargetByName("only")); - Assert.NotNull(logFactory?.Configuration?.FindTargetByName("first")); + var context = SetUpFakeHttpContext(); - var target = logFactory?.Configuration?.FindTargetByName("first"); - target.HttpContextAccessor = new FakeHttpContextAccessor(new HttpContextWrapper(httpContext)); + var target = logFactory?.Configuration?.FindTargetByName("only"); + target.HttpContextAccessor = new FakeHttpContextAccessor(new HttpContextWrapper(context)); // Act var httpModule = new NLogHttpModule(); - httpModule.OnBeginRequest(httpContext); + httpModule.OnBeginRequest(context); ILogger logger = logFactory.GetCurrentClassLogger(); for (int i = 0; i < 10; i++) { - logger.Debug("This is a unit test logging."); + logger.Debug(i.ToString()); } - // Assert - Assert.NotNull(httpContext.Items); - Assert.NotEmpty(httpContext.Items); - Assert.Equal(1, httpContext.Items.Count); + Assert.NotNull(context.Items); + Assert.NotEmpty(context.Items); + Assert.Equal(1, context.Items.Count); - foreach (var itemValue in httpContext.Items.Values) + foreach (var itemValue in context.Items.Values) { var bufferDictionary = itemValue as Dictionary; + Assert.NotNull(bufferDictionary); + Assert.Single(bufferDictionary); foreach (var bufferValue in bufferDictionary.Values) { Assert.NotNull(bufferValue); - Assert.Equal(9,bufferValue.Count); + + Assert.Equal(9, bufferValue.Count); + } + } + + httpModule.OnEndRequest(context); + + var wrappedTarget = target.WrappedTarget; + var debugTarget = wrappedTarget as DebugTarget; + + Assert.NotNull(debugTarget); + + // Buffer limit is set to 9 above + Assert.Equal(9, debugTarget.Counter); + + Assert.Equal("9", debugTarget.LastMessage); + + LogManager.Shutdown(); + } + + [Fact] + public void TestSingleMemoryTarget() + { + var logFactory = RegisterSingleMemoryTarget(); + + Assert.NotNull(logFactory?.Configuration?.FindTargetByName("only")); + + var context = SetUpFakeHttpContext(); + + var target = logFactory?.Configuration?.FindTargetByName("only"); + target.HttpContextAccessor = new FakeHttpContextAccessor(new HttpContextWrapper(context)); + + // Act + var httpModule = new NLogHttpModule(); + httpModule.OnBeginRequest(context); + + ILogger logger = logFactory.GetCurrentClassLogger(); + + for (int i = 0; i < 10; i++) + { + logger.Debug(i.ToString()); + } + + Assert.NotNull(context.Items); + Assert.NotEmpty(context.Items); + Assert.Equal(1, context.Items.Count); + + foreach (var itemValue in context.Items.Values) + { + var bufferDictionary = + itemValue as Dictionary; + + Assert.NotNull(bufferDictionary); + + Assert.Single(bufferDictionary); + + foreach (var bufferValue in bufferDictionary.Values) + { + Assert.NotNull(bufferValue); + + Assert.Equal(9, bufferValue.Count); + } + } + + httpModule.OnEndRequest(context); + + var wrappedTarget = target.WrappedTarget; + var memoryTarget = wrappedTarget as MemoryTarget; + + Assert.NotNull(memoryTarget); + + Assert.NotNull(memoryTarget.Logs); + + Assert.NotEmpty(memoryTarget.Logs); + + Assert.Equal(9, memoryTarget.Logs.Count); + + // We went thru the buffered wrapper where the buffer limit was 9, + // so in this case we have only 9 messages starting at 1, not + // 10 messages starting at 0. + + int j = 1; + foreach (var message in memoryTarget.Logs) + { + Assert.Equal(j.ToString(), message); + j++; + } + + LogManager.Shutdown(); + } + + [Fact] + public void TestSingleDebugTargetWithNullContext() + { + var logFactory = RegisterSingleDebugTarget(); + + Assert.NotNull(logFactory?.Configuration?.FindTargetByName("only")); + + HttpContext context = null; + + var target = logFactory?.Configuration?.FindTargetByName("only"); + target.HttpContextAccessor = new FakeHttpContextAccessor(null); + + // Act + var httpModule = new NLogHttpModule(); + httpModule.OnBeginRequest(context); + + ILogger logger = logFactory.GetCurrentClassLogger(); + + for (int i = 0; i < 10; i++) + { + logger.Debug(i.ToString()); + } + + httpModule.OnEndRequest(context); + + var wrappedTarget = target.WrappedTarget; + var debugTarget = wrappedTarget as DebugTarget; + + Assert.NotNull(debugTarget); + + // There should be 10 messages even if the buffer limit was 9. + // Due to null http context we skipped the buffering target + // so we should have all 10 messages. + Assert.Equal(10, debugTarget.Counter); + + Assert.Equal("9", debugTarget.LastMessage); + + LogManager.Shutdown(); + } + + [Fact] + public void TestSingleMemoryTargetWithNullContext() + { + var logFactory = RegisterSingleMemoryTarget(); + + Assert.NotNull(logFactory?.Configuration?.FindTargetByName("only")); + + HttpContext context = null; + + var target = logFactory?.Configuration?.FindTargetByName("only"); + target.HttpContextAccessor = new FakeHttpContextAccessor(null); + + // Act + var httpModule = new NLogHttpModule(); + httpModule.OnBeginRequest(context); + + ILogger logger = logFactory.GetCurrentClassLogger(); + + for (int i = 0; i < 10; i++) + { + logger.Debug(i.ToString()); + } + + httpModule.OnEndRequest(context); + + var wrappedTarget = target.WrappedTarget; + var memoryTarget = wrappedTarget as MemoryTarget; + + Assert.NotNull(memoryTarget); + + Assert.NotNull(memoryTarget.Logs); + + Assert.NotEmpty(memoryTarget.Logs); + + Assert.Equal(10, memoryTarget.Logs.Count); + + // because we had a null HttpContext, we did not go thru the + // buffered wrapper where the buffer limit was 9, + // so in this case we have all 10 messages starting at 0. + + int j = 0; + foreach (var message in memoryTarget.Logs) + { + Assert.Equal(j.ToString(), message); + j++; + } + + LogManager.Shutdown(); + } + + [Fact] + public void TestMutipleMemoryTargetsWithNullContext() + { + var logFactory = RegisterMultipleMemoryTargets(); + + Assert.NotNull(logFactory?.Configuration?.FindTargetByName("first")); + Assert.NotNull(logFactory?.Configuration?.FindTargetByName("second")); + Assert.NotNull(logFactory?.Configuration?.FindTargetByName("third")); + + HttpContext context = null; + + var firstTarget = logFactory?.Configuration?.FindTargetByName("first"); + firstTarget.HttpContextAccessor = new FakeHttpContextAccessor(null); + + var secondTarget = logFactory?.Configuration?.FindTargetByName("second"); + secondTarget.HttpContextAccessor = new FakeHttpContextAccessor(null); + + var thirdTarget = logFactory?.Configuration?.FindTargetByName("third"); + thirdTarget.HttpContextAccessor = new FakeHttpContextAccessor(null); + + // Act + var httpModule = new NLogHttpModule(); + httpModule.OnBeginRequest(context); + + ILogger logger = logFactory.GetCurrentClassLogger(); + + for (int i = 0; i < 10; i++) + { + logger.Debug(i.ToString()); + } + + httpModule.OnEndRequest(context); + + TestMemoryTargetForMultipleCaseNullContext(firstTarget); + TestMemoryTargetForMultipleCaseNullContext(secondTarget); + TestMemoryTargetForMultipleCaseNullContext(thirdTarget); + + LogManager.Shutdown(); + } + + [Fact] + public void TestMutipleMemoryTargets() + { + var logFactory = RegisterMultipleMemoryTargets(); + + Assert.NotNull(logFactory?.Configuration?.FindTargetByName("first")); + Assert.NotNull(logFactory?.Configuration?.FindTargetByName("second")); + Assert.NotNull(logFactory?.Configuration?.FindTargetByName("third")); + + var context = SetUpFakeHttpContext(); + + var firstTarget = logFactory?.Configuration?.FindTargetByName("first"); + firstTarget.HttpContextAccessor = new FakeHttpContextAccessor(new HttpContextWrapper(context)); + + var secondTarget = logFactory?.Configuration?.FindTargetByName("second"); + secondTarget.HttpContextAccessor = new FakeHttpContextAccessor(new HttpContextWrapper(context)); + + var thirdTarget = logFactory?.Configuration?.FindTargetByName("third"); + thirdTarget.HttpContextAccessor = new FakeHttpContextAccessor(new HttpContextWrapper(context)); + + // Act + var httpModule = new NLogHttpModule(); + httpModule.OnBeginRequest(context); + + ILogger logger = logFactory.GetCurrentClassLogger(); + + for (int i = 0; i < 10; i++) + { + logger.Debug(i.ToString()); + } + + Assert.NotNull(context.Items); + Assert.NotEmpty(context.Items); + Assert.Equal(1, context.Items.Count); + + foreach (var itemValue in context.Items.Values) + { + var bufferDictionary = + itemValue as Dictionary; + + Assert.NotNull(bufferDictionary); + + Assert.Equal(3,bufferDictionary.Count); + + foreach (var bufferValue in bufferDictionary.Values) + { + Assert.NotNull(bufferValue); + + Assert.Equal(9, bufferValue.Count); } } - httpModule.OnEndRequest(httpContext); + httpModule.OnEndRequest(context); + + TestMemoryTargetForMultipleCase(firstTarget); + TestMemoryTargetForMultipleCase(secondTarget); + TestMemoryTargetForMultipleCase(thirdTarget); + + LogManager.Shutdown(); + } + + private void TestMemoryTargetForMultipleCaseNullContext(WrapperTargetBase target) + { + var wrappedTarget = target.WrappedTarget; + var memoryTarget = wrappedTarget as MemoryTarget; + + Assert.NotNull(memoryTarget); + + Assert.NotNull(memoryTarget.Logs); + + Assert.NotEmpty(memoryTarget.Logs); + + Assert.Equal(10, memoryTarget.Logs.Count); + + // We went thru the buffered wrapper where the buffer limit was 9, + // so in this case we have only 9 messages starting at 1, not + // 10 messages starting at 0. + + int j = 0; + foreach (var message in memoryTarget.Logs) + { + Assert.Equal(j.ToString(), message); + j++; + } + } + + private void TestMemoryTargetForMultipleCase(WrapperTargetBase target) + { + var wrappedTarget = target.WrappedTarget; + var memoryTarget = wrappedTarget as MemoryTarget; + + Assert.NotNull(memoryTarget); + + Assert.NotNull(memoryTarget.Logs); + + Assert.NotEmpty(memoryTarget.Logs); + + Assert.Equal(9, memoryTarget.Logs.Count); + + // We went thru the buffered wrapper where the buffer limit was 9, + // so in this case we have only 9 messages starting at 1, not + // 10 messages starting at 0. + + int j = 1; + foreach (var message in memoryTarget.Logs) + { + Assert.Equal(j.ToString(), message); + j++; + } } } }