2

Our ASP.NET Web API 2 application is consumed by mobile applications. Using Azure Application Insights we detected many responses with response code 500(Internal server error) without any Exception associated with them in Application Insights. During debugging session we did not encounter any Exception thrown.

We had a suspicion that this could be caused by client disconnects. After implementing a .net application simulating disconnects, we could replicate this issue even on a clean webapi2 project.

After further investigation we found out, that the result code 500(after the client is disconnected) occurs only when specific conditions are met. The request need to be cancelled on a non GET http operation and before ExecuteRequestHandler asp.net event is reached. On GET requests we cannot replicate this issue, neither on requests which entered or passed the ExecuteRequestHandler event.

Our goal is to filter out client disconnects from logs and focus on real issues.

This issue may be related to ASP.NET Web API OperationCanceledException when browser cancels the request, however the accepted solution does not work, because the disconnect occurs before any DelegatingHandler is reached. We would not use the mentioned solution, because client disconnects is not a Server issue but rather a client. For example in netcore the cancelled requests have response code 0 in logs. Anyway, the client will not see the result nor the result code because it is already gone.

Other possibly related question.

We are using the latest version Microsoft.AspNet.WebApi v5.2.7 and the investigation take place only on a development machine with IISExpress.

UPDATE

Including the minimal code to reproduce on clean webapi2 project.

Global.asax.cs

public class WebApiApplication : System.Web.HttpApplication
{
    protected void Application_Start()
    {
        GlobalConfiguration.Configure(WebApiConfig.Register);
    }

    protected void Application_EndRequest(object sender, EventArgs e)
    {
        var context = HttpContext.Current;
        Debug.WriteLine($"{context.Response.StatusCode}:{context.Response.SubStatusCode}:{context.Request.Path}:{context.Request.Url.AbsoluteUri}");
    }
}

HomeController.cs

[RoutePrefix("api/foo")]
public class HomeController : ApiController
{
    [Route("bar")]
    [HttpPut]
    public async Task<IHttpActionResult> Put()
    {
        await Task.Delay(200);
        return Ok();
    }
}

PUT http://localhost:56952/api/foo/bar

On average 1 of 5 cancelled requests end with 500 when cancelled after 10ms. The response code is accessible from server logs Application Insights or Output Window in VS when logged. The client will not receive the response code, because the connection is closed before any response code is returned.

UPDATE 2

Telemetry from Application Insights

Application Insights Telemetry log

Pietro
  • 413
  • 2
  • 11
  • could you share some sample code? you could try to use some tools like debug diagnostic tool to capture some dump and anlays the dump file. – Jalpa Panchal Oct 17 '19 at 06:22
  • @JalpaPanchal the issue can be reproduced in defalut webapi project, we only introduced logging in global.asax EndRequest event, PUT action in home controller returning 200 and a client which cancels request after 10ms. If any of this could help you I can update the question with code or publish it on github. – Pietro Oct 17 '19 at 11:20
  • it is really very convenient if you post a sample project. – Jalpa Panchal Oct 18 '19 at 07:54
  • @JalpaPanchal I have updated the question with the code modification on clean webapi2 project. – Pietro Oct 18 '19 at 11:50
  • I can not reproduce your issue. could you share the detailed error message snapshot? – Jalpa Panchal Oct 22 '19 at 09:35
  • @JalpaPanchal Cancelled requests do not have any error message. They only appear in application insights, see the picture included in the question. – Pietro Oct 22 '19 at 11:05
  • I tried to write the simulate code as well but still not able to reproduce the issue. could you share the exact part of the code of your project? – Jalpa Panchal Oct 24 '19 at 02:15
  • @JalpaPanchal https://github.com/pietro753/stackoverflow58411426 there you go – Pietro Nov 04 '19 at 12:16
  • how do you cancel in 10ms? what app u usign? – Joebet Mutia Sep 09 '22 at 00:08

1 Answers1

1

I am considering this as a bug in .Net Framework. I have written a workaround to end the currently executing request when the specified criterion are met:

  • Cancellation is requested from the client
  • Client is not connected
  • Handling should occur only before the ExecuteRequestHandler event
public class CancellationHttpModule : IHttpModule
{
    public void Init(HttpApplication application)
    {
        application.OnExecuteRequestStep(OnExecuteRequestStep);
    }

    private void OnExecuteRequestStep(HttpContextBase context, Action step)
    {
        if (context.Response.StatusCode != 0 
            && context.Response.ClientDisconnectedToken.IsCancellationRequested
            && !context.Response.IsClientConnected
            && (int)context.CurrentNotification < (int)RequestNotification.ExecuteRequestHandler)
        {

            context.Response.StatusCode = 0;
            context.ApplicationInstance.CompleteRequest();
        }
        step();
    }


    public void Dispose()
    {
    }
}

After the handling takes places, status code is changed to zero(just like in .net core) and skipping all remaining events in ASP.NET pipeline to EndRequest event. I have tested this implementation on production for a month and did not find requests resulting into 500 without a corresponding Exception record in logs.

Pietro
  • 413
  • 2
  • 11