Make connection reset logs less scary #1199

halter73 · 2016-11-05T00:40:22Z

Particularly between requests, connection resets aren't that abnormal.

halter73 · 2016-11-05T00:46:24Z

cesarblum · 2016-11-05T01:16:57Z

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

@@ -188,6 +209,10 @@ public class Frame<TContext> : Frame
                // SetBadRequestState logs the error.
                SetBadRequestState(ex);
            }
+            catch (IOException ex) when (ex.InnerException is UvException)


Why don't you do all checks here and avoid the new try/catch block around the code that reads the request line?

This isn't for that. The try/catch above handles that and completely swallows it if it's incomplete. This replaces the "Connection processing ended abnormally" with a better one which has an eventId, connectionId, etc... Since we know a bad connection can cause SocketInput to throw and cause request processing to end abnormally, it's better to handle that explicitly. This catch will handle any connection error, not just resets.

Log.LogWarning(0,... is generally reserved for things we don't expect to happen under normalish circumstances.

Yeah, what I meant was, let the code above throw and catch it here, then check those conditions up there (_requestLineStatus and StatusCodes) here and make the appropriate trace call.

I might be missing something, but I don't see the need for the try/catch above and going through the whole thing with _requestProcessingStopping being false. You're ending the loop anyways, just let it throw.

👍 👍 👍 👍

cesarblum · 2016-11-05T01:20:58Z

src/Microsoft.AspNetCore.Server.Kestrel/KestrelServer.cs

+                if (!Constants.ECONNRESET.HasValue)
+                {
+                    _logger.LogWarning("Unable to determine ECONNRESET value on this platform.");
+                }


nit: add new line after this block

I copied the formatting directly from 1.0.0. You wrote that, right? 😝 I think having them together is fine since they're so closely related.

lol

when I see two if blocks like that I sometimes mentally insert a non-existing else before the second if when reading the code.

But this is not really critical so you can leave it as is.

cesarblum · 2016-11-05T01:22:28Z

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

+                Assert.True(await connectionResetLogged.WaitAsync(_semaphoreWaitTimeout));
+
+                // Check the no log level higher than Debug was used for a reset before a request
+                Assert.True(testSink.MaxLogLevel <= LogLevel.Debug);


Assert equality here.

cesarblum · 2016-11-05T01:22:50Z

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

@@ -191,12 +192,12 @@ public Task RemoteIPv6Address()
        }

        [Fact]
-        public async Task ConnectionResetAbortsRequest()
+        public async Task ConnectionResetPriorToRequestIsLoggedQuietly()


...LoggedAsDebug is more precise

cesarblum · 2016-11-05T01:23:42Z

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

+                Assert.Contains("reset", testSink.ConnectionResetMessage);
+            }
+        }
+


nit: remove extra blank line

cesarblum · 2016-11-05T01:23:57Z

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

+                Assert.All(waitAsyncResults, Assert.True);
+
+                // Check the no log level lower than Information was used for a reset mid-request
+                Assert.True(testSink.MaxLogLevel >= LogLevel.Information);


Assert equality.

cesarblum · 2016-11-05T01:25:36Z

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

+                        catch (IOException ex)
+                        {
+                            // Silence ECONNRESET errors made between requests
+                            if (_requestLineStatus == RequestLineStatus.Empty &&


Place requestLineStatus in an outer scope - better than making it a Frame member.

It means that we need to move TakeStartLine out of the while condition, or do assignment in the condition. Both seemd icky to me.

Doesn't C# allow while (... && (requestLineStatus = TakeStartLine(...)) != ...) ?

It does, but I don't like it.

You dislike it more than a break in a catch block?

cesarblum · 2016-11-05T01:26:20Z

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

+
+
+        [Fact]
+        public async Task ConnectionResetMidRequestIsLoggedLessQuietly()


...LoggedAsInformation

halter73 · 2016-11-05T03:35:19Z

Addressed pr feedback.

cesarblum · 2016-11-05T04:22:22Z

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

+            {
+                // Don't log ECONNRESET errors made between requests. Browsers like IE will reset connections regularly.
+                if (requestLineStatus != RequestLineStatus.Empty ||
+                    ((UvException)ex.InnerException).StatusCode != Constants.ECONNRESET.Value)


Need to check HasValue first

cesarblum · 2016-11-05T04:23:17Z

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

+                    ((UvException)ex.InnerException).StatusCode != Constants.ECONNRESET.Value)
+                {
+                    Log.RequestProcessingError(ConnectionId, ex);
+                }


else Log.ConnectionReset?

We already log that in Connection.OnRead. Part of this was getting rid of that double logging.

- Particularly between requests, connection resets aren't that abnormal.

dnfclas added the cla-already-signed label Nov 5, 2016

cesarblum suggested changes Nov 5, 2016

View reviewed changes

halter73 force-pushed the halter73/1176 branch from 6c79b25 to 8d00e94 Compare November 5, 2016 03:34

halter73 force-pushed the halter73/1176 branch from f0c1110 to 329138a Compare November 5, 2016 04:17

cesarblum reviewed Nov 5, 2016

View reviewed changes

cesarblum approved these changes Nov 5, 2016

View reviewed changes

halter73 force-pushed the halter73/1176 branch from aedd6a3 to 408aef0 Compare November 5, 2016 04:35

Make connection reset logs less scary

0d55946

- Particularly between requests, connection resets aren't that abnormal.

halter73 force-pushed the halter73/1176 branch from 408aef0 to 0d55946 Compare November 5, 2016 04:37

halter73 merged commit 0d55946 into dev Nov 5, 2016

halter73 deleted the halter73/1176 branch November 5, 2016 04:38

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Make connection reset logs less scary #1199

Make connection reset logs less scary #1199

halter73 commented Nov 5, 2016

halter73 commented Nov 5, 2016

cesarblum Nov 5, 2016

halter73 Nov 5, 2016

cesarblum Nov 5, 2016

halter73 Nov 5, 2016

cesarblum Nov 5, 2016

halter73 Nov 5, 2016

cesarblum Nov 5, 2016

cesarblum Nov 5, 2016

cesarblum Nov 5, 2016

cesarblum Nov 5, 2016

cesarblum Nov 5, 2016

cesarblum Nov 5, 2016

halter73 Nov 5, 2016

cesarblum Nov 5, 2016

halter73 Nov 5, 2016

cesarblum Nov 5, 2016

cesarblum Nov 5, 2016

halter73 commented Nov 5, 2016

cesarblum Nov 5, 2016

cesarblum Nov 5, 2016

halter73 Nov 5, 2016



		[Fact]
		public async Task ConnectionResetMidRequestIsLoggedLessQuietly()

Make connection reset logs less scary #1199

Make connection reset logs less scary #1199

Conversation

halter73 commented Nov 5, 2016

halter73 commented Nov 5, 2016

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

halter73 commented Nov 5, 2016

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment