serilog-web / classic

[Discontinued] Serilog web request logging and enrichment for classic ASP.NET applications
Apache License 2.0
79 stars 32 forks source link

HttpModule stops working when stressed. #60

Closed ghost closed 5 years ago

ghost commented 5 years ago

When using the HttpModule and putting a large number of requests through it suddenly stops working with no error logs or exceptions. Once this occurs all Serilog logging stops and the service has to be restarted.

Using

tsimbalar commented 5 years ago

Ouch :-/

Any information you can provide would be helpful.

Do you see any errors related to IIS in the Windows Event Viewer ? This would typically contain the details of unhandled exceptions, or details of things that went wrong at a lower level (like Http Modules)

ghost commented 5 years ago

Here is my current Logger config for Serilog

    Log.Logger = New LoggerConfiguration() _
        .MinimumLevel.Debug() _
        .Enrich.WithClaimValue("IDs") _
        .WriteTo.Trace() _
        .WriteTo.Seq(serverUrl:="http://localhost:5341") _
        .Filter.ByExcluding(Matching.WithProperty(Of String)("Controller", Function(x) x.Contains("/api/security"))) _
        .CreateLogger()

Here is the config for SerilogWebClassic

SerilogWebClassic.Configure(Function(cfg) As SerilogWebClassicConfigurationBuilder
    Return cfg _
      .EnableFormDataLogging(Function(form)
             Return form.AtLevel(LogEventLevel.Information)
        End Function) _
        .LogAtLevel(LogEventLevel.Information) _
        .IgnoreRequestsMatching(Function(ctx)
        Return ctx.Request.RawUrl.Contains("swagger") _
        Or ctx.Request.HttpMethod.ToString.Equals("OPTIONS")
        End Function)
    End Function)

Sorry about the formatting

This is only part of my usual config which is mostly disabled at the moment but even removing everything except the Trace sing still causes the issue.

There are some errors in the event log. Here is a sample of one, the rest are very similar. The code is being run on IIS express through Visual studio at the moment but the details are the same.

Exception information: 
    Exception type: OperationCanceledException 
    Exception message: The operation was canceled.
   at System.Threading.CancellationToken.ThrowOperationCanceledException()
   at System.Web.Http.Owin.HttpMessageHandlerAdapter.<SendResponseContentAsync>d__20.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.ValidateEnd(Task task)
   at System.Web.Http.Owin.HttpMessageHandlerAdapter.<InvokeCore>d__0.MoveNext()

I am also getting logs that say the following

The directory specified for caching compressed content C:\Users\name\AppData\Local\Temp\iisexpress\IIS Temporary Compressed Files\Clr4IntegratedAppPool is invalid.  Static compression is being disabled

Hope this helps. Thank you

tsimbalar commented 5 years ago

I'm afraid I can't be very helpful here :-/

and putting a large number of requests through it suddenly stops

How many requests are we talking about ?

When using the HttpModule and putting a large number of requests through it suddenly stops working with no error logs or exceptions.

do you mean the app stops working, or just that there are no more request logs being generated ?

Those logs (OperationCanceledException and Owin.HttpMessageHandlerAdapter.<SendResponseContentAsync>) seem to be quite common and harmless, as mentioned in https://github.com/IdentityServer/IdentityServer3/issues/3496 or https://stackoverflow.com/questions/47959800/what-is-causing-operationcanceledexception-in-owin-pipeline , but I'm not 100% sure.

OperationCanceledException are typically related to Tasks or async/await issues ...

tsimbalar commented 5 years ago

Also, which version of Windows are you using, which version of IIS ?

ghost commented 5 years ago

Thank you for looking into this. By large number i mean somewhere between 50 to 100 in a few seconds. I opened several web pages and refreshed them all at the same time, each of the pages would do about 10 requests each. Part way through this it would suddenly stop logging but the application would continue working. I am working on windows 10 though visual studio 2015.

However, I think I have managed to sort the issue.

After much frustration i removed all traces of Serilog and it's extensions from my project with intention of trying another logging system. After starting and realizing how much it would be compared to Seriog with the web classic module I started to add Serilog back into the project. I did this one package at a time and running the tests with the intent of working out which setting and package was causing the issues. This was the second time of running through this process but this time I have not run into any issues at all.

I would love to know what the issue was but I cannot recreate the issue.

Apologies if I have wasted your time and i appreciate your help and advice. Thank you

tsimbalar commented 5 years ago

Thanks, I appreciate that you took the time to try and reproduce it , and thanks for looping back to us.

Will close the issue for now, glad to re-open it if the issue comes back ;)