"EPIPE broken pipe" and "ECANCELED operation canceled" on event stream requests (+ ObjectDisposedException with HTTPS)

[SteveSandersonMS]

Is there a correct, supported way to implement long-running requests that are intended to be closed by the client, e.g., for EventStream?

See the (possibly naive) implementation of ServerSentEventController below. This produces a text/event-stream response. The client-side code keeps open a request to this until the user navigates away, which aborts the request.

Issue 1: Client-initiated aborts

Expected: When the client aborts the request, the HttpContext.RequestAborted token should fire immediately, and the response closes gracefully.

Actual: When the client aborts the request, HttpContext.RequestAborted does not fire immediately. After 5-10 seconds, in the console I get an error like Connection id "0HKUROLPTMNFF" communication error Microsoft.AspNetCore.Server.Kestrel.Internal.Networking.UvException: Error -32 EPIPE broken pipe on OS X, with no stack trace. On Windows, the error is ECANCELED operation canceled, again with no stack trace. Immediately after this error, HttpContext.RequestAborted does fire.

Note that the errors show up regardless of whether the cancellation token is passed to WriteAsync or not.

Issue 2: Server-initiated aborts

If, while the request is ongoing, you ctrl+c in the console to terminate the server app, I'd expect it really to terminate (closing the TCP connection to the client at once). However, the app keeps running for another 5-10 seconds, sending more messages to the client during that period.

Appendix: ServerSentEventController

    public class ServerSentEventController : Controller
    {
        [Route("/event-stream")]
        public async Task MyEventStream()
        {
            HttpContext.Response.Headers.Add("Content-Type", "text/event-stream");

            var ct = HttpContext.RequestAborted;
            while (!ct.IsCancellationRequested)
            {
                try
                {
                    await HttpContext.Response.WriteAsync($"data: Hello ({DateTime.Now})\r\r", ct);
                    await Task.Delay(1000, ct);
                }
                catch (TaskCanceledException)
                {
                    // If the client aborted the request, don't regard it as an error
                }
            }
        }
    }

BTW I know there have been other issues reported previously about EPIPE broken pipe (OS X) and ECANCELED operation canceled (Windows), but those are closed and the above is still a simple repro.

[cesarblum]

I tried reproing with a simple non-MVC app and don't get the same results as you. The token fires as soon as I abort the connection on the client side.

I'll try with an MVC app next; there might be something up the stack affecting this.

[cesarblum]

Same with MVC app - token fires right after I abort the connection on the client side.

Can you share more info on your app? Are you using any middleware?

[SteveSandersonMS]

It's definitely not MVC-specific. See below for a complete repro app that doesn't use MVC.

I tried reproing with a simple non-MVC app and don't get the same results as you

Might it be that you're just not logging the info messages? With the repro app below they are logged to the console.

Complete repro app without MVC

using System;
using System.Threading.Tasks;
using Microsoft.AspNetCore.Builder;
using Microsoft.AspNetCore.Hosting;
using Microsoft.AspNetCore.Http;
using Microsoft.Extensions.Configuration;
using Microsoft.Extensions.DependencyInjection;
using Microsoft.Extensions.Logging;

namespace WebApplication
{
    public class Program
    {
        public static void Main(string[] args)
        {
            new WebHostBuilder().UseKestrel().UseStartup<Startup>().Build().Run();
        }
    }

    public class Startup
    {
        public Startup(IHostingEnvironment env)
        {
            Configuration = new ConfigurationBuilder()
                .SetBasePath(env.ContentRootPath)
                .AddEnvironmentVariables()
                .Build();
        }

        public IConfigurationRoot Configuration { get; }
        public void ConfigureServices(IServiceCollection services) {}

        public void Configure(IApplicationBuilder app, IHostingEnvironment env, ILoggerFactory loggerFactory)
        {
            loggerFactory.AddConsole().AddDebug();

            app.Map("/event-stream", builder => {
                builder.Run(async ctx => {
                    ctx.Response.Headers.Add("Content-Type", "text/event-stream");
                    var ct = ctx.RequestAborted;
                    ct.Register(() => Console.WriteLine("Client disconnected"));
                    while (!ct.IsCancellationRequested)
                    {
                        try
                        {
                            await ctx.Response.WriteAsync($"data: Hello ({DateTime.Now})\r\r");
                            await Task.Delay(1000, ct);
                        }
                        catch (TaskCanceledException)
                        {
                            // If the client aborted the request, don't regard it as an error
                        }
                    }
                });
            });
        }
    }
}

[SteveSandersonMS]

Note that it's worse still if you're using HTTPS, as it throws a ObjectDisposedException as well as logging the EPIPE broken pipe/ECANCELED error (tested on OS X only with Kestrel 1.0.1).

To repro, use the code from my previous comment, but change the Main method to:

public static void Main(string[] args)
{
    new WebHostBuilder()
        .UseUrls("https://*:44300")
        .UseKestrel(opts => {
            opts.UseHttps(new X509Certificate2("ssl.pfx"));
        })
        .UseStartup<Startup>().Build().Run();
}

... and put a valid (e.g., self-signed) PFX file called ssl.pfx in the root of your project.

Now when the client aborts the request, the server still doesn't recognise the disconnection soon enough and will continue to try writing to the response, and then you get this ObjectDisposedException in addition to the EPIPE stuff:

info: Microsoft.AspNetCore.Server.Kestrel[14]
      Connection id "0HKUSH50PE770" communication error
Microsoft.AspNetCore.Server.Kestrel.Internal.Networking.UvException: Error -32 EPIPE broken pipe
info: Microsoft.AspNetCore.Hosting.Internal.WebHost[2]
      Request finished in 4101.0957ms 200 
warn: Microsoft.AspNetCore.Server.Kestrel[0]
      Connection processing ended abnormally
System.ObjectDisposedException: Cannot access a disposed object.
Object name: 'SslStream'.
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Net.Security.SslState.CheckThrow(Boolean authSucessCheck)
   at System.Net.Security.SslStream.get_RemoteCertificate()
   at Microsoft.AspNetCore.Server.Kestrel.Https.HttpsConnectionFilter.<>c__DisplayClass3_0.<OnConnectionAsync>b__1(IFeatureCollection features)
   at Microsoft.AspNetCore.Server.Kestrel.Internal.Http.Frame.Reset()
   at Microsoft.AspNetCore.Server.Kestrel.Internal.Http.Frame`1.<RequestProcessingAsync>d__2.MoveNext()

[cesarblum]

Ah, this is 1.0. I should have asked, sorry. I was testing with what we have in dev, which will be 1.1.

A few points:

• The ObjectDisposedException will be gone in 1.1.0.
• The ECANCELED, EPIPE, ECONNRESET (you might see that one too) log messages are expected. If the client does not gracefully close the connection with Kestrel, this is seen by Kestrel as a network error, which it logs. Note though that it's an information log message i.e. we don't really consider it an error but log what came in from the network for information's sake.
• The delay when hitting Ctrl+C is by design - Kestrel will give any pending connections 5 seconds to shut down gracefully before aborting them.

I still can't repro the 5-10 second delay you see between aborting the connection on the client and the RequestAborted token firing up. Are you running you client and server on separate machines? What is your client - custom code, a browser, ...?

[halter73]

@SteveSandersonMS This doesn't fix the major issue, but if you want ctrrl+c to kill long running requests sooner, you can lower then ShutdownTimeout.

In the case of the client resetting the connection mid chunked request, I think we will always log something (but in 1.1 we've changed this from warning to info level and reduced it to 1 log entry).

We'll look into the ObjectDisposedException.

[nphmuller]

I might have some more information on issue 1. Tried it on both commit 1.0.0 (07e958d) and the current Dev commit (1a273f5).

Sample code:

using System;
using System.Threading.Tasks;
using Microsoft.AspNetCore.Builder;
using Microsoft.AspNetCore.Hosting;
using Microsoft.AspNetCore.Http;
using Microsoft.Extensions.Logging;

namespace SampleApp
{
    public class Startup
    {
        public static void Main(string[] args)
        {
            new WebHostBuilder().UseKestrel().UseUrls("http://localhost:5000").UseStartup<Startup>().Build().Run();
        }

        public void Configure(IApplicationBuilder app, ILoggerFactory loggerFactory)
        {
            loggerFactory.AddConsole(LogLevel.Information);
            app.Run(async ctx =>
            {
                ctx.Response.Headers.Add("Content-Type", "text/event-stream");
                var ct = ctx.RequestAborted;
                for (int i = 0; i < 20; i++)
                {
                    Console.WriteLine($"Started response {i + 1} of 20");
                    try
                    {
                        await Task.Delay(1000, ct);
                        await ctx.Response.WriteAsync($"data: Hello ({DateTime.Now})\r\r");
                    }
                    catch (TaskCanceledException)
                    {
                        break;
                    }
                    Console.WriteLine($"Ended response {i + 1} of 20");
                }
            });
        }
    }
}

Now, when I fire a request from the browser to http://localhost:5000, and immediately abort the request in the browser, the console has the following output:

info: Microsoft.AspNetCore.Hosting.Internal.WebHost[1]
Request starting HTTP/1.1 GET http://localhost:5000/
Started response 1 of 20
Ended response 1 of 20
Started response 2 of 20
Ended response 2 of 20
Started response 3 of 20
info: Microsoft.AspNetCore.Server.Kestrel[14]
Connection id "0HKV17V8EGG77" communication error
Microsoft.AspNetCore.Server.Kestrel.Internal.Networking.UvException: Error -4081 ECANCELED operation canceled
info: Microsoft.AspNetCore.Hosting.Internal.WebHost[2]
Request finished in 2133.1317ms 200 text/event-stream

Note that the cancellation isn't noticed until the start of the 3rd loop. The delay value in Task.Delay() does not matter. 1000 ms and 10.000 ms give the same result.

[SteveSandersonMS]

Thanks for the info @CesarBS / @halter73 / @nphmuller!

@CesarBS - the client I'm using is Chome, and by 'aborting request' I mean 'pressing escape'. I think the delay is probably explained (or at least demonstrated) by @nphmuller's comment.

@halter73 Cool - thanks for letting me know. By "1 log entry", do you mean "per server process lifetime" or "per aborted request"? The latter would be a bit awkward if there was no way to suppress it, because it would happen for every EventStream connection. What's SignalR going to do about this?

[halter73]

Per aborted request. That's why it's informational, so hopefully it can be filtered in that way. Bad requests also have a special logging id (17) in the "Microsoft.AspNetCore.Server.Kestrel" logging category.

It's possible do do what SignalR does, and have the client send an "abort" message to the server, that can then cause the server to close the event source connection gracefully by completing the Task returned by the middleware. The abort by the client can be triggered by window.on(before)unload.

[nphmuller]

Did some more research, and it seems the delay comes all the way from libuv.
For every WriteAsync() call in the sample, libuv calls back to UvWriteCb() in UvWriteReq.cs, with a pointer to the request (UvWriteReq) and a status code describing how the write has been handled. Only after the 3rd WriteAsync() call libuv reports status code -4081 (ECANCELED), which immediately triggers the abort flow in Kestrel.

[muratg]

@CesarBS Investigate/close as needed :)

[cesarblum]

I was wrong when I thought the ObjectDisposedException was incidentally fixed in dev by another change. I can repro it. I'll submit a PR soon.

The problem is that HttpsConnectionFilter references its SslStream in its PrepareRequest delegate. When the connection is aborted, the SslStream instance is disposed by Connection. Meanwhile, the FrameOfT loop might still be running its last iteration and will call Reset, which in turn will call PrepareRequest - hence the ObjectDisposedException.

[cesarblum]

ObjectDisposedException fixed in #1127.

[nphmuller]

Just tested 3104110 with the sample I posted above for issue 1: HttpContext.RequestAborted is only set to cancelled after the 3rd WriteAsync() call to libuv, after a browser (Chrome) initiated abort.

The issue still occurs. Should I make a seperated issue for it? Since this issue was used for 2 seperate issues from the beginning it should be at least easier to track.

[muratg]

@nphmuller Yes, please file another issue. It indeed would make it easier to track. Thank you!