Aspnetcore: ASP requests hang if ILogger throws

[jroggeman]

Description

ASP.NET requests hang indefinitely if the ILogger being used throws a NotImplementedException from the BeginScope method.

To Reproduce

Steps to reproduce the behavior:
Repro can be found in minimal repository here: https://github.com/jroggeman/aspnetbug

Basic overview:

1. Using ASP.NET Core 2.2.204
2. Create a new ASP.NET web application
3. Create a new dotnet standard library (netstandard2.0)
4. In the library, implement a minimal console logger and provider using ILogger and ILoggerProvider interface. Make sure BeginScope method throws a NotImplementedException
5. In the web app, register the provider and inject it in to the default controller
6. dotnet run the app and request a page from the controller

Observe that the request will hang indefinitely with no output from ASP

Expected behavior

An error is indicated somehow - a 500 is returned from ASP, ASP prints a stack trace,

Additional context

I understand you probably shouldn't inject incomplete implementations of interfaces into ASP :) We've stopped doing that and all is fine. But I would also expect that ASP would realize that this was an error somehow and handle it, rather than hanging the request. So just in case this type of issue is more pervasive, I figured I'd throw it over to you all.

dotnet info:

.NET Core SDK (reflecting any global.json):
 Version:   2.2.204
 Commit:    8757db13ec

Runtime Environment:
 OS Name:     Windows
 OS Version:  10.0.17763
 OS Platform: Windows
 RID:         win10-x64
 Base Path:   C:\Program Files\dotnet\sdk\2.2.204\

Host (useful for support):
  Version: 2.2.5
  Commit:  0a3c9209c0

.NET Core SDKs installed:
  2.1.602 [C:\Program Files\dotnet\sdk]
  2.1.604 [C:\Program Files\dotnet\sdk]
  2.2.202 [C:\Program Files\dotnet\sdk]
  2.2.204 [C:\Program Files\dotnet\sdk]

.NET Core runtimes installed:
  Microsoft.AspNetCore.All 2.1.9 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.All]
  Microsoft.AspNetCore.All 2.1.11 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.All]
  Microsoft.AspNetCore.All 2.2.3 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.All]
  Microsoft.AspNetCore.All 2.2.5 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.All]
  Microsoft.AspNetCore.App 2.1.9 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.App]
  Microsoft.AspNetCore.App 2.1.11 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.App]
  Microsoft.AspNetCore.App 2.2.3 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.App]
  Microsoft.AspNetCore.App 2.2.5 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.App]
  Microsoft.NETCore.App 2.1.9 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
  Microsoft.NETCore.App 2.1.11 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
  Microsoft.NETCore.App 2.2.3 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
  Microsoft.NETCore.App 2.2.5 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]

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

---

Edit: Repo link for bug repro was committed one level too deep so was missing the actual logging library. Fixed now.

[anurse]

I can repro this. If your logger's BeginScope method throws, it bubbles up here and fails to initialize the request, which leaves things hanging. Nothing is logged to show the failure (which makes some sense since the logging fails).

While an ILogger that throws here is incorrect, we should consider yielding that exception somewhere. Interestingly, this only occurs for BeginScope errors. If Log or IsEnabled throws, you immediately get an error in the console (because that exception bubbles all the way up to the top) because we do logging in the startup path (rather than in a request). Should we consider catching this and doing something with it @davidfowl @Tratcher ?

[Tratcher]

Environment.FailFast()....

[anurse]

It's not entirely unreasonable to log it, since we should believe that Log will work if we get a failure here. Of course, if Log does fail, how deep do we go :).

[jkotalik]

Try to log, if it throws again, Environment.FailFast or something?

[davidfowl]

The request shouldn't hang but I don't know what we'd do with this error. Are you thinking this is something server specific?

[anurse]

I think we should consider what happens when things in IHttpApplication.CreateContext throw. This goes a little beyond Logging since it's just the thing causing the problem here. We seem to hang the entire request, and not report anything at all.

[davidfowl]

I don’t want to sprinkle try catch all over our stack to handle a poorly written logger. Can we handle this in the logger factory?

[anurse]

The aggregate logger already "catches" the exception, but only so it can rethrow it as an AggregateException (in case other loggers throw)

[davidfowl]

Maybe we should consider a mode where those pushing those exceptions elsewhere (like pushing them through a diagnostic source or event source).

[anurse]

EventSource is certainly a reasonable place to put these, but wouldn't really solve the immediate problem, which is that you have no idea that the exception occurred unless you catch first-chance exceptions.

[davidfowl]

I don’t see that as a huge problem tbh, your logger implementations should never throw. Maybe we Debug.WriteLine?

[anurse]

Let's at a minimum look at making sure that Kestrel/IIS kill the connection when CreateContext throws. Logging is really hard here because we don't know if it'll work.

[anurse]

Possibly related: https://github.com/aspnet/Extensions/issues/1689