Unexpected behaviour for Response.OnCompleted

[Meowzz95]

Describe the bug

Response.OnCompleted(async () =>
                {
                    _logger.LogInformation($"In complete callback, going to sleep");
                    await Task.Run(() => Thread.Sleep(7000));
                    _logger.LogInformation($"sleep done");
                });

The above code should register a handler for OnCompleted event and does not block. This works partially correctly but I found the fav icon is loaded in 6.96s every time I try. To me this looks like somehow the sleep is delaying the load of fav icon.

One of my friends who is on Windows env, reports that the same code, giving different behaviour, which blocks the page for 7s instead of blocking the fav icon, he will follow up in this thread.

To Reproduce

The complete min reproduce can be found here:
https://github.com/Meowzz95/TestResponseOnCompleted

Further technical details

ASP.NET Core version 3.1
Include the output of dotnet --info

.NET Core SDK (reflecting any global.json):
 Version:   3.1.201
 Commit:    b1768b4ae7

Runtime Environment:
 OS Name:     Mac OS X
 OS Version:  10.15
 OS Platform: Darwin
 RID:         osx.10.15-x64
 Base Path:   /usr/local/share/dotnet/sdk/3.1.201/

Host (useful for support):
  Version: 3.1.3
  Commit:  4a9f85e9f8

.NET Core SDKs installed:
  3.1.201 [/usr/local/share/dotnet/sdk]

.NET Core runtimes installed:
  Microsoft.AspNetCore.All 2.2.6 [/usr/local/share/dotnet/shared/Microsoft.AspNetCore.All]
  Microsoft.AspNetCore.App 2.2.6 [/usr/local/share/dotnet/shared/Microsoft.AspNetCore.App]
  Microsoft.AspNetCore.App 3.0.0 [/usr/local/share/dotnet/shared/Microsoft.AspNetCore.App]
  Microsoft.AspNetCore.App 3.1.3 [/usr/local/share/dotnet/shared/Microsoft.AspNetCore.App]
  Microsoft.NETCore.App 2.2.6 [/usr/local/share/dotnet/shared/Microsoft.NETCore.App]
  Microsoft.NETCore.App 3.0.0 [/usr/local/share/dotnet/shared/Microsoft.NETCore.App]
  Microsoft.NETCore.App 3.1.3 [/usr/local/share/dotnet/shared/Microsoft.NETCore.App]

To install additional .NET Core runtimes or SDKs:
  https://aka.ms/dotnet-download

IDE: JB Rider JetBrains Rider 2020.2

Build #RD-202.6397.244, built on August 11, 2020

[YipingRuan]

Compare between dotnet run and from visual studio

Finish loading fast:

Finish loading slow:

[Tratcher]

Which servers? On Mac you must be using Kestrel and http/1.1. In Windows the default is IIS In-Process.

#17268 just improved some of this behavior for IIS In-Process in 5.0.0 rc1. You should be able to try a nightly build soon.

As for kestrel, this behavior makes some sense if the two requests are sent on the same connection back to back. The first request is processed, the response sent, and then OnCompleted gets delayed before it continues processing the next request. If you look at the server logs, both requests should have the same connection ID. In kestrel each connection is effectively a single threaded loop and it reuses most of the structures for the next request, so it needs you to be done with them before continuing.

[Tratcher]

Note HTTP/2 is mostly not affected by these issues because it's designed to multiplex requests. HTTP/2 is enabled by default for https on Windows, but it's not supported on Mac.

[Meowzz95]

Thanks for the explanation, it now makes sense for the different behaviors.

However, according to the documentation

https://docs.microsoft.com/en-us/dotnet/api/microsoft.aspnetcore.http.httpresponse.oncompleted?view=aspnetcore-3.1

Adds a delegate to be invoked after the response has finished being sent to the client.

The delegate should be invoked only after the response finishes sending to the client. So why the page or the fav icon is delayed 7s in this case?

[Tratcher]

Because on kestrel that 7s of delay happens at the end of the prior request, before the favicon request even begins processing.

[ghost]

This issue has been resolved and has not had any activity for 1 day. It will be closed for housekeeping purposes.

See our Issue Management Policies for more information.