0

I have an awkward issue with IIS 10.0 on Windows Server 2016 and ASP.Net 4.5.2 and MVC 5.2.7.

At times, certain requests do not receive a response and run for minutes, maybe 10 or so, before ending in a lost connection (PR_CONNECT_RESET_ERROR in Firefox on Windows, NSURLDomainError in Firefox on iOS). These are mostly POST requests. When this issue occurs, other GET requests will receive a swift response and a correct result. Normally, POST-request do no take long to be processed, typically less than 3 seconds.

Recycling the associated worker process will make the issue go away, for hours or days.

When today inspected the web server when the issue was going on, I saw little CPU usage, less than 10%, memory 56%, the worker process a modest 615 MB. I saw neither logging in the W3C log of these requests, nor in my custom application logs.

I added the Web-Request-Monitor conform How do I see currently executing web request on IIS 8, but in doing so, the the worker process probably got recycled, as the issue is not currently occurring.

There are a reverse proxy and an access manager between the internet and my web server. I suppose they can have something to do with this issue, but it certainly is related to IIS, as recycling helps.

All of this is happening on a acceptation web server running a newer version of my application. I am not aware of any big changes to the application's architecture that could be involved. Also, there will be very little traffic from other clients, if none at all.

What could be next steps to investigate this issue further?

R. Schreurs
  • 8,587
  • 5
  • 43
  • 62
  • You cannot troubleshoot a low frequency performance issue, as there is no way to get the necessary data (like hang dumps). Low CPU usage and small memory footprint is expected for typical hang issues, as they can be thread/network related. "I saw neither logging in the W3C log of these requests, nor in my custom application logs" is the red flag. If your application logs do have "enter"/"exit" entries, for such you should see only "enter"-s without "exit"-s. So by improving the logging manner you might catch them next time. – Lex Li Jan 05 '20 at 19:24

2 Answers2

4

Update

This issue was definitely caused by log4net. However, it was not related to the log4net.Internal.Debug setting. It was caused by two application domains accessing the same log file. This occasionally resulted in concurrency issues with accessing the log file. It appeared that log4net could not properly handle this and got stuck while writing to the log file.

This log file was configured with the RollingFileAppender option. Since we also used AdoNetAppender, we decided to remove file logging all together.

Original

I have found a probable cause. I'll report the steps I took to investigate the issue.

  1. I activated the Worker Processes feature in IIS.

  2. When, after a couple of days of waiting, the issue started again, I found long running requests. They all had State ExecuteRequestHandler and Module Name ManagedPipelineHandler. They had Time Elapsed of hundreds of seconds.

  3. I also activated the Failed Requests Tracing with a rule for long running requests with a Time Taken of 1 minute.

  4. After a couple of days, I started to receive failed request reports. The failed request all have a GENERAL_SET_RESPONSE_HEADER event as their last event.

  5. I added additional debug logging events for each requests. When debugging in my development environment, at one point, I started to see the hanging behaviour there, on one of the new logging statements(!). The application uses log4net.

  6. I captured a stack trace:

    log4net.dll!log4net.Appender.AppenderSkeleton.DoAppend(log4net.Core.LoggingEvent loggingEvent) log4net.dll!log4net.Util.AppenderAttachedImpl.AppendLoopOnAppenders(log4net.Core.LoggingEvent loggingEvent) log4net.dll!log4net.Repository.Hierarchy.Logger.CallAppenders(log4net.Core.LoggingEvent loggingEvent) log4net.dll!log4net.Repository.Hierarchy.Logger.Log(System.Type callerStackBoundaryDeclaringType, log4net.Core.Level level, object message, System.Exception exception) log4net.dll!log4net.Core.LogImpl.DebugFormat(string format, object arg0)

The DoAppend method uses lock(this), which may very well cause hangs.

I also found out that the config setting log4net.Internal.Debug was set to true, which I do not want under normal circumstances and this may be related. I did not attempt to understand the log4net code, but I remember that logging initially did not work, in the acceptance environment, so the setting may very well have been set to true then, causing the issue to start.

Another indication that this is happening with log4net is that when the issue last occurred, I realized that logging of level standard, only occurs in some POST requests. I found a POST-request that does not log and requests to it where handled normally, while the other POST-requests still hung.

For now, I have set log4net.Internal.Debug to false and will wait to see what happens.

R. Schreurs
  • 8,587
  • 5
  • 43
  • 62
0

IIS recycle fix this issue doesn't mean that this is an IIS issue because all asp.net application run in .net runtime unless it is proved that the request is hang in IIS module.

So you may need to wait this issue happen again, then create a Failed request tracing rule for time-taken. Then it will tell us this issue is happening on IIS pipeline module or .net runtime.

If all request hang in .net runtime. Then you may have to capture a hang dump and do a deep analysis via WINDGB and mex extension. It will tell us what's happening there.

Jokies Ding
  • 3,374
  • 1
  • 5
  • 10
  • What I meant by _but it certainly is related to IIS_ is: it is not (only) caused by other network components. It happens when IIS has received the request and is processing it, possible with the help of a worker process. Apologies for the confusion. – R. Schreurs Jan 15 '20 at 11:52