Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Static file request missing HTTP method, and therefore rejected #4195

Closed
vankampenp opened this issue Nov 21, 2018 · 11 comments
Closed

Static file request missing HTTP method, and therefore rejected #4195

vankampenp opened this issue Nov 21, 2018 · 11 comments

Comments

@vankampenp
Copy link

Describe the bug

A clear and concise description of what the bug is.

I am getting a 404, mostly on one image, however, intermittently, also on others on the same page. This occurs only in debug deployment, not when deploying the Release configuration.

Chrome Console:
GET https://{my domain}/css/images/btn-info.png 404 (Not Found)

Server Log:

2018-11-21 20:34:29.3242||INFO |8.11.15.0||Microsoft.AspNetCore.Hosting.Internal.WebHost|||Request starting HTTP/1.1  http://{my domain}/css/images/btn-info.png  |
2018-11-21 20:34:29.3242||TRACE|8.11.15.0||Microsoft.AspNetCore.HostFiltering.HostFilteringMiddleware|||All hosts are allowed.|


2018-11-21 20:34:29.3242|DEBUG|8.11.15.0||Microsoft.AspNetCore.Authentication.Cookies.CookieAuthenticationHandler|||AuthenticationScheme: Identity.Application was successfully authenticated.|
2018-11-21 20:34:29.3242|5294|DEBUG|8.11.15.0||Microsoft.AspNetCore.StaticFiles.StaticFileMiddleware||| requests are not supported|
2018-11-21 20:34:29.3242|5294|DEBUG|8.11.15.0||Microsoft.AspNetCore.Routing.RouteConstraintMatcher|||Route value 'css' with key 'area' did not match the constraint 'Microsoft.AspNetCore.Mvc.Routing.KnownRouteValueConstraint'.|
2018-11-21 20:34:29.3242|5294|DEBUG|8.11.15.0||Microsoft.AspNetCore.Builder.RouterMiddleware|||Request did not match any routes.|
2018-11-21 20:34:29.3242|5294|DEBUG|8.11.15.0||Microsoft.AspNetCore.StaticFiles.StaticFileMiddleware||| requests are not supported|
2018-11-21 20:34:29.3242|5294|DEBUG|8.11.15.0||Microsoft.AspNetCore.Builder.RouterMiddleware|||Request did not match any routes.|
2018-11-21 20:34:29.3242|5294|DEBUG|8.11.15.0||Microsoft.AspNetCore.Server.Kestrel|||Connection id "0HLIFT0Q49UEQ" completed keep alive response.|
2018-11-21 20:34:29.3242|5294|INFO |8.11.15.0||Microsoft.AspNetCore.Hosting.Internal.WebHost|||Request finished in 0.8642ms 404 |

Notice the space before " requests are not allowed" and in the line Request starting.... The HTTP method is missing. I assume that this is causing the StaticFileMiddleware to reject the request. But why is this missing?

All other requests in the log have the HTTP method, e.g:

2018-11-21 20:34:28.8363||INFO |8.11.15.0||Microsoft.AspNetCore.Hosting.Internal.WebHost||GET|Request starting HTTP/1.1 GET http://{my domain}/css/style.css?v=wJW-HAqVN3UbVwRE4u0aQGaFW9TF5e3V4_3yaApkzoo  |

The image is loaded from css:

.btn-info {
    background-image: url("images/btn-info.png");
    background-repeat: no-repeat;
    background-position: center;
}

Startup:

app.UseStaticFiles(new StaticFileOptions
            {
                OnPrepareResponse = ctx =>
                {
                    const int durationInSeconds = 15778463; // 6 months
                    ctx.Context.Response.Headers.Append("Cache-Control", $"public, max-age={durationInSeconds}");
                }
            });

This is the pubxml:
<Project ToolsVersion="4.0" xmlns="http://schemas.microsoft.com/developer/msbuild/2003">
  <PropertyGroup>
    <WebPublishMethod>MSDeploy</WebPublishMethod>
    <LastUsedBuildConfiguration>Debug</LastUsedBuildConfiguration>
    <LastUsedPlatform>Any CPU</LastUsedPlatform>
    <SiteUrlToLaunchAfterPublish>https://{my domain}/online</SiteUrlToLaunchAfterPublish>
    <LaunchSiteAfterPublish>True</LaunchSiteAfterPublish>
    <ExcludeApp_Data>False</ExcludeApp_Data>
    <ProjectGuid>{guid}</ProjectGuid>
    <MSDeployServiceURL>http://{my domain}:80/MSDeployAgentService</MSDeployServiceURL>
    <DeployIisAppPath>nl.managetests</DeployIisAppPath>
    <RemoteSitePhysicalPath />
    <LangVersion>latest</LangVersion>
    <SkipExtraFilesOnServer>True</SkipExtraFilesOnServer>
    <MSDeployPublishMethod>RemoteAgent</MSDeployPublishMethod>
    <LangVersion>latest</LangVersion>
    <EnableMSDeployBackup>True</EnableMSDeployBackup>
    <DeleteExistingFiles>False</DeleteExistingFiles>
    <EnableMSDeployAppOffline>True</EnableMSDeployAppOffline>
    <UserName>Administrator</UserName>
    <_SavePWD>True</_SavePWD>
    <PublishDatabaseSettings>
      <Objects xmlns="" />
    </PublishDatabaseSettings>
    <TargetFramework>netcoreapp2.1</TargetFramework>
    <SelfContained>false</SelfContained>
    <_IsPortable>true</_IsPortable>
  </PropertyGroup>
</Project>

Additional context

Add any other context about the problem here.
ISS on Windows Server 2012 R2
Include the output of dotnet --info (on the development PC)

.NET Core SDK (reflecting any global.json):
Version: 2.1.403
Commit: 04e15494b6

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

Host (useful for support):
Version: 2.1.5
Commit: 290303f510

.NET Core SDKs installed:
1.0.0 [C:\Program Files\dotnet\sdk]
1.1.0 [C:\Program Files\dotnet\sdk]
2.1.4 [C:\Program Files\dotnet\sdk]
2.1.103 [C:\Program Files\dotnet\sdk]
2.1.104 [C:\Program Files\dotnet\sdk]
2.1.200 [C:\Program Files\dotnet\sdk]
2.1.201 [C:\Program Files\dotnet\sdk]
2.1.202 [C:\Program Files\dotnet\sdk]
2.1.301 [C:\Program Files\dotnet\sdk]
2.1.302 [C:\Program Files\dotnet\sdk]
2.1.402 [C:\Program Files\dotnet\sdk]
2.1.403 [C:\Program Files\dotnet\sdk]

.NET Core runtimes installed:
Microsoft.AspNetCore.All 2.1.1 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.All]
Microsoft.AspNetCore.All 2.1.2 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.All]
Microsoft.AspNetCore.All 2.1.4 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.All]
Microsoft.AspNetCore.All 2.1.5 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.All]
Microsoft.AspNetCore.App 2.1.1 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.App]
Microsoft.AspNetCore.App 2.1.2 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.App]
Microsoft.AspNetCore.App 2.1.4 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.App]
Microsoft.AspNetCore.App 2.1.5 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.App]
Microsoft.NETCore.App 1.0.4 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
Microsoft.NETCore.App 1.0.5 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
Microsoft.NETCore.App 1.1.1 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
Microsoft.NETCore.App 1.1.2 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
Microsoft.NETCore.App 2.0.5 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
Microsoft.NETCore.App 2.0.6 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
Microsoft.NETCore.App 2.0.7 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
Microsoft.NETCore.App 2.0.9 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
Microsoft.NETCore.App 2.1.1 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
Microsoft.NETCore.App 2.1.2 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
Microsoft.NETCore.App 2.1.4 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
Microsoft.NETCore.App 2.1.5 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]

To install additional .NET Core runtimes or SDKs:
https://aka.ms/dotnet-download
@Tratcher
Copy link
Member

This is using Kestrel, correct?

When we've seen this before it was always caused by async state corruption by the prior request on that connection. Can you pull the logs for the prior request?

The common issue is when a background thread holds onto the HttpContext and accesses it inappropriately after the end of the request. This can corrupt resources that are shared with future requests on that connection.

@vankampenp
Copy link
Author

@Tratcher The page (action= Switchboard) is used multple times, showing slightly different content. The last time loading that page it fails. I was first logging out (SignOutAsync()) before the last time showing that page, but I had already removed that to see if that caused some type of corruption.

Here requests that are going to that page, ending with the request that fails.


2018-11-21 20:34:28.7699|5294|DEBUG|8.11.15.0||DTOWEB.Controllers.BaseController|Base|GET|Switchboard in 15 ms|
2018-11-21 20:34:28.7699|5294|INFO |8.11.15.0||Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker|Base|GET|Executed action method DTOWEB.Controllers.BaseController.SwitchBoard (DTOWEB), returned result Microsoft.AspNetCore.Mvc.ViewResult in 15.6645ms.|
2018-11-21 20:34:28.7699|5294|TRACE|8.11.15.0||Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker|Base|GET|Action Filter: Before executing OnActionExecuted on filter Microsoft.AspNetCore.Mvc.ModelBinding.UnsupportedContentTypeFilter.|
2018-11-21 20:34:28.7699|5294|TRACE|8.11.15.0||Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker|Base|GET|Action Filter: After executing OnActionExecuted on filter Microsoft.AspNetCore.Mvc.ModelBinding.UnsupportedContentTypeFilter.|
2018-11-21 20:34:28.7699|5294|TRACE|8.11.15.0||Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker|Base|GET|Action Filter: After executing OnActionExecutionAsync on filter Microsoft.AspNetCore.Mvc.Internal.ControllerActionFilter.|
2018-11-21 20:34:28.7699|5294|TRACE|8.11.15.0||Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker|Base|GET|Result Filter: Before executing OnResultExecuting on filter Microsoft.AspNetCore.Mvc.ViewFeatures.Internal.SaveTempDataFilter.|
2018-11-21 20:34:28.7699|5294|TRACE|8.11.15.0||Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker|Base|GET|Result Filter: After executing OnResultExecuting on filter Microsoft.AspNetCore.Mvc.ViewFeatures.Internal.SaveTempDataFilter.|
2018-11-21 20:34:28.7699|5294|TRACE|8.11.15.0||Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker|Base|GET|Before executing action result Microsoft.AspNetCore.Mvc.ViewResult.|
2018-11-21 20:34:28.7699|5294|DEBUG|8.11.15.0||Microsoft.AspNetCore.Mvc.Razor.RazorViewEngine|Base|GET|View lookup cache hit for view 'switchboard' in controller 'Base'.|
2018-11-21 20:34:28.7699|5294|INFO |8.11.15.0||Microsoft.AspNetCore.Mvc.ViewFeatures.ViewResultExecutor|Base|GET|Executing ViewResult, running view switchboard.|
2018-11-21 20:34:28.7699|5294|DEBUG|8.11.15.0||Microsoft.AspNetCore.Mvc.ViewFeatures.ViewResultExecutor|Base|GET|The view path '/Views/Base/switchboard.cshtml' was found in 0.0662ms.|
2018-11-21 20:34:28.7699|5294|DEBUG|8.11.15.0||Microsoft.AspNetCore.Mvc.Razor.RazorViewEngine|Base|GET|View lookup cache hit for view '_Layout' in controller 'Base'.|
2018-11-21 20:34:28.7699|5294|DEBUG|8.11.15.0||Microsoft.AspNetCore.Mvc.Razor.RazorViewEngine|Base|GET|View lookup cache hit for view 'Head' in controller 'Base'.|
2018-11-21 20:34:28.7852|5294|TRACE|8.11.15.0||Microsoft.AspNetCore.DataProtection.KeyManagement.KeyRingBasedDataProtector|Base|GET|Performing unprotect operation to key {cafa52a6-433a-4452-9a55-dfa495b6ff78} with purposes ('C:\Data\stage\devserver\httpdocs', 'Microsoft.AspNetCore.Antiforgery.AntiforgeryToken.v1').|
2018-11-21 20:34:28.7852|5294|TRACE|8.11.15.0||Microsoft.AspNetCore.DataProtection.KeyManagement.KeyRingBasedDataProtector|Base|GET|Performing protect operation to key {cafa52a6-433a-4452-9a55-dfa495b6ff78} with purposes ('C:\Data\stage\devserver\httpdocs', 'Microsoft.AspNetCore.Antiforgery.AntiforgeryToken.v1').|
2018-11-21 20:34:28.7852|5294|DEBUG|8.11.15.0||Microsoft.AspNetCore.Antiforgery.Internal.DefaultAntiforgery|Base|GET|An antiforgery cookie token was reused.|
2018-11-21 20:34:28.7852|5294|INFO |8.11.15.0||Microsoft.AspNetCore.Mvc.ViewFeatures.ViewResultExecutor|Base|GET|Executed ViewResult - view switchboard executed in 4.7629ms.|
2018-11-21 20:34:28.7852|5294|TRACE|8.11.15.0||Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker|Base|GET|After executing action result Microsoft.AspNetCore.Mvc.ViewResult.|
2018-11-21 20:34:28.7852|5294|TRACE|8.11.15.0||Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker|Base|GET|Result Filter: Before executing OnResultExecuted on filter Microsoft.AspNetCore.Mvc.ViewFeatures.Internal.SaveTempDataFilter.|
2018-11-21 20:34:28.7852|5294|TRACE|8.11.15.0||Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker|Base|GET|Result Filter: After executing OnResultExecuted on filter Microsoft.AspNetCore.Mvc.ViewFeatures.Internal.SaveTempDataFilter.|
2018-11-21 20:34:28.7852|5294|TRACE|8.11.15.0||Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker|Base|GET|Resource Filter: Before executing OnResourceExecuted on filter Microsoft.AspNetCore.Mvc.ViewFeatures.Internal.SaveTempDataFilter.|
2018-11-21 20:34:28.7852|5294|TRACE|8.11.15.0||Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker|Base|GET|Resource Filter: After executing OnResourceExecuted on filter Microsoft.AspNetCore.Mvc.ViewFeatures.Internal.SaveTempDataFilter.|
2018-11-21 20:34:28.7852|5294|INFO |8.11.15.0||Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker|Base|GET|Executed action DTOWEB.Controllers.BaseController.SwitchBoard (DTOWEB) in 21.0552ms|
2018-11-21 20:34:28.7852|5294|DEBUG|8.11.15.0||Microsoft.AspNetCore.Server.Kestrel|Base|GET|Connection id "0HLIFT0Q49UES" completed keep alive response.|
2018-11-21 20:34:28.7852|5294|DEBUG|8.11.15.0||Microsoft.EntityFrameworkCore.Infrastructure|Base|GET|'DTOIdentityDBContext' disposed.|
2018-11-21 20:34:28.7852|5294|INFO |8.11.15.0||Microsoft.AspNetCore.Hosting.Internal.WebHost|Base|GET|Request finished in 26.3287ms 200 text/html; charset=utf-8|
2018-11-21 20:34:28.8363||INFO |8.11.15.0||Microsoft.AspNetCore.Hosting.Internal.WebHost||GET|Request starting HTTP/1.1 GET http://{mydomain}/css/style.css?v=wJW-HAqVN3UbVwRE4u0aQGaFW9TF5e3V4_3yaApkzoo  |
2018-11-21 20:34:28.8363||TRACE|8.11.15.0||Microsoft.AspNetCore.HostFiltering.HostFilteringMiddleware||GET|All hosts are allowed.|
2018-11-21 20:34:28.8363||TRACE|8.11.15.0||Microsoft.AspNetCore.DataProtection.KeyManagement.KeyRingBasedDataProtector||GET|Performing unprotect operation to key {cafa52a6-433a-4452-9a55-dfa495b6ff78} with purposes ('C:\Data\stage\devserver\httpdocs', 'Microsoft.AspNetCore.Authentication.Cookies.CookieAuthenticationMiddleware', 'Identity.Application', 'v2').|
2018-11-21 20:34:28.8363||DEBUG|8.11.15.0||Microsoft.AspNetCore.Authentication.Cookies.CookieAuthenticationHandler||GET|AuthenticationScheme: Identity.Application was successfully authenticated.|
2018-11-21 20:34:28.8363|5294|TRACE|8.11.15.0||Microsoft.AspNetCore.StaticFiles.StaticFileMiddleware||GET|Range header's value is empty.|
2018-11-21 20:34:28.8363|5294|INFO |8.11.15.0||Microsoft.AspNetCore.StaticFiles.StaticFileMiddleware||GET|Sending file. Request path: '/css/style.css'. Physical path: 'C:\Data\stage\devserver\httpdocs\wwwroot\css\style.css'|
2018-11-21 20:34:28.8363|5294|DEBUG|8.11.15.0||Microsoft.AspNetCore.Server.Kestrel||GET|Connection id "0HLIFT0Q49UEQ" completed keep alive response.|
2018-11-21 20:34:28.8363|5294|INFO |8.11.15.0||Microsoft.AspNetCore.Hosting.Internal.WebHost||GET|Request finished in 1.109ms 200 text/css|
2018-11-21 20:34:28.8363||INFO |8.11.15.0||Microsoft.AspNetCore.Hosting.Internal.WebHost||GET|Request starting HTTP/1.1 GET http://{mydomain}/images/check.jpg  |
2018-11-21 20:34:28.8363||TRACE|8.11.15.0||Microsoft.AspNetCore.HostFiltering.HostFilteringMiddleware||GET|All hosts are allowed.|
2018-11-21 20:34:28.8363||TRACE|8.11.15.0||Microsoft.AspNetCore.DataProtection.KeyManagement.KeyRingBasedDataProtector||GET|Performing unprotect operation to key {cafa52a6-433a-4452-9a55-dfa495b6ff78} with purposes ('C:\Data\stage\devserver\httpdocs', 'Microsoft.AspNetCore.Authentication.Cookies.CookieAuthenticationMiddleware', 'Identity.Application', 'v2').|
2018-11-21 20:34:28.8363||DEBUG|8.11.15.0||Microsoft.AspNetCore.Authentication.Cookies.CookieAuthenticationHandler||GET|AuthenticationScheme: Identity.Application was successfully authenticated.|
2018-11-21 20:34:28.8363|5294|TRACE|8.11.15.0||Microsoft.AspNetCore.StaticFiles.StaticFileMiddleware||GET|Range header's value is empty.|
2018-11-21 20:34:28.8363|5294|INFO |8.11.15.0||Microsoft.AspNetCore.StaticFiles.StaticFileMiddleware||GET|Sending file. Request path: '/images/check.jpg'. Physical path: 'C:\Data\stage\devserver\httpdocs\wwwroot\images\check.jpg'|
2018-11-21 20:34:28.8363|5294|DEBUG|8.11.15.0||Microsoft.AspNetCore.Server.Kestrel||GET|Connection id "0HLIFT0Q49UES" completed keep alive response.|
2018-11-21 20:34:28.8363|5294|INFO |8.11.15.0||Microsoft.AspNetCore.Hosting.Internal.WebHost||GET|Request finished in 1.1804ms 200 image/jpeg|
2018-11-21 20:34:28.8363||INFO |8.11.15.0||Microsoft.AspNetCore.Hosting.Internal.WebHost||GET|Request starting HTTP/1.1 GET http://{mydomain}/css/images/ajax-loader.gif  |
2018-11-21 20:34:28.8363||TRACE|8.11.15.0||Microsoft.AspNetCore.HostFiltering.HostFilteringMiddleware||GET|All hosts are allowed.|
2018-11-21 20:34:28.8363||TRACE|8.11.15.0||Microsoft.AspNetCore.DataProtection.KeyManagement.KeyRingBasedDataProtector||GET|Performing unprotect operation to key {cafa52a6-433a-4452-9a55-dfa495b6ff78} with purposes ('C:\Data\stage\devserver\httpdocs', 'Microsoft.AspNetCore.Authentication.Cookies.CookieAuthenticationMiddleware', 'Identity.Application', 'v2').|
2018-11-21 20:34:28.8363||DEBUG|8.11.15.0||Microsoft.AspNetCore.Authentication.Cookies.CookieAuthenticationHandler||GET|AuthenticationScheme: Identity.Application was successfully authenticated.|
2018-11-21 20:34:28.8363|5294|TRACE|8.11.15.0||Microsoft.AspNetCore.StaticFiles.StaticFileMiddleware||GET|Range header's value is empty.|
2018-11-21 20:34:28.8363|5294|INFO |8.11.15.0||Microsoft.AspNetCore.StaticFiles.StaticFileMiddleware||GET|Sending file. Request path: '/css/images/ajax-loader.gif'. Physical path: 'C:\Data\stage\devserver\httpdocs\wwwroot\css\images\ajax-loader.gif'|
2018-11-21 20:34:28.8363|5294|DEBUG|8.11.15.0||Microsoft.AspNetCore.Server.Kestrel||GET|Connection id "0HLIFT0Q49UEQ" completed keep alive response.|
2018-11-21 20:34:28.8363|5294|INFO |8.11.15.0||Microsoft.AspNetCore.Hosting.Internal.WebHost||GET|Request finished in 1.235ms 200 image/gif|
2018-11-21 20:34:28.8857||TRACE|8.11.15.0||DTOWEB.Infrastructure.EmailHandler|||Sent mail to pieter@datec.nl about [site] status: John English heeft de AQ afgerond.|
2018-11-21 20:34:28.9000||TRACE|8.11.15.0||DTOWEB.Infrastructure.EmailHandler|||Succesful using smtp.datec.nl:465:=> Sending to pieter@datec.nl about [site] status: John English heeft de AQ afgerond.'|
2018-11-21 20:34:29.2105||INFO |8.11.15.0||Microsoft.AspNetCore.Hosting.Internal.WebHost||GET|Request starting HTTP/1.1 GET http://{mydomain}/js/jScript.js?v=LZlAlNMsltB7XcAcQlNK6xKDzXY2881oMxskOJLOslE  |
2018-11-21 20:34:29.2105||TRACE|8.11.15.0||Microsoft.AspNetCore.HostFiltering.HostFilteringMiddleware||GET|All hosts are allowed.|
2018-11-21 20:34:29.2105||TRACE|8.11.15.0||Microsoft.AspNetCore.DataProtection.KeyManagement.KeyRingBasedDataProtector||GET|Performing unprotect operation to key {cafa52a6-433a-4452-9a55-dfa495b6ff78} with purposes ('C:\Data\stage\devserver\httpdocs', 'Microsoft.AspNetCore.Authentication.Cookies.CookieAuthenticationMiddleware', 'Identity.Application', 'v2').|
2018-11-21 20:34:29.2105||DEBUG|8.11.15.0||Microsoft.AspNetCore.Authentication.Cookies.CookieAuthenticationHandler||GET|AuthenticationScheme: Identity.Application was successfully authenticated.|
2018-11-21 20:34:29.2105|5294|TRACE|8.11.15.0||Microsoft.AspNetCore.StaticFiles.StaticFileMiddleware||GET|Range header's value is empty.|
2018-11-21 20:34:29.2105|5294|INFO |8.11.15.0||Microsoft.AspNetCore.StaticFiles.StaticFileMiddleware||GET|Sending file. Request path: '/js/jScript.js'. Physical path: 'C:\Data\stage\devserver\httpdocs\wwwroot\js\jScript.js'|
2018-11-21 20:34:29.2105|5294|DEBUG|8.11.15.0||Microsoft.AspNetCore.Server.Kestrel||GET|Connection id "0HLIFT0Q49UES" completed keep alive response.|
2018-11-21 20:34:29.2105|5294|INFO |8.11.15.0||Microsoft.AspNetCore.Hosting.Internal.WebHost||GET|Request finished in 1.1904ms 200 application/javascript|
2018-11-21 20:34:29.3242||INFO |8.11.15.0||Microsoft.AspNetCore.Hosting.Internal.WebHost|||Request starting HTTP/1.1  http://{mydomain}/css/images/btn-info.png  |

@Tratcher
Copy link
Member

If you look at the Kestrel logs they tell you there are at least two different connections in use. You need to correlate which requests happened on the same connection as the final broken request.

@Tratcher
Copy link
Member

Though I guess in your example the last requests on both connections for static files. That implies that if there's an async issue then it's in a middleware before static files, or in a logging component. Do you reference HttpContext from any logging code?

@vankampenp
Copy link
Author

Thanks!
It turned out that sending the completion message is on the same connection. I am using MailKit to send the message. I don't want to let the user wait for that (this particular user does not need to be informed about the success).
I am using this code to send the email

 public static  void SendMail(AppSettings appSettings, string fromAddress, string displayName,
            string emailAddress,
            string htmlBody, string subject) 
        {
            Task.Run(() => SendMailAsync(appSettings, fromAddress, displayName, emailAddress, htmlBody, subject));
        }

I have now changed this for testing to


 public static void  SendMail(AppSettings appSettings, string fromAddress, string displayName,
            string emailAddress,
            string htmlBody, string subject) 
        {
          var t=  Task.Run(() => SendMailAsync(appSettings, fromAddress, displayName, emailAddress, htmlBody, subject));
            t.Wait();
        }

And this does not have the problem. So it seems the SendMailAsync method is causing the problem.

@Tratcher
Copy link
Member

Does SendMailAsync touch HttpContext?

@vankampenp
Copy link
Author

SendMailAsync just creates the body and sends the mail through MailKit, it does not touch HttpContext (at least not in my code).
Below is the log from our staging server with what I believe to be the connection id's. You can seen the two lines coming from the SendMailAsync just before the failed request, this time the whole page request for http://{mydomain}/klaar failed.

I now found that an other issue (in another part of the site) we are having is the same, it is a 404 on a Ajax call, caused by missing the HTTP Method on the request. This is also just after sending an other email on a background thread. After awaiting that call, that problem also goes away.

2018-11-22 10:50:10.5121|TraceId=0HLIGBV4ISVIS:0000000C|5311|DEBUG|8.11.15.0||Microsoft.EntityFrameworkCore.Database.Command|Base|GET|A data reader was disposed.|
2018-11-22 10:50:10.5121|TraceId=0HLIGBV4ISVIS:0000000C|5311|DEBUG|8.11.15.0||Microsoft.EntityFrameworkCore.Database.Connection|Base|GET|Closing connection to database |
2018-11-22 10:50:10.5121|TraceId=0HLIGBV4ISVIS:0000000C|5311|DEBUG|8.11.15.0||Microsoft.EntityFrameworkCore.Database.Connection|Base|GET|Closed connection to database|
2018-11-22 10:50:10.5121|TraceId=0HLIGBV4ISVIS:0000000C|5311|DEBUG|8.11.15.0||Microsoft.EntityFrameworkCore.ChangeTracking|Base|GET|Context 'DtoUser' started tracking 'DTOIdentityDBContext' entity. Consider using 'DbContextOptionsBuilder.EnableSensitiveDataLogging' to see key values.|
2018-11-22 10:50:10.5121|TraceId=0HLIGBV4ISVIS:0000000C|5311|TRACE|8.11.15.0||DTOWEB.Infrastructure.EmailHandler|Base|GET|FinishMail FinishEmailTL_nl.htm|
2018-11-22 10:50:10.5121|TraceId=0HLIGBV4ISVIS:0000000C|5311|TRACE|8.11.15.0||DTOWEB.Infrastructure.EmailHandler|Base|GET|Finishemail getting examiner|
2018-11-22 10:50:10.5121|TraceId=0HLIGBV4ISVIS:0000000C|5311|INFO |8.11.15.0||Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker|Base|GET|Executed action method DTOWEB.Controllers.BaseController.SwitchBoard (DTOWEB), returned result Microsoft.AspNetCore.Mvc.LocalRedirectResult in 30.3491ms.|
2018-11-22 10:50:10.5121|TraceId=0HLIGBV4ISVIS:0000000C|5311|TRACE|8.11.15.0||Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker|Base|GET|Action Filter: Before executing OnActionExecuted on filter Microsoft.AspNetCore.Mvc.ModelBinding.UnsupportedContentTypeFilter.|
2018-11-22 10:50:10.5121|TraceId=0HLIGBV4ISVIS:0000000C|5311|TRACE|8.11.15.0||Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker|Base|GET|Action Filter: After executing OnActionExecuted on filter Microsoft.AspNetCore.Mvc.ModelBinding.UnsupportedContentTypeFilter.|
2018-11-22 10:50:10.5121|TraceId=0HLIGBV4ISVIS:0000000C|5311|TRACE|8.11.15.0||Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker|Base|GET|Action Filter: After executing OnActionExecutionAsync on filter Microsoft.AspNetCore.Mvc.Internal.ControllerActionFilter.|
2018-11-22 10:50:10.5121|TraceId=0HLIGBV4ISVIS:0000000C|5311|TRACE|8.11.15.0||Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker|Base|GET|Result Filter: Before executing OnResultExecuting on filter Microsoft.AspNetCore.Mvc.ViewFeatures.Internal.SaveTempDataFilter.|
2018-11-22 10:50:10.5121|TraceId=0HLIGBV4ISVIS:0000000C|5311|TRACE|8.11.15.0||Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker|Base|GET|Result Filter: After executing OnResultExecuting on filter Microsoft.AspNetCore.Mvc.ViewFeatures.Internal.SaveTempDataFilter.|
2018-11-22 10:50:10.5121|TraceId=0HLIGBV4ISVIS:0000000C|5311|TRACE|8.11.15.0||Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker|Base|GET|Before executing action result Microsoft.AspNetCore.Mvc.LocalRedirectResult.|
2018-11-22 10:50:10.5121|TraceId=0HLIGBV4ISVIS:0000000C|5311|INFO |8.11.15.0||Microsoft.AspNetCore.Mvc.Infrastructure.LocalRedirectResultExecutor|Base|GET|Executing LocalRedirectResult, redirecting to /klaar.|
2018-11-22 10:50:10.5121|TraceId=0HLIGBV4ISVIS:0000000C|5311|TRACE|8.11.15.0||Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker|Base|GET|After executing action result Microsoft.AspNetCore.Mvc.LocalRedirectResult.|
2018-11-22 10:50:10.5121|TraceId=0HLIGBV4ISVIS:0000000C|5311|TRACE|8.11.15.0||Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker|Base|GET|Result Filter: Before executing OnResultExecuted on filter Microsoft.AspNetCore.Mvc.ViewFeatures.Internal.SaveTempDataFilter.|
2018-11-22 10:50:10.5121|TraceId=0HLIGBV4ISVIS:0000000C|5311|TRACE|8.11.15.0||Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker|Base|GET|Result Filter: After executing OnResultExecuted on filter Microsoft.AspNetCore.Mvc.ViewFeatures.Internal.SaveTempDataFilter.|
2018-11-22 10:50:10.5121|TraceId=0HLIGBV4ISVIS:0000000C|5311|TRACE|8.11.15.0||Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker|Base|GET|Resource Filter: Before executing OnResourceExecuted on filter Microsoft.AspNetCore.Mvc.ViewFeatures.Internal.SaveTempDataFilter.|
2018-11-22 10:50:10.5121|TraceId=0HLIGBV4ISVIS:0000000C|5311|TRACE|8.11.15.0||Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker|Base|GET|Resource Filter: After executing OnResourceExecuted on filter Microsoft.AspNetCore.Mvc.ViewFeatures.Internal.SaveTempDataFilter.|
2018-11-22 10:50:10.5121|TraceId=0HLIGBV4ISVIS:0000000C|5311|INFO |8.11.15.0||Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker|Base|GET|Executed action DTOWEB.Controllers.BaseController.SwitchBoard (DTOWEB) in 31.0325ms|
2018-11-22 10:50:10.5121|TraceId=0HLIGBV4ISVIS:0000000C|5311|DEBUG|8.11.15.0||Microsoft.AspNetCore.Server.Kestrel|Base|GET|Connection id "0HLIGBV4ISVIS" completed keep alive response.|
2018-11-22 10:50:10.5121|TraceId=0HLIGBV4ISVIS:0000000C|5311|DEBUG|8.11.15.0||Microsoft.EntityFrameworkCore.Infrastructure|Base|GET|'DTOIdentityDBContext' disposed.|
2018-11-22 10:50:10.5121|TraceId=0HLIGBV4ISVIS:0000000C|5311|INFO |8.11.15.0||Microsoft.AspNetCore.Hosting.Internal.WebHost|Base|GET|Request finished in 39.0209ms 302 |
2018-11-22 10:50:10.5215|TraceId=0HLIGBV4ISVIS:0000000D||TRACE|8.11.15.0||DTOWEB.Infrastructure.EmailHandler|||SendMailAsync: smtp.mail.nl:465 |
2018-11-22 10:50:10.5215|TraceId=0HLIGBV4ISVIS:0000000D||DEBUG|8.11.15.0||DTOWEB.Infrastructure.DsnSmtpClient|||DsnSmtpClient|
2018-11-22 10:50:10.5215|TraceId=0HLIGBV4ISVIS:0000000D||INFO |8.11.15.0||Microsoft.AspNetCore.Hosting.Internal.WebHost|||Request starting HTTP/1.1  http://{mydomain}/klaar  |
2018-11-22 10:50:10.5215|TraceId=0HLIGBV4ISVIS:0000000D||TRACE|8.11.15.0||Microsoft.AspNetCore.HostFiltering.HostFilteringMiddleware|||All hosts are allowed.|
2018-11-22 10:50:10.5215|TraceId=0HLIGBV4ISVIS:0000000D||TRACE|8.11.15.0||Microsoft.AspNetCore.DataProtection.KeyManagement.KeyRingBasedDataProtector|||Performing unprotect operation to key {cafa52a6-433a-4452-9a55-dfa495b6ff78} with purposes ('C:\Data\stage\devserver\httpdocs', 'Microsoft.AspNetCore.Authentication.Cookies.CookieAuthenticationMiddleware', 'Identity.Application', 'v2').|
2018-11-22 10:50:10.5215|TraceId=0HLIGBV4ISVIS:0000000D||DEBUG|8.11.15.0||Microsoft.AspNetCore.Authentication.Cookies.CookieAuthenticationHandler|||AuthenticationScheme: Identity.Application was successfully authenticated.|
2018-11-22 10:50:10.5215|TraceId=0HLIGBV4ISVIS:0000000D|5311|DEBUG|8.11.15.0||Microsoft.AspNetCore.StaticFiles.StaticFileMiddleware||| requests are not supported|
2018-11-22 10:50:10.5215|TraceId=0HLIGBV4ISVIS:0000000D|5311|DEBUG|8.11.15.0||Microsoft.AspNetCore.Routing.Tree.TreeRouter|||Request successfully matched the route with name '(null)' and template 'klaar'.|
2018-11-22 10:50:10.5215|TraceId=0HLIGBV4ISVIS:0000000D|5311|DEBUG|8.11.15.0||Microsoft.AspNetCore.Mvc.Internal.ActionSelector|||Action 'DTOWEB.Controllers.BaseController.SwitchBoard (DTOWEB)' with id 'e4a2a066-73cb-4c84-94bb-f1fd791e6801' did not match the constraint 'Microsoft.AspNetCore.Mvc.Internal.HttpMethodActionConstraint'|
2018-11-22 10:50:10.5215|TraceId=0HLIGBV4ISVIS:0000000D|5311|DEBUG|8.11.15.0||Microsoft.AspNetCore.Mvc.Internal.MvcAttributeRouteHandler|||No actions matched the current request. Route values: |
2018-11-22 10:50:10.5215|TraceId=0HLIGBV4ISVIS:0000000D|5311|DEBUG|8.11.15.0||Microsoft.AspNetCore.Routing.RouteConstraintMatcher|||Route value 'klaar' with key 'area' did not match the constraint 'Microsoft.AspNetCore.Mvc.Routing.KnownRouteValueConstraint'.|
2018-11-22 10:50:10.5215|TraceId=0HLIGBV4ISVIS:0000000D|5311|DEBUG|8.11.15.0||Microsoft.AspNetCore.Routing.RouteBase|||Request successfully matched the route with name 'default' and template '{action}'.|
2018-11-22 10:50:10.5215|TraceId=0HLIGBV4ISVIS:0000000D|5311|DEBUG|8.11.15.0||Microsoft.AspNetCore.Mvc.Internal.ActionSelector|||No actions matched the current request. Route values: action=klaar, controller=Base|
2018-11-22 10:50:10.5215|TraceId=0HLIGBV4ISVIS:0000000D|5311|DEBUG|8.11.15.0||Microsoft.AspNetCore.Mvc.Internal.MvcRouteHandler|||No actions matched the current request. Route values: action=klaar, controller=Base|
2018-11-22 10:50:10.5215|TraceId=0HLIGBV4ISVIS:0000000D|5311|DEBUG|8.11.15.0||Microsoft.AspNetCore.Builder.RouterMiddleware|||Request did not match any routes.|
2018-11-22 10:50:10.5215|TraceId=0HLIGBV4ISVIS:0000000D|5311|DEBUG|8.11.15.0||Microsoft.AspNetCore.StaticFiles.StaticFileMiddleware||| requests are not supported|
2018-11-22 10:50:10.5215|TraceId=0HLIGBV4ISVIS:0000000D|5311|DEBUG|8.11.15.0||Microsoft.AspNetCore.Builder.RouterMiddleware|||Request did not match any routes.|
2018-11-22 10:50:10.5215|TraceId=0HLIGBV4ISVIS:0000000D|5311|DEBUG|8.11.15.0||Microsoft.AspNetCore.Server.Kestrel|||Connection id "0HLIGBV4ISVIS" completed keep alive response.|
2018-11-22 10:50:10.5215|TraceId=0HLIGBV4ISVIS:0000000D|5311|INFO |8.11.15.0||Microsoft.AspNetCore.Hosting.Internal.WebHost|||Request finished in 1.2773ms 404 |
2018-11-22 10:50:10.6289|TraceId=||TRACE|8.11.15.0||Microsoft.AspNetCore.Http.Connections.Internal.HttpConnectionManager|||Scanning connections.|
2018-11-22 10:50:10.6289|TraceId=||TRACE|8.11.15.0||Microsoft.AspNetCore.Http.Connections.Internal.HttpConnectionManager|||Scanned connections in 00:00:00.0000445.|
2018-11-22 10:50:10.6634|TraceId=0HLIGBV4ISVIS:0000000E||TRACE|8.11.15.0||DTOWEB.Infrastructure.EmailHandler|||Sent mail to pieter@mail.nl about [site] status: Jan Os heeft de CERQJ afgerond.|
2018-11-22 10:50:10.6826|TraceId=0HLIGBV4ISVIS:0000000E||TRACE|8.11.15.0||DTOWEB.Infrastructure.EmailHandler|||Succesful using smtp.mail.nl:465|
2018-11-22 10:50:11.6289|TraceId=||TRACE|8.11.15.0||Microsoft.AspNetCore.Http.Connections.Internal.HttpConnectionManager|||Scanning connections.|
2018-11-22 10:50:11.6289|TraceId=||TRACE|8.11.15.0||Microsoft.AspNetCore.Http.Connections.Internal.HttpConnectionManager|||Scanned connections in 00:00:00.0000595.|
2018-11-22 10:50:12.6289|TraceId=||TRACE|8.11.15.0||Microsoft.AspNetCore.Http.Connections.Internal.HttpConnectionManager|||Scanning connections.|
2018-11-22 10:50:12.6289|TraceId=||TRACE|8.11.15.0||Microsoft.AspNetCore.Http.Connections.Internal.HttpConnectionManager|||Scanned connections in 00:00:00.0000655.|
2018-11-22 10:50:13.6289|TraceId=||TRACE|8.11.15.0||Microsoft.AspNetCore.Http.Connections.Internal.HttpConnectionManager|||Scanning connections.|
2018-11-22 10:50:13.6289|TraceId=||TRACE|8.11.15.0||Microsoft.AspNetCore.Http.Connections.Internal.HttpConnectionManager|||Scanned connections in 00:00:00.0000632.|
2018-11-22 10:50:14.6289|TraceId=||TRACE|8.11.15.0||Microsoft.AspNetCore.Http.Connections.Internal.HttpConnectionManager|||Scanning connections.|

In the Switchboard method I am updating a SignalR hub, and I am also using HttpClientFactory. I am using HttpContext in that method as well.

@Tratcher
Copy link
Member

Then it's your logging code itself causing the problem. It is logging the request Method, so it's accessing the HttpContext to get that.

@vankampenp
Copy link
Author

Spot on sir! I removed the wait's on the SendMailAsync , and stopped the request Method logging. Than it works too. So my question is, what is causing this? Should I not have tried to remove the email delay from the UI, or is there something Nlog should look at to do differently?

@Tratcher
Copy link
Member

Background threads cannot safely access HttpContext. Since logging can sometimes happen on background threads it also cannot access HttpContext. If you really want to log something like the method then pass that value through as a paramter, don't try to read it from ambient thread context.

@vankampenp
Copy link
Author

Thanks you insight and help is greatly appreciated.

@ghost ghost locked as resolved and limited conversation to collaborators Dec 3, 2019
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@Tratcher @vankampenp