Delay in client-initiated abort for event stream request #1139
Description
This issue was part of #1103 (see Issue 1), but has been moved to a different issue report to improve trackability. I have tested this on tag 1.0.0, rel/1.0.1 and 3104110 (the commit after #1103 has been marked as completed)
Say I have a controller that sends a 'text/event-stream' response, which writes (Response.WriteAsync()) a string every second. When the client aborts the request (like clicking on the 'Stop' button in chrome), the request in the controller should be aborted immediately. This means that HttpContext.RequestAborted should be set to cancelled immediately. This however doesn't happen. There always seems to be a delay of a couple of WriteAsync() calls
In the sample below, 2 things get written to the console: Starting response {i} and Ended response {i}. Now, when I fire the request and immediately abort the request from 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
The cancellation isn't noticed until the start of the 3rd loop. This always happens and has no connection to the Task.Delay() value, because a delay of 1000 ms and 10.000 ms produce the same result.
After some research 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.
On a side-note: this also happens with other content-types, but I've used a text/event-stream type in this issue as a most likely use-case.
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");
}
});
}
}
}