Set StatusCode before disposing HttpContext (#876) #993

mikeharder · 2016-07-19T19:34:31Z

Recommend ignoring whitespace when viewing the diff: https://github.com/aspnet/KestrelHttpServer/pull/993/files?w=0

Addresses #876

@halter73, @CesarBS, @JunTaoLuo

halter73 · 2016-07-19T21:39:49Z

src/Microsoft.AspNetCore.Server.Kestrel/Internal/Http/FrameOfT.cs

                            }

-                            await ProduceEnd();
+                            _application.DisposeContext(context, _applicationException);


I think this should be called even if _requestAborted is true. This can be the case if the app calls HttpContext.Abort(). Might want to add a test for that.

It will also probably require another finally block because messageBody.Consume(); can throw too.

Thanks, I will investigate further. This code was changed recently in 3186e1b.

CC: @CesarBS

Currently, if the app calls HttpContext.Abort(), then HttpContext.Response.StatusCode will be 200 when it's disposed (which appears in the logs). I agree this seems wrong. However, if the app aborts the request then no status code is sent to the client, so the status of the request is technically undefined.

What should HttpContext.Response.StatusCode be in this case? We can set it to 500 which is arguably better than 200, but something like null or -1 (property is an int rather than HttpStatusCode) might be more appropriate.

503? Service Unavailable

Perhaps HttpContext.Response.StatusCode should just be ignored in this case, and the logging code should check HttpContext.RequestAborted, and display something other than the status code (e.g. "aborted").

@benaadams: I think HttpContext.Response.StatusCode should remain whatever it was before the request was aborted, which is already working with my current changes. This seems like a separate issue of whether logging should differentiate between completed and aborted requests.

One edge case currently not handled, is an app which calls HttpContext.Abort() and then throws an exception, which should probably result in HttpContext.Response.StatusCode = 500. We can try to call ProduceEnd() even if the request has been aborted, which will correct set the status code, but I'm not sure if ProduceEnd() assumes the request was not aborted.

Not changing it to something related to it being aborted might confuse automated log parsing?

cesarblum · 2016-07-21T18:42:48Z

Check the failures on Travis - you might need to update those tests that failed.

halter73 · 2016-07-22T00:25:56Z

src/Microsoft.AspNetCore.Server.Kestrel/Internal/Http/FrameOfT.cs

                            }

+                            // ProduceEnd() must be called before _application.DisposeContext(), to ensure
+                            // HttpContext.Response.StatusCode is correctly set when
+                            // IHttpContextFactory.Dispose(HttpContext) is called.
                            await ProduceEnd();


EngineTests.NoResponseSentWhenConnectionIsClosedByServerBeforeClientFinishesSendingRequest seems to be failing because ProduceEnd was moved outside the if block.

I'm not sure that's the case. That test calls Abort(), which will close the connection, so anything written after that (the error response written by ProduceEnd() should not be received by the client.

cesarblum · 2016-10-07T19:24:33Z

src/Microsoft.AspNetCore.Server.Kestrel/Internal/Http/FrameOfT.cs

+                                // IHttpContextFactory.Dispose(HttpContext) is called.
+                                await ProduceEnd();
+                            }
+                            finally


This looks a bit awful. An alternative would be to call DisposeContext() is the catch block for BadHttpRequestException (this is addressing what @halter73 pointed out - DisposeContext() won't be called if messageBody.Consume() throws because of a malformed request.

I think we can get rid of the finally above. I've wanted to clean up the control flow of this method for a while. It's not exactly buggy, but i's confusing because it's not immediately clear what we expect can throw.

To be clear, not this finally, but the one after catch { ReportApplicationError }.

My suggestion is that we have a new try immediately after _application.CreateContext(this);. This try block would continue all the way until this finally.

Yes. This means you would have try { try { await _application.ProcessRequestAsync(context).ConfigureAwait(false); } catch { ..., but at least that's easier to follow.

cesarblum · 2016-10-11T17:16:37Z

Ping.

mikeharder · 2016-10-11T17:37:36Z

cesarblum · 2016-10-11T23:24:13Z

Updated. @halter73 I'm setting status code to 0 when the request is aborted and no response has started.

halter73 · 2016-10-11T23:30:49Z

src/Microsoft.AspNetCore.Server.Kestrel/Internal/Http/FrameOfT.cs

                        }
                    }

+                    StopStreams();


Do you think StopStreams() should go in the finally?

halter73 · 2016-10-11T23:33:16Z

src/Microsoft.AspNetCore.Server.Kestrel/Internal/Http/FrameOfT.cs

+                            {
+                                // If the request was aborted and no response was sent, there's no
+                                // meaningful status code to log.
+                                StatusCode = 0;


How does this interact with TryProduceInvalidRequestResponse()?

I'm thinking I should move await TryProduceInvalidRequestResponse(); inside the check for _requestAborted == 0.

halter73 · 2016-10-11T23:35:22Z

test/Microsoft.AspNetCore.Server.Kestrel.FunctionalTests/ResponseTests.cs

+                },
+                expectedClientStatusCode: null,
+                expectedServerStatusCode: HttpStatusCode.BadRequest,
+                sendMalformedRequest: true);


We should have a test for when the app actual reads the request body, and the swallows the exception or doesn't.

cesarblum · 2016-10-12T17:12:43Z

@halter73 5b03f68 splits request rejection and setting bad request state in Frame, as we dicussed yesterday.

cesarblum · 2016-10-12T17:47:02Z

I'll add a test that validates that an app can write it's own 400 response if it chooses to handle a BadHttpRequestException.

halter73 · 2016-10-12T23:55:34Z

src/Microsoft.AspNetCore.Server.Kestrel/Internal/Http/Frame.cs

-            _requestRejected = true;
-
-            Log.ConnectionBadRequest(ConnectionId, ex);
+            _requestRejectedException = ex;


Shouldn't _requestRejectedException be set in RejectRequest?

I think this is the appropriate place to set that. Connection calls SetBadRequestState() when a time out occurs, and that will be picked up by later by TryProduceInvalidRequestResponse(). Besides, _requestRejectedException is state too.

halter73 · 2016-10-14T18:42:34Z

SingleErrorResponseSentWhenAppSwallowsBadRequestException is failed on the last commit on AppVeyor. It was testing this commit where the TCP loopback fast path code was already removed.

cesarblum · 2016-10-15T01:09:21Z

TestConnection is failing to receive data when the FIN handshake isn't completed and the server sends an RST. My guess is that the shutdown callback is called before the FIN handshake is done, and the RST is sent when we dispose the socket.

It's a weird issue though since the response data was sent by the server (can see it in Message Analyzer), but it looks as if you can't read buffered data if the connection was reset. The problem is probably all the way down in winsock - we've seen a similar issue in the past.

cesarblum · 2016-10-17T21:02:43Z

The test failure is not related to this PR. Any more feedback?

halter73 · 2016-10-17T21:39:18Z

src/Microsoft.AspNetCore.Server.Kestrel/Internal/Http/FrameOfT.cs

                        {
-                            // End the connection for non keep alive as data incoming may have been thrown off
-                            return;
+                            SetBadRequestState(ex);


Add comment that this is for bad request data in the request body (not start line/headers) and SetBadRequestState can't be called later because _application.DisposeContext logs the status code.

Added comments.

halter73 · 2016-10-17T21:55:10Z

dnfclas added the cla-already-signed label Jul 19, 2016

halter73 reviewed Jul 19, 2016
View reviewed changes

halter73 reviewed Jul 22, 2016
View reviewed changes

halter73 assigned cesarblum Jul 25, 2016

cesarblum force-pushed the mikeharder/httpcontext-dispose branch from 760225c to b822cd2 Compare October 7, 2016 19:23

cesarblum reviewed Oct 7, 2016

View reviewed changes

cesarblum force-pushed the mikeharder/httpcontext-dispose branch from b822cd2 to 81a182a Compare October 11, 2016 17:29

cesarblum force-pushed the mikeharder/httpcontext-dispose branch from 81a182a to 25b2c94 Compare October 11, 2016 23:17

cesarblum force-pushed the mikeharder/httpcontext-dispose branch from 25b2c94 to 80b7252 Compare October 11, 2016 23:24

halter73 reviewed Oct 11, 2016

View reviewed changes

cesarblum force-pushed the mikeharder/httpcontext-dispose branch from 5b03f68 to f7b7319 Compare October 12, 2016 17:13

cesarblum force-pushed the mikeharder/httpcontext-dispose branch from f7b7319 to 15dae1a Compare October 12, 2016 18:53

halter73 reviewed Oct 12, 2016

View reviewed changes

cesarblum force-pushed the mikeharder/httpcontext-dispose branch from 2fe2be0 to 2164f8a Compare October 13, 2016 18:38

cesarblum force-pushed the mikeharder/httpcontext-dispose branch from 2164f8a to 5b79e7e Compare October 17, 2016 21:03

halter73 reviewed Oct 17, 2016

View reviewed changes

halter73 approved these changes Oct 17, 2016

View reviewed changes

mikeharder and others added 2 commits October 17, 2016 15:16

Set StatusCode before disposing HttpContext (#876)

f1071de

Separate request rejection from bad request state setting.

7858479

cesarblum force-pushed the mikeharder/httpcontext-dispose branch from a868f6f to 7858479 Compare October 17, 2016 22:17

cesarblum merged commit 7858479 into dev Oct 17, 2016

cesarblum deleted the mikeharder/httpcontext-dispose branch October 17, 2016 22:22

halter73 mentioned this pull request Nov 2, 2016

Functional tests failing due to aborted connections #1167

Closed

benaadams mentioned this pull request Jan 21, 2017

Use ContentLength as primary data source #1313

Merged

Set StatusCode before disposing HttpContext (#876) #993

Set StatusCode before disposing HttpContext (#876) #993

Uh oh!

Conversation

mikeharder commented Jul 19, 2016 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

Choose a reason for hiding this comment

Uh oh!

mikeharder Jul 20, 2016 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

cesarblum commented Jul 21, 2016

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

cesarblum commented Oct 11, 2016

Uh oh!

mikeharder commented Oct 11, 2016

Uh oh!

cesarblum commented Oct 11, 2016

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

cesarblum commented Oct 12, 2016

Uh oh!

cesarblum commented Oct 12, 2016

Uh oh!

Choose a reason for hiding this comment

Uh oh!

cesarblum Oct 13, 2016 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

halter73 commented Oct 14, 2016

Uh oh!

cesarblum commented Oct 15, 2016

Uh oh!

cesarblum commented Oct 17, 2016

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

halter73 commented Oct 17, 2016

Uh oh!

Uh oh!

mikeharder commented Jul 19, 2016 •

edited

Loading

mikeharder Jul 20, 2016 •

edited

Loading

cesarblum Oct 13, 2016 •

edited

Loading