dotnet / aspnetcore

ASP.NET Core is a cross-platform .NET framework for building modern cloud-based web applications on Windows, Mac, or Linux.
https://asp.net
MIT License
35.35k stars 9.99k forks source link

Unexpected behaviour for Response.OnCompleted #25122

Closed Meowzz95 closed 4 years ago

Meowzz95 commented 4 years ago

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. image

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 commented 4 years ago

Compare between dotnet run and from visual studio

Finish loading fast: dotnet run2

Finish loading slow: visual studio

Tratcher commented 4 years ago

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

https://github.com/dotnet/aspnetcore/issues/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 commented 4 years ago

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 commented 4 years ago

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 commented 4 years ago

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

ghost commented 4 years ago

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.