Aspnetcore: Kestrel returns 400 before reaching any of my code

[andre-ss6]

Our web app started returning seemingly random 400s since the last two weeks. It is a ASP.NET Core 2.0 mvc web site running under IIS and Windows Server 2016. First thing we did was, of course, look at our logs. However, there was nothing. None of those 400s were there. We then enabled Failed Request Tracing and found this: https://pastebin.com/NVR2pzbJ (as you may know, Failed Request Traces from IIS are quite gigantic, thus I'm using pastebin). Anyway, the TLDR is this:

<EventData>
  <Data Name="ContextId">{80002F02-0002-EE00-B63F-84710C7967BB}</Data>
  <Data Name="ModuleName">AspNetCoreModule</Data>
  <Data Name="Notification">128</Data>
  <Data Name="HttpStatus">400</Data>ç
  <Data Name="HttpReason">Bad Request</Data>
  <Data Name="HttpSubStatus">0</Data>
  <Data Name="ErrorCode">0</Data>
  <Data Name="ConfigExceptionInfo"></Data>
 </EventData>
 <RenderingInfo Culture="en-US">
  <Opcode>MODULE_SET_RESPONSE_ERROR_STATUS</Opcode>
  <Keywords>
   <Keyword>RequestNotifications</Keyword>
  </Keywords>
  <freb:Description Data="Notification">EXECUTE_REQUEST_HANDLER</freb:Description>
  <freb:Description Data="ErrorCode">The operation completed successfully.
 (0x0)</freb:Description>
 </RenderingInfo>
 <ExtendedTracingInfo xmlns="http://schemas.microsoft.com/win/2004/08/events/trace">
  <EventGuid>{002E91E3-E7AE-44AB-8E07-99230FFA6ADE}</EventGuid>
 </ExtendedTracingInfo>
</Event>
<Event xmlns="http://schemas.microsoft.com/win/2004/08/events/event">
 <System>
  <Provider Name="WWW Server" Guid="{3A2A4E84-4C21-4981-AE10-3FDA0D9B0F83}"/>
  <EventID>0</EventID>
  <Version>1</Version>
  <Level>4</Level>
  <Opcode>56</Opcode>
  <Keywords>0x0</Keywords>
  <TimeCreated SystemTime="2018-09-06T13:58:08.103Z"/>
  <Correlation ActivityID="{80002F02-0002-EE00-B63F-84710C7967BB}"/>
  <Execution ProcessID="3828" ThreadID="14428"/>
  <Computer>siip</Computer>
 </System>
 <EventData>
  <Data Name="ContextId">{80002F02-0002-EE00-B63F-84710C7967BB}</Data>
  <Data Name="HeaderName">Content-Length</Data>
  <Data Name="HeaderValue">0</Data>
  <Data Name="Replace">true</Data>
 </EventData>
 <RenderingInfo Culture="en-US">
  <Opcode>GENERAL_SET_RESPONSE_HEADER</Opcode>
 </RenderingInfo>
 <ExtendedTracingInfo xmlns="http://schemas.microsoft.com/win/2004/08/events/trace">
  <EventGuid>{D42CF7EF-DE92-473E-8B6C-621EA663113A}</EventGuid>
 </ExtendedTracingInfo>
</Event>
<Event xmlns="http://schemas.microsoft.com/win/2004/08/events/event">
 <System>
  <Provider Name="WWW Server" Guid="{3A2A4E84-4C21-4981-AE10-3FDA0D9B0F83}"/>
  <EventID>0</EventID>
  <Version>1</Version>
  <Level>4</Level>
  <Opcode>56</Opcode>
  <Keywords>0x0</Keywords>
  <TimeCreated SystemTime="2018-09-06T13:58:08.103Z"/>
  <Correlation ActivityID="{80002F02-0002-EE00-B63F-84710C7967BB}"/>
  <Execution ProcessID="3828" ThreadID="14428"/>
  <Computer>siip</Computer>
 </System>
 <EventData>
  <Data Name="ContextId">{80002F02-0002-EE00-B63F-84710C7967BB}</Data>
  <Data Name="HeaderName">Server</Data>
  <Data Name="HeaderValue">Kestrel</Data>
  <Data Name="Replace">true</Data>
 </EventData>
 <RenderingInfo Culture="en-US">
  <Opcode>GENERAL_SET_RESPONSE_HEADER</Opcode>
 </RenderingInfo>
 <ExtendedTracingInfo xmlns="http://schemas.microsoft.com/win/2004/08/events/trace">
  <EventGuid>{D42CF7EF-DE92-473E-8B6C-621EA663113A}</EventGuid>
 </ExtendedTracingInfo>
</Event>
<Event xmlns="http://schemas.microsoft.com/win/2004/08/events/event">
 <System>
  <Provider Name="WWW Server" Guid="{3A2A4E84-4C21-4981-AE10-3FDA0D9B0F83}"/>
  <EventID>0</EventID>
  <Version>1</Version>
  <Level>5</Level>
  <Opcode>3</Opcode>
  <Keywords>0x100</Keywords>
  <TimeCreated SystemTime="2018-09-06T13:58:08.103Z"/>
  <Correlation ActivityID="{80002F02-0002-EE00-B63F-84710C7967BB}"/>
  <Execution ProcessID="3828" ThreadID="14428"/>
  <Computer>siip</Computer>
 </System>
 <EventData>
  <Data Name="ContextId">{80002F02-0002-EE00-B63F-84710C7967BB}</Data>
  <Data Name="ModuleName">AspNetCoreModule</Data>
  <Data Name="Notification">128</Data>
  <Data Name="fIsPostNotificationEvent">false</Data>
  <Data Name="CompletionBytes">0</Data>
  <Data Name="ErrorCode">0</Data>
 </EventData>
 <RenderingInfo Culture="en-US">
  <Opcode>NOTIFY_MODULE_COMPLETION</Opcode>
  <Keywords>
   <Keyword>RequestNotifications</Keyword>
  </Keywords>
  <freb:Description Data="Notification">EXECUTE_REQUEST_HANDLER</freb:Description>
  <freb:Description Data="ErrorCode">The operation completed successfully.
 (0x0)</freb:Description>
 </RenderingInfo>
 <ExtendedTracingInfo xmlns="http://schemas.microsoft.com/win/2004/08/events/trace">
  <EventGuid>{002E91E3-E7AE-44AB-8E07-99230FFA6ADE}</EventGuid>
 </ExtendedTracingInfo>
</Event>

Now, I'm not an IIS expert by any means, but if I understand this correctly, Asp.Net Core has run and has decided to return 400 bad request. The problem is: _our code never ran_. This is our Startup.Configure():

public void Configure(IApplicationBuilder app, IHostingEnvironment env)
        {
            // This middleware, as you can see, is the first thing ever to run and it simply logs
           // everything that enters and leaves. Do note that other "normal" 400 errors are logged by this
            app.UseMiddleware<SerilogMiddleware>();

            if (env.IsDevelopment())
            {
                app.UseDeveloperExceptionPage();
                app.UseBrowserLink();
            }
            else
            {
                app.UseExceptionHandler("/Home/Error/500");
            }

            // other middleware ...

            // This turns 400s, 404s and 500s into some pretty pages.
            // And this middleware is also not being run when this problem occurs,
            // further evidencing that Kestrel is returning 400 _before_ any of my code runs.
            app.UseStatusCodePagesWithReExecute("/Home/Error/{0}");

            app.UseMvc(routes =>
            {
                routes
                .MapRoute(
                    name: "default",
                    template: "{controller=Home}/{action=Index}/{id?}");
            });
        }

We thought that maybe the request got corrupted and somehow it was so invalid that kestrel didn't even bother to send it to the rest of the pipeline. However, we've repated the same request on fiddler and they return success codes. This is the request if you don't want to navigate through those 4k lines of log:

Cache-Control: max-age=0
Connection: keep-alive
Content-Length: 2410
Content-Type: application/x-www-form-urlencoded
Accept: text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,image/apng,*/*;q=0.8
Accept-Encoding: gzip, deflate
Accept-Language: pt-BR,pt;q=0.9,en-US;q=0.8,en;q=0.7
Cookie: .AspNetCore.Antiforgery.yRvNsY19ltY=CfDJ8DgfkYSRB59EqqhuWGHNsd9RwNppJLY8SuEzNMhyyszJv8tPzAJPfuZ4uwMX8RPtO28x3qVO1FtSXHGrb4pjZLkETcbVr4zDiH4VEuoFYbNqBe6hUKHZrN4Vg_5LIGCfY6vVLtnX1Dl7QCy3arKjRVY; .AspNetCore.Cookies=CfDJ8DgfkYSRB59EqqhuWGHNsd_qCE-_zqZcbhiSe47BlGFvLNyIFQ2CyUTMFARZScdH8o0E-LhqGzGgbMPnn5G9-T0KpL7sV0K4uQ1yYA59vo25d42-rtr8WMz2jgEVlYCwiUoZwy0AHBhJstwdilM3_D3FxkJTzebye8BHOrjobdeOqTWk4D774_V4M-O2-pltX3On_U0vKheQGc2-YrGwP4RFlR0x9XSrszgtKyRv_mJE67g9ueRD1aRRp9-BGoymJujrxjDnuPD7ZIN1RWlstiV5RyQpsjnurMISgNsl6ET5wRH0-Bu2p-RNnjAiFHAlCjom4RKb7pKDXMipaQoEGkwesn4T02kV5R4NhwrUOzbyUFZ1aWltOFuDp6Ce3pMAnPNtx2SsUN0ru7T3Yjc1pUIEZW3_quxcHQnrb601NGRHZpmoIqVOJSIFOhuX-rgYhGWfBUHtqckv2Cb-WiS1sIrR0Za7E692mQkVvbN5uT1n1fFbhNLRmixT0empfGtI8ZrKbHDjmVhdOuTvgNRZ3Z0uQx05pjmtITHenYkqCtPja0j-sCqEIhMsfXc2XFj4dNNvTMWEBGHXzTpvqD2CUgpBt2fHxC2fm8tRXZPWgojqVrM4JRMS03sl5nf92RIbtubVc8gsRNYIZPftLdl193PmosGSAYhpiU6XyRwh7d4KILEgsXJPZXiwY5UTmBCqW84aHRv9X9ZZ1P-e9jvBHm_31gR8IbiFeiZqGTRF8_cPDYuBd43fuA0z_L1G8LpcNaQrbDm-CrVuaWLpr8aQy-VzrQJMiCJWUxo9sQRZGCaK_Jl_ukRKn-YHelY9nNAAcWitiPLdqQYal194oLYPYo4t7K9ftGQuib4NJa7I8TwXeKK1Qy6TVupTQgUNIjO_yvRiZyrnvq5oaOP9V9SYT4_nppOhryaqVQ-jJRY4XKxqnP5shwDbPtOVFg-67ozWebX_a7EHSzULIvSoBUsR7utlhZCmmBJGgBZZhJfr2-6GWwcdcJ23Sz0x5JyW-O4Liw4ErXnbEdSvZTomjS2pjqleG_TsBJS6xCEIStSRRiyxZduG9ihmQB1fCGC8DhTmckU0-M_quPsHGjBahr7f1MNx6yXxF5ms4CHSvG-i7Lhh-WDDRLg21dBvtFrvT65bYsoRPHsukfi-6dT3oS49KdriqCNKTa5o4nWX98563be0znJTj8T_1eXOrYcjRfYThZnkB8OpJjz1Eihaj7bgQ-N6zuK3NWJSU3j4EA2s15qgrnVzCEXcd37HpQxRzTtCJ0eS-EY062xf3RW441WRY1-bhqjsAgajW6JCgkh7Ukb4W-_accuiUjW0U2jSepyUysdTva64JwF8hKF7ap1StomK1U7Dxg10hLJ3vMfqW1G5Tbo-ahQCVhBxhgKjsCFUFALdQUlWgnfsXMyr-6wbT273lQ7xsYW2HzhkSLYyWbkZLXEP5QJjm4hgb8EEEJYrLLkwqAyu5uO7CLqbLbKlytAH5rAcvnWq6J2yZfC_diNoRW35gaw96RV51OTI2CQTOPzYzqZTfUYmkhuNeGkNIZqgPOKJivZu5aSNMBBrzqXPcDAPmHEOKTlNODtiN1f3sE1XzPUz2CWRf-GMTO6NwdrRYgx2Y6aTf_XCElC5z6Rk1dK04yhR9xBKq_l35YjyuZNPg9ArO46jhfBM1WbaB_tmBPob9dSEuW5kXNnfBZ-CbWJZEioequiVC-_Z2PGtbOeRkFtCfPgk07t9kVskNjYHtFRSmEB7kmC-DYDFz29SXicjsgTko05tmviT_XxTDaAtdQfoYap5QF8BTgSW9L2uvDPB3XS5QUhiKSbXtU-UUoQp4uJ_zGwg3H-2bsTiieG2ZfGZ7uRKGQ1we-WWp1Jb-4ADv28ZQrQuYaNfRtelIxixDmUWoOoygIvGV_K-Ini27CPeZ8ys5oG3LiW-sQND_eVIluCGwY3RkorPhgmggAKOsHIvqRyzD3Y0PtdUkqN2J5cODm4sADZl9J_0uFhe4q-dnCyeqQhDbKfIr3nCiHehKfsBKKa_49aOF0ZhH9z5quZvymtWo3mAJp3VUNTdJcAqYnvWWydS3gLhlGz2AJxkpnzVd0XDaTy4y3yDoS_h15efbjZjI6hrByCAg48phLByXJ0aJYKeh-7Qf-lsvVpixkQKOWie5weN8LWKbE5z8HdKVW0gL_2me7fh1k8PdI3wyX6dvG1K6Ez0GN2nWl0wNUQknyj9xCAr2IOzmNXXJkDHzLBxtvIJvUqRQTN5MRwmz-Mp-CUjdiexokVSa8s87Dts-YLkY9d9dy2SWSPuhfowr9XnBjuRBkv62kQMAFQzvxMiz0vdj-cLRTclH8xWYg4damLkJ_ugUXMUPEixKPMurLOlYL9GxlFaiIjvytj9g2Y53C2LrQWtrJakNuweHXSQsSSUiUl99mDBQzYC2Wg3QmGILCz7_bT4XH_FLYcMQt7QVTASmS_4ikFjIVe4QhWOMWXUFnY9TCYmUkqSYXPtDyd23rbnRU8xZosTH7FLWXH0PnbIs2AsfTmPq52WtIR2tLn1hcgsOR7YqXn_MWE7HLLh_FQdt-x6jSNKpxkFMeR3ZsQXHQzoRqdeb3S17Fe7XD58HhpSPBXcyDgqZK3uu84CLsR-CjY9h3xnKSTSepU9Nqa_KdGIa8Q9bpKAVpu2arnlW6Fxdh7_j9_cPpFS6Jk6mGMH0xh5JE_ZxhICXMlWYCIblD_YBV3HTE7FDGj1gbg-TT6inBnq8PbDXXEOfPa3K1OuqdDgHXvFLwqq0y1PXg3r0c2eYcMIUdS0DBjiIsu6sLqNwPJvdwI-B_aucHCha6ZHNUrSEbLJVqw3HWlZ-CgSSLa_G8JYjzp2k4Lw2HaZd2cYP2H25ZIfDac-mBtgutJN9pIzxvF-qrPatjXjRA8LyPj2H92cy2mKu7WXpvrvvs7JppiSNPVKJFzvR0RmMbvvONUnyQlnrXizwPgwKSOEFLzyl9kvsafzTXVdhUhb3Mo3WYFEng; .AspNetCore.Session=CfDJ8DgfkYSRB59EqqhuWGHNsd8Rf5SAzNzUXxufiopkJheFoufaoaYs2XFLN%2FpaOO9pUyxt3J9noimn8wgCl3vxbuAPNJ0tsqR%2FBiEn0YU2SOFLrPVhGgZ6kd0rn3tmhPHyrZTSVGP%2Ftvow8CPdWg8USxbMhwtKrcwaKq56tmhqcjUm
Host: [redacted-url]
Referer: http://[redacted-url]/Inspecao/Cadastrar
User-Agent: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/68.0.3440.106 Safari/537.36
Origin: http://[redacted-url]
Upgrade-Insecure-Requests: 1

DataAlteracao=&DataInclusao=&Municipio=São+Vicente&Data=13/08/2018&Hora=09:31&

There were other parameters in the body, but I've removed them for brevity. You can find all of them on the provided log. Also, note that in the log, the body was url-encoded. We tested both replaying them url-encoded and decoded, both result in _our code being run_, which is what is really important here.

Edit Some more info: We have this same application deployed to two different physical servers. Only one of them is having these issues, however. These are the differences I managed to gather between the two (italic being the one presenting these issues):

_Windows Server 2016_ vs Windows Server 2008
_Azure VM_ vs Physical Server
_Multiple (20+) IIS Websites, all runing ASP.NET Core 2 and 3 running WebForms under .NET 4.5_ vs 2 IIS Websites running ASP.NET Core 2
_16 GB RAM_ vs 8GB

[JunTaoLuo]

Since I've recently worked on aspnet/KestrelHttpServer#1144, I am suspicous of the [redacted-url] in your Referer header. My hunch is that it may have non-standard-ASCII characters, judging from the fact that you have content such as Municipio=São+Vicente. If that is the case, they I would suggest trying the same request on 2.2.0-preview2 which is where we started to accept UTF-8 encoded header values.

If it is not the case, can you provide us logs with ConnectionLogging turned on so we may examine what Kestrel received? That would help us narrow down which component set the 400 bad request error.

[andre-ss6]

Yea, I had seen that issue. However, unfortunately, no, there are no non-standard characters in none of the urls.

And what exactly is ConnectionLogging? How do I turn it on?

[JunTaoLuo]

I see, then we'll need to investigate further. You can turn on connection logging like so:
c# WebHost.CreateDefaultBuilder(args) .UseKestrel(options => { options.ConfigureEndpointDefaults(listenOptions => { listenOptions.UseConnectionLogging(); }); }) .UseStartup<Startup>();

Or if you are configuring endpoints directly: https://github.com/aspnet/KestrelHttpServer/blob/6fde01a825cffc09998d3f8a49464f7fbe40f9c4/samples/SampleApp/Startup.cs#L82-L88

[andre-ss6]

Ok thanks. I see, however, that's available only on Asp.Net Core 2.1, and our project is 2.0 currently. We'll update it here and then enable connection logging. I'll post back when I have any updates.

[andre-ss6]

We've just updated our app to 2.1 and enabled Connection Logging in two of our websites. If we see anything I'll post here.

However, there's something _else_ I wanted to share. While looking at the failed request traces, I noticed this one: https://pastebin.com/XEZQkd10

TDLR:

Situation #2

<Event xmlns="http://schemas.microsoft.com/win/2004/08/events/event">
 <System>
  <Provider Name="WWW Server" Guid="{3A2A4E84-4C21-4981-AE10-3FDA0D9B0F83}"/>
  <EventID>0</EventID>
  <Version>1</Version>
  <Level>3</Level>
  <Opcode>16</Opcode>
  <Keywords>0x100</Keywords>
  <TimeCreated SystemTime="2018-09-12T14:38:43.399Z"/>
  <Correlation ActivityID="{800000C0-0000-EB00-B63F-84710C7967BB}"/>
  <Execution ProcessID="9504" ThreadID="11988"/>
  <Computer>siip</Computer>
 </System>
 <EventData>
  <Data Name="ContextId">{800000C0-0000-EB00-B63F-84710C7967BB}</Data>
  <Data Name="ModuleName">AspNetCoreModule</Data>
  <Data Name="Notification">128</Data>
  <Data Name="HttpStatus">400</Data>
  <Data Name="HttpReason">Bad Request</Data>
  <Data Name="HttpSubStatus">0</Data>
  <Data Name="ErrorCode">2147952454</Data>
  <Data Name="ConfigExceptionInfo"></Data>
 </EventData>
 <RenderingInfo Culture="en-US">
  <Opcode>MODULE_SET_RESPONSE_ERROR_STATUS</Opcode>
  <Keywords>
   <Keyword>RequestNotifications</Keyword>
  </Keywords>
  <freb:Description Data="Notification">EXECUTE_REQUEST_HANDLER</freb:Description>
  <freb:Description Data="ErrorCode">An existing connection was forcibly closed by the remote host.
 (0x80072746)</freb:Description>
 </RenderingInfo>
 <ExtendedTracingInfo xmlns="http://schemas.microsoft.com/win/2004/08/events/trace">
  <EventGuid>{002E91E3-E7AE-44AB-8E07-99230FFA6ADE}</EventGuid>
 </ExtendedTracingInfo>
</Event>

---

Now, of course this one returned 400 because, as the log says, the connection was closed by the client, as opposed to the first log I showed on the OP, which has no error message whatsoever -- like this:

Situation #1 (as in OP)

<Event xmlns="http://schemas.microsoft.com/win/2004/08/events/event">
 <System>
  <Provider Name="WWW Server" Guid="{3A2A4E84-4C21-4981-AE10-3FDA0D9B0F83}"/>
  <EventID>0</EventID>
  <Version>1</Version>
  <Level>3</Level>
  <Opcode>16</Opcode>
  <Keywords>0x100</Keywords>
  <TimeCreated SystemTime="2018-09-12T14:09:37.264Z"/>
  <Correlation ActivityID="{80000056-0003-F500-B63F-84710C7967BB}"/>
  <Execution ProcessID="9504" ThreadID="4612"/>
  <Computer>siip</Computer>
 </System>
 <EventData>
  <Data Name="ContextId">{80000056-0003-F500-B63F-84710C7967BB}</Data>
  <Data Name="ModuleName">AspNetCoreModule</Data>
  <Data Name="Notification">128</Data>
  <Data Name="HttpStatus">400</Data>
  <Data Name="HttpReason">Bad Request</Data>
  <Data Name="HttpSubStatus">0</Data>
  <Data Name="ErrorCode">0</Data>
  <Data Name="ConfigExceptionInfo"></Data>
 </EventData>
 <RenderingInfo Culture="en-US">
  <Opcode>MODULE_SET_RESPONSE_ERROR_STATUS</Opcode>
  <Keywords>
   <Keyword>RequestNotifications</Keyword>
  </Keywords>
  <freb:Description Data="Notification">EXECUTE_REQUEST_HANDLER</freb:Description>
  <freb:Description Data="ErrorCode">The operation completed successfully.
 (0x0)</freb:Description>
 </RenderingInfo>
 <ExtendedTracingInfo xmlns="http://schemas.microsoft.com/win/2004/08/events/trace">
  <EventGuid>{002E91E3-E7AE-44AB-8E07-99230FFA6ADE}</EventGuid>
 </ExtendedTracingInfo>
</Event>

So, while Situation #1 has some clear issue with it, since, as I understand, if the handler completed succesfully, it _had to_ have invoked my code (the middleware pipeline)... still, I do think that in both of these situations my code _should_ have run. I understand that in Situation #2 some network problem happened, however I don't see why is that an excuse to not run the full pipeline. After all, the request had already reached Asp.Net Core and I want my logs to run whenever a request reaches Asp.Net Core.

EDIT

Oh, btw, I forgot to mention: in this last log I shared (the 400 because of connection drop), nothing was on our logs again (because, of course, as I said, our code didn't run). So I'm guessing that enabling Connection Logging won't do much good because our logs probably won't run. Stdout logging is enabled this time though, so maybe that helps somehow.

EDIT 2

I find it interesting that these traces report the timeTaken for the request as 0, especially the most weird ones (like the one I originally reported, in which the ASP.NET Core Module says there were no errors albeit having returned 400 and not running our code).

EDIT 3

Well, things just got weirder. We've just seen a lot of requests that have been logged by ASP.NET logging as having returned 302 or 200, however IIS logged them as having returned 400. Unfortunately ConnectionLogging wasn't enabled by the time those requests were logged, so I have nothing for now. I've checked time taken (maybe the requests were reaching timeout just at the last milisec?) but I've confirmed that is not the issue, since it happened with requests ranging from milliseconds of time taken to more than 10 seconds.

[muratg]

@andre-ss6 Any new findings here?

[andre-ss6]

I'm sorry for being away all this time. No, unfortunately we couldn't manage to find anything else. The 400s wouldn't appear in our logs even when Connection Logging was enabled. Those requests really seemed to be responded either in ANCM or in Kestrel, before reaching the actual application code.

About the requests I mentioned in the last edit, which return 400 but are logged as normal responses in our logs: they seem to represent another problem. We think they happen when you make a double submit with some time in between them (like .5s). Then, what happens is that, according to the logs, ASP.NET returns a normal response to both (like 200 or 304 -- and yes, we managed to get these ones logged with Connection Logging enabled) but IIS/Kestrel/ANCM (?) returns 400. However, those are different from the problem I originally reported, because those are logged by our code. Also, those have a real timeTaken, while in the original problem timeTaken is 0. Unfortunately we haven't had time to try to replicate this double submit issue in a sample application though.

In the end, what we noticed is that as we updated our apps to ASP.NET Core 2.1, the problem started to disappear.

I will keep an eye on it though. If I manage to find anything else, I'll post here. If you want to close the issue, though, I'm fine with it.

Edit: even though we couldn't find the root cause of this problem, I still stand by what I said in my last reply: I think that, independently of anything, if a request reaches IIS, application code should _always_ run. Or at least there should be a way to hook into Kestrel in order to log absolutely _all_ requests.

Edit 2: Ok, I just now understood that those logs actually already _are_ Kestrel logs, right? If that's the case, then I guess we have two options left: ANCM is returning 400 before Kestrel (is this possible? I asked this elsewhere but got no answer) or Kestrel is returning before logging anything (which seems unlikely -- although that's exactly what's happening here, funnily enough 😛 ). In any case, it's hard to know for sure because, as I said, the problem seemed to have disappeared after we upgraded to 2.1. Well, thinking about it, we actually made another change during this process: we switched to SCD (instead of FDD). Maybe that was what helped? 🤔

[andre-ss6]

Ok those were a lot of edits. Maybe I should have posted another reply instead haha. I'm justing posting this one to make sure that you see my latest edits in the case that you had already seen the reply without the edits.

[Tratcher]

ConnectionLogging is the lowest possible level of logging in Kestrel and it tracks every byte of data sent and received. It's not possible for Kestrel to send a 400 without it showing up there.

ANCM does not generate 400 responses, but IIS/Http.Sys can. It will do this for things like disallowed characters in the URL. I think the only log that captures those is ETW.

[andre-ss6]

I guess it was not IIS because, as reported in the OP, the failed request Trace reports ANCM as having run successfully.

[mastrauckas]

I appeared to have the same issue. So having code that looks like this

public class ClientHelper
{
     public HttpClient Client { get; }
     public ExternalApiHelper( HttpClient client)
     {
          Client = client;
     }

     public async Task<HttpResponseMessage> SendAsync(HttpMethod method, string url, object requestObject = null)
     {
          var requestString = JsonConvert.SerializeObject(requestObject);
          HttpRequestMessage request = new HttpRequestMessage()
            {
                Method = method,
                RequestUri = new Uri(url),
                Content =  new StringContent(requestObject, Encoding.UTF8, "application/json")
            };

            var response = await Client.SendAsync(request);
            if (response.StatusCode != HttpStatusCode.OK)
          {
               throw new Exception("HTTP Response was not OK")
          }
          var responseContent = await response.Content.ReadAsStringAsync();
          return JsonConvert.DeserializeObject<T>(responseContent);
     }
}

Now if I call this method like this:

client.SendAsync(HttpMethod.Get, url);
client.SendAsync(HttpMethod.Get, url, "");
client.SendAsync(HttpMethod.Get, url); 

Ater the first client.SendAsync(HttpMethod.Get, url);, a line after will get

HTTP/1.1 400 Bad Request
Connection: close
Date: Wed, 24 Oct 2018 20:32:27 GMT
Server: Kestrel
Content-Length: 0

Notice how the Connection: close? It appears the connection is getting corrupt?

If you change the code from

Content =  new StringContent(requestString, Encoding.UTF8, "application/json")

to

Content = HttpMethod.Get == method ? null : new StringContent(requestString, Encoding.UTF8, "application/json")

Everything works. This also appears to happen on macOS and Linux but not Winodws 10.

[Tratcher]

@mastrauckas why are you sending GET requests with request bodies? Very few servers allow that.

[andre-ss6]

I see. A GET request with a body is returning 400. I think that's against the specification, right? IIRC, the body SHOULD be ignored, but the request should _not_ return 400 just because of that. In any way, as nice as it would be to have servers properly handle that, this is so uncommonly implemented that I think it's pretty useless.

Regarding the issue, I'm pretty sure that's not my case. The case I reported on the OP is a POST request (most -- if not all -- of the requests that presented that problem were POST). Also, the most important thing here is not actually the 400, but the IIS trace.

[mastrauckas]

What makes this hard to troubleshoot is that you can use middleware to catch the exceptions or use UseExceptionHandler and neither would catch this.

To also make this happen and close the connection with a BadRequest, you need to use the shared HttpClient on multiple request after sending the word null in the body before the connection gets corrupted and Kestrel sends the 400 Bad Request.

As far as a POST, I was getting the BadRequest on a POST. I had a shared HttpClient that went like this:

GET with a null in the body and action gets called.
Maybe more GET's with null body, not sure on this.
POST with a good body and got 400 Bad Request with a closed connection and my action never getting called.

Anyway, I was also putting this on here to help others in the future that might come to this thread.

[mastrauckas]

@mastrauckas why are you sending GET requests with request bodies? Very few servers allow that.

It was a bug in our system.

The problem is Kestrel did not send a BadRequest when sending a body with a GET request. It was 2 or 3 request later on a different request that I got the BadRequest.

As I mentioned, I sent a GET with a body and it hit my action and got an Ok status back but on a later call I called with a completely valid POST and got a BadRequest back without even hitting my action.

If it had gotten a BadRequest when sending a GET with a body that would make sense. However, I didn't.

This also only happens on macOS and Linux but _doesn't happen_ on Windows 10.

[andre-ss6]

Do you have Failed Request Traces of that?

[stijnherreman]

We're also experiencing this occasionally with apps hosted as Virtual Applications in an App Service. When it happens, it's always after a deploy. Even a GET to the root returns a 400.
Enabling logging causes the app to restart, after which the issue disappears. Stopping and starting the App Service also makes the issue disappear.

HTTP/1.1 400 Bad Request
Server: Kestrel
X-Powered-By: ASP.NET
Set-Cookie: ARRAffinity=[redacted]
Date: Tue, 18 Dec 2018 14:00:22 GMT
Content-Length: 0

I'll configure our apps to have logging enabled by default and I'll configure connection logging, so hopefully the next time it occurs I can post some logs.

[stijnherreman]

I've created a new issue #5699 because I don't know if our issues are related.

[AndreasTurowski]

We have a similar problem. Our Controller (running in docker on linux, .Net core 2.2, service routing with traefik) is called by a proxy. The client test code sends a post request to the proxy that returns an error status code (NotFound, Forbidden etc.). The next call from the proxy will leads to BadRequest and our controller code is not invoked. We can see the BadRequest in traefik log, so we know that the proxy is not the problem. If we slow down the calls to a call frequency of 1 call in 2 seconds we have no problem. That looks like a DOS prevention. I hope we get some help, because this is absolutely critical in our project.

[andre-ss6]

That's interesting. We didn't try, back when this was happening, to slow down the requests and see how that would affect the rate at which the problem appears. It's also interesting because, as I reported in one of my earlier replies, we managed to track down one of the 400 issues (not the originally reported, because that one has some different peculiarities, like timeTaken of 0 and a successful error code) to being caused by sending two identical requests in a small time frame.

[animalcaretechnologies]

I am having the same issue as AndreasTurowski. I have not solved it yet, but it appears to only happen when the connection is kept alive between multiple requests. I see the following error logged in kestrel.

dbug: Microsoft.AspNetCore.Server.Kestrel[26]
Connection id "0HLKSTHRBLL2M", Request id "0HLKSTHRBLL2M:00000002": done reading request body.
info: Microsoft.AspNetCore.Server.Kestrel[17]
Connection id "0HLKSTHRBLL2M" bad request data: "Invalid request line: '1\x0D\x0A'"
Microsoft.AspNetCore.Server.Kestrel.Core.BadHttpRequestException: Invalid request line: '1\x0D\x0A'

[animalcaretechnologies]

Turns out it has nothing to do with keep-alive header. My issue was a traefik bug. One request was adding the header "expect:100-continue" and traefik does not forward correctly when that header is present. It was not actually forwarding the post data.

https://github.com/containous/traefik/issues/2899

[AndreasTurowski]

After a while and some updates of .net core, the problem has changed its face. Now we get a 505 Status Code (Http version not supported). Our client is an old piece of software that sends requests with HTTP/1.0 and "Connection: close"-Header to a proxy. That proxy keeps the Connection: close in the header but sends the request as HTTP/1.1 to our controller. After changing the proxy code to send the request with the original HTTP/1.0 protocol, everything works fine. I think, we can close this issue.

[nizarelouaer]

I am having the same issue. My client is sending a POST request with a JSON Body. My services is a .net core 3.1 web api. When I send a POST request I am receiving 400 BAD Request. I analyzed the request and saw that the header has the key:
""""
Connection | Upgrade, HTTP2-Settings
""""
This is actually causing the problem. I cannot modify the headers because I have no control on the client app. IS there a workaround in the kerstel settings ?
Thank you

[nicoske]

We had the same issue with nginx and we solved it by forward the connection header received from the client:

proxy_set_header Connection $http_connection;

Instead of

proxy_set_header Connection "Upgrade";

[TheMisir]

We had the same issue with nginx and we solved it by forward the connection header received from the client:

proxy_set_header Connection $http_connection;

Instead of

proxy_set_header Connection "Upgrade";

Thank you so much, this worked for me. Also I'm wondering why this issue is happening.

[msftbot[bot]]

Thank you for contacting us. Due to a lack of activity on this discussion issue we're closing it in an effort to keep our backlog clean. If you believe there is a concern related to the ASP.NET Core framework, which hasn't been addressed yet, please file a new issue.

This issue will be locked after 30 more days of inactivity. If you still wish to discuss this subject after then, please create a new issue!