NLog.Web icon indicating copy to clipboard operation
NLog.Web copied to clipboard

Add buffering target wrapper to ASP.NET Core

Open bakgerman opened this issue 3 years ago • 14 comments

Attempt to move NLog.Web target wrapper to NLog.Web.AspNetCore

Application must setup middleware NLogBufferingTargetWrapperMiddleware, which enables the use of target-wrapper AspNetBufferingTargetWrapper (type="AspNetBufferingWrapper")

bakgerman avatar Jul 08 '22 18:07 bakgerman

Could you please add some tests?

maybe helpful: https://stackoverflow.com/questions/59583406/how-to-unit-test-a-net-middleware-that-uses-response-onstarting

Certainly, thank you for the link. I was looking for the existing unit tests for the ASP.NET version of the buffer target wrapper but could not locate.

bakgerman avatar Jul 09 '22 16:07 bakgerman

Codecov Report

Base: 69% // Head: 72% // Increases project coverage by +3% :tada:

Coverage data is based on head (5caf312) compared to base (a4ea473). Patch coverage: 57% of modified lines in pull request are covered.

:exclamation: Current head 5caf312 differs from pull request most recent head c4d5b6b. Consider uploading reports for the commit c4d5b6b to get more accurate results

Additional details and impacted files
@@          Coverage Diff          @@
##           master   #816   +/-   ##
=====================================
+ Coverage      69%    72%   +3%     
=====================================
  Files          66     66           
  Lines        1259   1271   +12     
  Branches      323    333   +10     
=====================================
+ Hits          869    920   +51     
+ Misses        246    196   -50     
- Partials      144    155   +11     
Impacted Files Coverage Δ
src/Shared/Internal/LogEventInfoBuffer.cs 93% <0%> (ø)
src/NLog.Web/NLogBufferingTargetWrapperModule.cs 33% <33%> (ø)
...d/Targets/Wrappers/AspNetBufferingTargetWrapper.cs 63% <63%> (ø)
...utRenderers/AspNetRequestDurationLayoutRenderer.cs 56% <0%> (-9%) :arrow_down:

Help us with your feedback. Take ten seconds to tell us how you rate us. Have a feature suggestion? Share it here.

:umbrella: View full report at Codecov.
:loudspeaker: Do you have feedback about the report comment? Let us know in this issue.

codecov-commenter avatar Jul 09 '22 16:07 codecov-commenter

Will need to determine why Write method in the target sees a null HttpContext if this is due to unit test only or if this fails in actual application. Will work on that next. Rest of it seems to be OK. I probably need to use IHttpContextAccessor in the class instead of new HttpContextAccessor and that will fix it.

bakgerman avatar Jul 09 '22 17:07 bakgerman

I have made a commit so that the http context is saved into an httpcontextaccessor upon begin request, so that the http context is available during the write method. Since we don't have httpcontext.current in asp.net core. Debugging in the unit tests this did write events to the log buffer now.

bakgerman avatar Jul 09 '22 18:07 bakgerman

Curious how this works together with AsyncTargetWrapper. The NLog Layout provides automatic context-capture, but now you have to implement everything yourself.

But it also seems that the original NLog.Web-module is a little weird, since it explict calls WrappedTarget.PrecalculateVolatileLayouts(logEvent.LogEvent); which does not make any sense.

I can sadly enough not review this, since I don't have enough experience with neither NLog.Web or NLog.Web.AspNetCore. Not a big fan of static variables.

snakefoot avatar Jul 13 '22 20:07 snakefoot

yes unfortunately any strange aspects of the original may exist in this one. I was myself unable to understand how this will work in concert with the existing AsyncTargetWrapper. This waits until the request is completed, but then executes all of the logging at the end, and what if there is a large number of logs buffered, how long can that take to execute? This is the "most exact copy" of the original that will work in ASP.NET Core, but inherits any strange aspects of the original. They must have used static events since they did not know in what order the classes would be constructed, the httpmodule/middleware first, or the target first. Will try to think of a way around that.

bakgerman avatar Jul 13 '22 21:07 bakgerman

Added a commit so that the asp.net and asp.net core version both use a common base class, so no more duplicated code.

bakgerman avatar Jul 15 '22 17:07 bakgerman

The code for ASP.NET and ASP.NET Core is now 95% the same in base classes.

bakgerman avatar Jul 16 '22 17:07 bakgerman

@bakgerman Curious if you have ever used this code on ASP.NET Core Application? Or if you are just picking up a challenge?

I'm guessing the goal of this buffering-wrapper is to provide all LogEvents leading up to a certain state (probably error-state triggered by exception). And for all other situations then just discard the collected events?

I'm guessing there will be a lock-congestion/memory-allocation performance penalty when trying to enable this feature on ASP.NET Application that handles concurrent web-requests.

snakefoot avatar Jul 17 '22 17:07 snakefoot

@bakgerman Curious if you have ever used this code on ASP.NET Core Application? Or if you are just picking up a challenge?

I'm guessing the goal of this buffering-wrapper is to provide all LogEvents leading up to a certain state (probably error-state triggered by exception). And for all other situations then just discard the collected events?

I'm guessing there will be a lock-congestion/memory-allocation performance penalty when trying to enable this feature on ASP.NET Application that handles concurrent web-requests.

Yes, I am just picking up a challenge. And try to make asp.net core have feature equality to asp.net.

But this is indeed a strange target, that holds onto logs until an event occurs, then flushes them all at once.

If we have many http requests at same time, and the log events are all held until request is over, then the result may not be good. Logging should never affect the system being logged.

Wondering if we should mark AspNet BufferingTargetWrapper as Obsolete and not make AspNetCore version? Does anyone know reason behind creation of the original class for Asp.net?

If this pull request is cancelled that is fine, I can examine request for IHealthCheck feature instead.

bakgerman avatar Jul 17 '22 18:07 bakgerman

Think it would make most sense if there was only one AspNetBufferingTargetWrapper, but depending on target-platform, then it hooked up to Http-Module or Http-Middleware. Maybe the Http-Module and Http-Middleware could implement an internal-interface, if it would make the common AspNetBufferingTargetWrapper-implementation-cleaner.

Would also prefer if it was possible to support ServiceFabric on AspNetCore, so one could have multiple web-sites running within the same host-application (Each with their own instance of NLog-Logging-Provider + NLog LogFactory-Instance + NLog Targets Instances). Maybe the HttpContext-usage should be different, so it is actually the target that initializes the buffer on first log-event-write (instead of middleware initializing the buffer upfront). But it is the middleware that flushes buffers on end-request. (The target-wrapper doesn't have to hook up with the middleware, but will use the HttpContext).

snakefoot avatar Jul 23 '22 14:07 snakefoot

Think it would make most sense if there was only one AspNetBufferingTargetWrapper, but depending on target-platform, then it hooked up to Http-Module or Http-Middleware. Maybe the Http-Module and Http-Middleware could implement an internal-interface, if it would make the common AspNetBufferingTargetWrapper-implementation-cleaner.

Would also prefer if it was possible to support ServiceFabric on AspNetCore, so one could have multiple web-sites running within the same host-application (Each with their own instance of NLog-Logging-Provider + NLog LogFactory-Instance + NLog Targets Instances). Maybe the HttpContext-usage should be different, so it is actually the target that initializes the buffer on first log-event-write (instead of middleware initializing the buffer upfront). But it is the middleware that flushes buffers on end-request (The target-wrapper doesn't have to hook up with the middleware, but will use the HttpContext).

The code has been altered to have only 1 TargetWrapper, and the buffer is now initialized on first log event write. There is already a common base class the Module and Middleware both use. I have dropped the OnBeginRequest event, dropped HttpContextEventArgs class, and use injected IHttpContextAccessor same as the LayoutRender base class.

bakgerman avatar Jul 23 '22 15:07 bakgerman

Yes a static flush method on AspNetBufferWrapper would be good (Taking the HttpContext as input-parameter)

snakefoot avatar Jul 26 '22 17:07 snakefoot

Should we merge this in, or close and leave unmerged? Have we received any community feedback?

bakgerman avatar Dec 09 '22 01:12 bakgerman

Should we merge this in, or close and leave unmerged? Have we received any community feedback?

I have not heard anything from anyone, even though we been poking those who once showed interest.

But I like the change and think it is an improvement of the existing logic. Could you "repair" the pull-request so it becomes a non-breaking change:

  • Keep the old name NLogHttpModule (And not NLogBufferingTargetWrapperModule)
  • Perform mixed reset of your pull-request so it becomes a single commit, and see if we can get AspNetBufferingTargetWrapper.cs to become a "move" instead of "delete" + "add".

snakefoot avatar Dec 10 '22 12:12 snakefoot

Should we merge this in, or close and leave unmerged? Have we received any community feedback?

I have not heard anything from anyone, even though we been poking those who once showed interest.

But I like the change and think it is an improvement of the existing logic. Could you "repair" the pull-request so it becomes a non-breaking change:

  • Keep the old name NLogHttpModule (And not NLogBufferingTargetWrapperModule)
  • Perform mixed reset of your pull-request so it becomes a single commit, and see if we can get AspNetBufferingTargetWrapper.cs to become a "move" instead of "delete" + "add".

Kept the old name.
Working on he git reset

bakgerman avatar Dec 12 '22 01:12 bakgerman

Moved to another pull request: #900

bakgerman avatar Dec 13 '22 04:12 bakgerman