6

I'm facing a problem with IIS + Kestrel hosting of asp.net core application (web api).

Sometimes response delay is about 5sec. In such case Chrome shows "GET net::ERR_CONNECTION_TIMED_OUT" (but Firefox waits until response)

It only happens on IIS, if I run it locally within Visual Studio Code it works fine (at least I haven't caught any "freezes").

There is some info from app log on server side. For successful request it looks like:

info: Microsoft.AspNetCore.Hosting.Internal.WebHost[1]
      Request starting HTTP/1.1 OPTIONS http://
info: Microsoft.AspNetCore.Hosting.Internal.WebHost[2]
      Request finished in 0.2813ms 204 
info: Microsoft.AspNetCore.Hosting.Internal.WebHost[1]
      Request starting HTTP/1.1 GET http://
info: Microsoft.AspNetCore.Authentication.JwtBearer.JwtBearerMiddleware[2]
      Successfully validated the token.
info: Microsoft.AspNetCore.Authentication.JwtBearer.JwtBearerMiddleware[3]
      HttpContext.User merged via AutomaticAuthentication from authenticationScheme: Bearer.
info: Microsoft.AspNetCore.Authorization.DefaultAuthorizationService[1]
      Authorization was successful for user: admin.
info: Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker[1]
      Executing action method <method-name> with arguments <args> - ModelState is Valid
info: Microsoft.AspNetCore.Mvc.Internal.ObjectResultExecutor[1]
      Executing ObjectResult, writing value Microsoft.AspNetCore.Mvc.ControllerContext.
info: Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker[2]
      Executed action <method-name> in 41.9809ms
info: Microsoft.AspNetCore.Hosting.Internal.WebHost[2]
      Request finished in 42.6694ms 200 application/json; charset=utf-8

for failed looks like:

info: Microsoft.AspNetCore.Hosting.Internal.WebHost[1]
      Request starting HTTP/1.1 OPTIONS http://
info: Microsoft.AspNetCore.Hosting.Internal.WebHost[2]
      Request finished in 0.3408ms 204

Application pool for that app is set up without managed code.

Web.config contains:

<?xml version="1.0" encoding="utf-8"?>
<configuration>
  <system.webServer>
    <handlers>
      <add name="aspNetCore" path="*" verb="*" modules="AspNetCoreModule" resourceType="Unspecified" />
    </handlers>
    <aspNetCore processPath="dotnet" arguments=".\app.dll" stdoutLogEnabled="true" stdoutLogFile=".\logs\stdout">
      <environmentVariables>
        <environmentVariable name="ASPNETCORE_ENVIRONMENT" value="app-release" />
      </environmentVariables>
    </aspNetCore>
  </system.webServer>
</configuration>

What may be a cause of such strange behaviour?

P.S.

  • IIS version - 10
  • netcoreapp - 1.1 (common "Microsoft.AspNetCore." libraries - 1.1.1)

Update:

I set "Trace" level for logging and didn't see any logs about "corrupted" request, only about requests before. Also took a look at chrome dev's tools "network" tab and there is:

Request Headers
Provisional headers are shown
Access-Control-Request-Headers:access-control-allow-origin,authorization
Access-Control-Request-Method:GET

Update:

I have no idea why but it's started to spontaneously error even on static content like css.

Also I forget to note that I have the same functionality on asp.net web api 2 (not core) - and it works fine on the same server. Founded such info in log before slow request:

dbug: Microsoft.AspNetCore.Server.Kestrel[2]
      Connection id "0HL3SC4O1J78T" stopped.
dbug: Microsoft.AspNetCore.Server.Kestrel[8]
      Connection id "0HL3SC4O1J78S" sent FIN with status "0".
dbug: Microsoft.AspNetCore.Server.Kestrel[2]
      Connection id "0HL3SC4O1J78S" stopped.
dbug: Microsoft.AspNetCore.Server.Kestrel[2]
      Connection id "0HL3SC4O1J78R" stopped.
dbug: Microsoft.AspNetCore.Server.Kestrel[8]
      Connection id "0HL3SC4O1J78V" sent FIN with status "0".
dbug: Microsoft.AspNetCore.Server.Kestrel[2]
      Connection id "0HL3SC4O1J78V" stopped.

Update:

There is no any messages in IIS log (within inetpub/logs) about "corrupted" request too. Just an information about last successful request-response. It looks like request isn't handled by IIS at all. Is it possible (I'm not experienced in IIS setup and configuraiton)?

Also tried to use a stub - empty .net core application instead of my. The result is the same. From what I'm concluding that the problem isn't in my app

user1820686
  • 2,008
  • 5
  • 25
  • 44
  • 1
    How often do you get this behavior? every 2h? once a week? If you can replicate, it might be worth changing the logging to get even more logs(change "Information" to "Debug" or even "Trace"). As it's related to only IIS, do you have a recycling conditions on your application pool? In the event viewer of your windows, do you see something related to your application pool having been restarted? Have you tried enhancing the requestTimeout from your web.config? – Daboul Apr 05 '17 at 13:14
  • @Daboul, randomly, every minute) going to try what you advice, probably get more info... – user1820686 Apr 05 '17 at 13:21
  • I'm having a similar problem - intermittent long response time. Same Core versions, except in an Azure App Service. Was working fine on the preview build before moving to Core SDK 1.0.1, even with the same versions of the ASP.NET libraries. – EFVincent Apr 05 '17 at 22:55
  • @EFVincent, what did you do eventually? which version of Core SDK preview did you downgrade to? and which libraries Microsoft.AspNetCore. did you reference in project? I tried to downgrade to "1.0.1 with SDK Preview 4 build 4233" but without success...Also can't get what to do with "Windows Server Hosting" which uses 1.0.4/1.1.1 versions (I need to host on IIS) – user1820686 Apr 06 '17 at 09:16
  • @user1820686 I haven't solved the problem, but it seems to only occur in certain environments. Still running 1.0.1 release SDK. We have three Azure environments, DEV, QA, and PROD, and it only seems to effect DEV. I'm still investigating. – EFVincent Apr 07 '17 at 13:00
  • Looks a little bit like: https://github.com/aspnet/IISIntegration/issues/305 – Daboul Apr 08 '17 at 16:35
  • Do you have long requets? Have you tried tunning the request timeout of the IIS ASP.NET Core Module https://learn.microsoft.com/en-us/aspnet/core/hosting/aspnet-core-module ? – Daboul Apr 08 '17 at 16:36
  • @Daboul, tried to change requestTimeout - doesn't help :- ( The strangest thing is that static files requests are freezed too – user1820686 Apr 09 '17 at 03:58
  • When your app runs, you must see a dotnet.exe process running in the task manager? Can you monitor its PID? Is it changing over time when you experience slowness? Maybe your app gets unloaded for some reason (recycling ....), and when a new request arrives IIS has to respawn a new process which would explain the delay. – Daboul Apr 09 '17 at 07:44
  • Have you checked your IIS settings? https://www.simple-talk.com/blogs/speeding-up-your-application-with-the-iis-auto-start-feature/ – Ilya Chumakov Apr 09 '17 at 16:41
  • @IlyaChumakov, tried to change settings as you'd suggested - unfortunately without success – user1820686 Apr 10 '17 at 09:29
  • @Daboul, PID is constant during slowness – user1820686 Apr 10 '17 at 09:40
  • https://github.com/aspnet/IISIntegration/issues/245 – Paul Totzke Apr 12 '17 at 19:19

0 Answers0