I am trying to host a ASP.NET Core MVC project on a single core Windows Server 2012 host. I am using ASP.NET Core MVC 1.0.0 and running on IIS 8 with .NET Framework 4.6.1 The app works fine at first ~10 minutes, and then suddenly the server stops responding.
At first I thought it was deadlock on database side so I added logging in the DbContext class:
private static long ActiveContextCount = 0;
private ILogger _log;
private Stopwatch _timer = new Stopwatch();
private Guid _contextId = Guid.NewGuid();
public BlogContext(string nameOrConnectionString, ILoggerFactory logger)
:base(nameOrConnectionString)
{
_log = logger.CreateLogger<BlogContext>();
Database.Log = l =>
{
_log.LogInformation(l);
};
ActiveContextCount++;
_timer.Start();
_log.LogInformation("BlogContext created. GUID:{0}, Active count {1}", _contextId, ActiveContextCount);
}
protected override void Dispose(bool disposing)
{
ActiveContextCount--;
_timer.Stop();
_log?.LogInformation("BlogContext Disposed. GUID:{0}, Live time: {1}ms, Active count {2}", _contextId, _timer.ElapsedMilliseconds, ActiveContextCount);
base.Dispose(disposing);
}
I am using Entity Framework 6 and I have setup the DbContext to be scoped:
services.AddScoped(p => new BlogContext(_dataDbConnectionString, p.GetRequiredService<ILoggerFactory>()));
It turned out that the DB operations all works fine. I traced requests in logs and noticed that some request has the last log as:
[Information] Executing ViewResult, running view at path "/Views/Blog/Details.cshtml".
And never finish (i.e. cannot find dispose in the log). From that point the ActiveContextCount
just piles up to a few hundreds and the entire application hangs and stops responding.
(EDIT 08/29) Another example, no query was even executed:
[Information] Request starting HTTP/1.1 GET http://myapp/
[Information] UsersContext created. GUID:bb7743b9-7999-4a01-819f-3d239d34d4d9, Active count 7
[Information] HttpContext.User merged via AutomaticAuthentication from authenticationScheme: "Identity.Application".
[Information] BlogContext created. GUID:8c7505d4-5c87-428e-ad56-12f35f54aadc, Active count 6
[Information] Executing action method "MyApp.Controllers.HomeController.Index (MyApp)" with arguments (["1"]) - ModelState is Valid
[Information] Executing ViewResult, running view at path "/Views/Home/Index.cshtml".
I am stuck at this point. Why does the view result never finish? Is this a bug in the framework or my app? Even if there is a bug, why doesn't the request just be aborted and abandoned after some timeout? I tried to specify a timeout in web.config but doesn't help:
<aspNetCore processPath=".\MyApp.exe" arguments="" forwardWindowsAuthToken="false" stdoutLogEnabled="false" stdoutLogFile=".\logs\stdout" requestTimeout="00:00:40" />
How can I further debug this issue?
So I've finally figured out the problem after a few weeks of debugging. The problem was indeed in the view. I went through the asp.net core doc and noticed this line:
The PartialAsync method is available for partial views containing asynchronous code (although code in views is generally discouraged).
Then I went over to look at the actual implementation of Html.Partial
on github.
var result = htmlHelper.RenderPartialAsync(partialViewName, htmlHelper.ViewData.Model, viewData);
result.GetAwaiter().GetResult();
So the synchronous partial was actually just a blocking wrapper over the async version! And this is the classic async await deadlock (1), since I am calling @await Component.InvokeAysnc
in the partial view (as there is no synchronous version for invoking View Components). I have replaced all Html.Partial
reference to await Html.PartialAsync
and problem solved. I really hope they could have a better warning on this... :(
P.S. I don't have the reputation to post more than 2 links, but why...
(1): blog.stephencleary.com/2012/07/dont-block-on-async-code.html
If you love us? You can donate to us via Paypal or buy me a coffee so we can maintain and grow! Thank you!
Donate Us With