Hi, I wanted to let you know about an issue we're seeing in ASP.NET Web API v5.2.7 when using IndexAsync and BulkSize causes messages to be sent during a request. If sending the messages does not finish before the request is complete then we see an unobserved task exception like this one (which also likely means that sending log messages is aborted):
System.AggregateException: A Task's exception(s) were not observed either by Waiting on the Task or accessing its Exception property. As a result, the unobserved exception was rethrown by the finalizer thread. ---> System.NullReferenceException: Object reference not set to an instance of an object.
at System.Web.ThreadContext.AssociateWithCurrentThread(Boolean setImpersonationContext)
at System.Web.HttpApplication.OnThreadEnterPrivate(Boolean setImpersonationContext)
at System.Web.HttpApplication.System.Web.Util.ISyncContext.Enter()
at System.Web.Util.SynchronizationHelper.SafeWrapCallback(Action action)
at System.Threading.Tasks.Task.Execute()
--- End of inner exception stack trace ---
---> (Inner Exception #0) System.NullReferenceException: Object reference not set to an instance of an object.
at System.Web.ThreadContext.AssociateWithCurrentThread(Boolean setImpersonationContext)
at System.Web.HttpApplication.OnThreadEnterPrivate(Boolean setImpersonationContext)
at System.Web.HttpApplication.System.Web.Util.ISyncContext.Enter()
at System.Web.Util.SynchronizationHelper.SafeWrapCallback(Action action)
at System.Threading.Tasks.Task.Execute()<---
My rough understanding of why this happens is that when _client.IndexBulkAsync is called and starts running in the background it captures context from ASP.NET, and then when an await completes inside the method (e.g. here) it tries to restore the captured context but since the request has completed the context is no longer available resulting in a NullReferenceException.
To reliably run background processes from a request in ASP.NET one needs to use an approach like HostingEnvironment.QueueBackgroundWorkItem that ensures the background task keeps running after the request completes and that it doesn't try to capture/use context that won't be available after the request completes.
It seems like one easy way to add support for this would be to give us a way to override this line in ElasticSearchAppender to use HostingEnvironment.QueueBackgroundWorkItem. At the moment it seems like we would have to create our own copy of ElasticSearchAppender since DoIndexNow is private.
Here are steps if you want to reproduce this for yourself:
Create an ASP.NET Web API project using log4net for logging and log4stash to send those logs to ES.
In your Global.asax.cs register a handler for TaskScheduler.UnobservedTaskException that logs the exception somehow (so you can see the issue when it happens).
In your ElasticSearchAppender config include the following parameters:
Server=192.168.100.100 (or some other IP that won't respond to requests so sending the log messages will take a long time)
Bulksize=1 (to ensure that Bulksize will be reached when messages are logged during the request)
BulkIdleTimeout=10000 (just has to be long enough to ensure Bulksize is reached)
IndexAsync=True (because if it's false the messages will be sent synchronously and block the ASP.NET request from completing until the messages are sent)
If your ASP.NET Web API controller add the following code:
// Need to force GC so that finalizers are run and unhandled exception is detected.
HostingEnvironment.QueueBackgroundWorkItem(ForceGc);
async Task ForceGc(CancellationToken ct) {
for (int i = 0; i < 30; i++) {
_log.Warn("Forcing GC: " + i);
GC.Collect();
GC.WaitForPendingFinalizers();
await Task.Delay(TimeSpan.FromSeconds(1));
}
}
// Ensure some messages are logged
foreach (var i in Enumerable.Range(1, 10)) {
LogManager.GetLogger(GetType()).Warn($"Test: {i}");
}
Send a request to the controller so the code is run.
Once you do this you should see the unobserved task exception occur.
Some possible workarounds:
Set IndexAsync=False (though this means if BulkSize is reached that the request will be blocked until messages are sent).
Make BulkIdleTimeout and/or Bulksize high enough that it's never reached in practice.
Hi, I wanted to let you know about an issue we're seeing in ASP.NET Web API v5.2.7 when using IndexAsync and BulkSize causes messages to be sent during a request. If sending the messages does not finish before the request is complete then we see an unobserved task exception like this one (which also likely means that sending log messages is aborted):
My rough understanding of why this happens is that when _client.IndexBulkAsync is called and starts running in the background it captures context from ASP.NET, and then when an await completes inside the method (e.g. here) it tries to restore the captured context but since the request has completed the context is no longer available resulting in a NullReferenceException.
To reliably run background processes from a request in ASP.NET one needs to use an approach like HostingEnvironment.QueueBackgroundWorkItem that ensures the background task keeps running after the request completes and that it doesn't try to capture/use context that won't be available after the request completes.
It seems like one easy way to add support for this would be to give us a way to override this line in ElasticSearchAppender to use HostingEnvironment.QueueBackgroundWorkItem. At the moment it seems like we would have to create our own copy of ElasticSearchAppender since DoIndexNow is private.
Here are steps if you want to reproduce this for yourself:
If your ASP.NET Web API controller add the following code:
Once you do this you should see the unobserved task exception occur.
Some possible workarounds: