Unhandled exception: access to disposed logger factory

[paulbatum]

With app insights enabled, I've seen the following failures when executing HTTP triggered functions from the portal:

System.ObjectDisposedException : Cannot access a disposed object.
Object name: 'LoggerFactory'.
   at Microsoft.Extensions.Logging.LoggerFactory.CreateLogger(String categoryName)
   at async Microsoft.Azure.WebJobs.Script.WebHost.WebScriptHostManager.HandleRequestAsync(FunctionDescriptor function,HttpRequestMessage request,CancellationToken cancellationToken) at C:\azure-webjobs-sdk-script\src\WebJobs.Script.WebHost\WebScriptHostManager.cs : 183
   at async Microsoft.Azure.WebJobs.Script.WebHost.Controllers.FunctionsController.ProcessRequestAsync(HttpRequestMessage request,FunctionDescriptor function,CancellationToken cancellationToken) at C:\azure-webjobs-sdk-script\src\WebJobs.Script.WebHost\Controllers\FunctionsController.cs : 110
   at async Microsoft.Azure.WebJobs.Script.WebHost.Controllers.FunctionsController.<>c__DisplayClass3_0.<ExecuteAsync>b__0(??) at C:\azure-webjobs-sdk-script\src\WebJobs.Script.WebHost\Controllers\FunctionsController.cs : 57
   at async Microsoft.Azure.WebJobs.Extensions.Http.HttpRequestManager.ProcessRequestAsync(HttpRequestMessage request,Func`3 processRequestHandler,CancellationToken cancellationToken)
   at async Microsoft.Azure.WebJobs.Script.WebHost.Controllers.FunctionsController.ExecuteAsync(HttpControllerContext controllerContext,CancellationToken cancellationToken) at C:\azure-webjobs-sdk-script\src\WebJobs.Script.WebHost\Controllers\FunctionsController.cs : 59
   at async System.Web.Http.Dispatcher.HttpControllerDispatcher.SendAsync(HttpRequestMessage request,CancellationToken cancellationToken)
   at async System.Web.Http.Dispatcher.HttpControllerDispatcher.SendAsync(HttpRequestMessage request,CancellationToken cancellationToken)
   at async Microsoft.Azure.WebJobs.Script.WebHost.Handlers.SystemTraceHandler.SendAsync(HttpRequestMessage request,CancellationToken cancellationToken) at C:\azure-webjobs-sdk-script\src\WebJobs.Script.WebHost\Handlers\SystemTraceHandler.cs : 50
   at async Microsoft.Azure.WebJobs.Script.WebHost.Handlers.WebScriptHostHandler.SendAsync(HttpRequestMessage request,CancellationToken cancellationToken) at C:\azure-webjobs-sdk-script\src\WebJobs.Script.WebHost\Handlers\WebScriptHostHandler.cs : 63
   at async System.Web.Http.HttpServer.SendAsync(HttpRequestMessage request,CancellationToken cancellationToken)

Unfortunately I don't have a reliable repro - I suspect there is a race. I'm also not sure yet if this is a script level bug or a SDK bug.

[fabiocav]

@cgillum had this issue reported in the context of Durable Functions as well.

Took a quick look at this and the issue seems to be caused by the fact that our config is reused across different host instances, and the ILoggerFactory is associated with that config, but when the host restarts (for any reason), it's dispose logic ultimately disposes of the factory (by disposing of the context, which in turn disposes of the factory here https://github.com/Azure/azure-webjobs-sdk/blob/dev/src/Microsoft.Azure.WebJobs.Host/Executors/JobHostContext.cs#L99), leaving it in a disposed state.
Once the config is passed into the next instance of the host, we'll start seeing these failures.

[fabiocav]

@brettsam / @mathewc / @MikeStall , this is another example of our mutating config object reuse/DI issues biting us.

[brettsam]

Thanks for looking @fabiocav -- I'm taking a look at this now.

While we do reuse the ScriptHostConfiguration, we create a new JobHostConfiguration with every new ScriptHost. That should mean that we get a new LoggerFactory with each new ScriptHost. I also can't seem to figure out why it wouldn't happen every time if we're re-using disposed LoggerFactories. I'm trying to repro this in the portal now but I've not been able to hit it yet.

@paulbatum -- how often were you seeing the issue? Did you have incoming requests at the same time, or were you only issuing requests via the portal?

[cgillum]

FWIW, in the case of Durable Functions the issue goes away if we set the FUNCTIONS_EXTENSION_VERSION app setting to 1.0.11015 and restart the function app.

[brettsam]

@cgillum -- that's b/c I just (re-)added the LoggerFactory disposal with this latest release. We thought we'd fixed the issue with PR #1575, but it's obviously not fully fixed. This HttpTrigger path looks just like the bug we were trying to fix; the Orchestrator one looks completely different.

The common thread is that these seem to be coming via the Portal.

The easy temp fix is to remove the disposal until we can iron this out. I'll do this if I can't get a real fix in place before our next release.

[brettsam]

I see a couple of problems with our fix for #1575 that could cause races -- I'm going to remove the LoggerFactory disposal until we can figure out a solid way to prevent running functions on disposed hosts.

[brettsam]

@cgillum -- so it looks like PR Azure/azure-webjobs-sdk#1192 was actually included in 11015 (it went in a couple days before the release). So I'd guess that you're still exposed to the bug being pinned to this build. The errors that @paulbatum was seeing were run on 11015 as well, which confirms it. It makes me think that the restart of the function app was the important piece in your scenario and you were somehow hitting a race. If you move back to ~1, do you see the bug?

For the issue that @paulbatum is seeing -- the fix for #1537 watches the CanInvoke property of the ScriptHostManager and makes sure we don't run any HTTP functions while it is false. However, in his logs, I can clearly see a Job host stopped, followed a couple seconds later by a wave of HttpTrigger functions being executed and hitting the disposed object exception. Then, shortly after, the host starts back up. Somehow that CanInvoke check must not be protecting us.

It may be b/c we're not setting the Host state to Default quick enough. It feels like we should be setting it before we stop the current host, to make sure that no new requests come in after we call Dispose -- here you can see we don't set it until the loop continues. On a single-core machine, this may be more problematic than on our dev machines. We may want to make sure to set it before the call to Orphan, here.

There's another problem, too. Our usage of the LoggerFactory in Autofac means that it's possible for us to grab the LoggerFactory from a disposed host and pass it to a controller, which also throws. I'll need to address that before re-enabling the LoggerFactory disposal as well.

None of this explains Azure/azure-functions-durable-extension#10. I'm going to start digging into that to see if it is related to either of the issues I've identified here.

[cgillum]

Strangely, I haven't been able to repro it this morning on ~1. A few days ago it was a 100% repro, which supports the idea that this could be a race condition (I'm wondering if noisy neighbors could also have a potential impact - making it even less predictable).

[fabiocav]

@brettsam I'm hoping this issue will be resolved by the DI work we're planning on doing. That factory shouldn't be disposed by the context, and with the plans we have, the lifetime of that object should be properly managed outside of it.

[brettsam]

@fabiocav -- we'll need to chat about the DI lifecycle of the LoggerFactory. Any changes to host.json mean we need to recreate it, for example. So it can't really live with the full lifecycle of the ScriptHostManager. And disposing it forces a flush, which works well for WebJobs scenarios (that's why it's disposed when the host stops).

But -- more related to this issue -- my bigger concern was that we're still running functions on stopped, disposed hosts. It looks like the HttpTrigger still isn't fully prevented from dispatching jobs to the old host during a restart. Even if the LoggerFactory wasn't disposed, any other disposed objects could be in play. It just so happens that we access the LoggerFactory with every invocation, hence the obvious exception.