search

mattwcole / gelf-extensions-logging

GELF provider for Microsoft.Extensions.Logging
MIT License
109 stars 42 forks source link

Potential threading issue when used with AspNetCore #27

Closed darraghjones closed 6 years ago

darraghjones commented 6 years ago

I'm seeing the follow error periodically in my logs....~ 0.5% of requests.

System.NullReferenceException: Object reference not set to an instance of an object.
   at Microsoft.AspNetCore.Http.DefaultHttpContext.get_Items()

I only get this error when the GelfLoggerProvider is added. From what I've read this could be due to accessing the DefaultHttpContext from multiple threads. I've tried disabling scopes to see if that helped, but I still see the error.

I would also like to point out I only notice this when running on AWS ECS.

NatalyDrobot commented 6 years ago

We have also started to get a similar error, but much more often. Lowering the level of logging to Error has helped a little, but... we still have had to stop using the library, because when increasing the frequency of requests to our API, the frequency of NullReferenceException increases.

The last configuration:

"Logging": { "IncludeScopes": true, "LogLevel": { "Default": "Information" }, "Console": { "LogLevel": { "Microsoft.AspNetCore.Diagnostics.ExceptionHandlerMiddleware": "Error", "Microsoft.AspNetCore.Server.Kestrel": "Error", "Microsoft.AspNetCore.Hosting.Internal.WebHost": "Warning", "Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker": "Warning", "Default": "Information" } }, "GELF": { "IncludeScopes": true, "LogLevel": { "Microsoft.AspNetCore.Diagnostics.ExceptionHandlerMiddleware": "Error", "Microsoft.AspNetCore.Server.Kestrel": "Error", "Microsoft.AspNetCore.Hosting.Internal.WebHost": "Warning", "Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker": "Warning", "Default": "Information" } }

mattwcole commented 6 years ago

Thanks for reporting this. The library pushes logs to an internal queue where they are de-queued and sent from background threads (here) so it does indeed look like a threading issue. @darraghjones something in the scope would be my first thought as well. I haven't seen this with aspnetcore 2.0, this will require some investigation.

mattwcole commented 6 years ago

We have been able to reproduce the issue with aspnetcore 2.1. It appears to be because of the enumeration of AdditionalFields on the background thread that serializes GelfMessage. The framework appears to put something in the log scope that ultimately touches HttpContext, and this is accessed in the background during the enumeration. We have a fix that seems to be working - I will include this in a new release over the weekend.

mattwcole commented 6 years ago

I've just pushed v1.5.0-pre1 to nuget.org with an update that should fix this.