Improve Kestrel connection metrics with error reasons #55565

JamesNK · 2024-05-07T03:31:19Z

This PR improves the kestrel.connection.duration metric by adding information about why the connection ended.

Tags added or changed:

http.connection.protocol_code - Standards based, publicly communicated code for the connection ending. Often sent to the client. The value is either the HTTP/2 error code or HTTP/3 error code that the connection ended with. Doesn't apply to HTTP/1.1.
kestrel.connection.end_reason - A more detailed internal reason about why a connection ended. Always present.
error.type - If the end reason is an error, e.g. connection killed because of timeout, excessive stream resets, transport ended while there are active HTTP requests, invalid frame, etc. error.type could be the same as the end reason. The value could also be an exception type name if an unhandled exception is thrown from connection middleware pipeline. The first error recorded wins. Only present if there is an error.

We need to decide what the new tags is. Is it the end reason or error reason? For example, a connection can be ended by the client sending a go away frame. Do we want to track that? It's not an error to close a connection like that, so in this case we're are tracking all end reasons. On the other hand, we might want to only track unexpected and unhealthy reasons that end the connection. The benefit of only tracking errors is it is very easy to get just the unhealthy connections by filtering metrics to ones that have this tag. However, I think we can achieve this by also putting error reasons into the error.type tag.

tldr kestrel.connection.end_reason is always present and provides the reason, error.type is present if the end reason is considered an error and has the same value as kestrel.connection.end_reason.

Questions for folks:

Is having information about all connection end reasons useful? If it isn't then we could remove kestrel.connection.end_reason and just have error.type.
What end reasons are an error? For example, are the following errors or not...
- Transport closing when there are no active HTTP requests
- Transport closing when there are active HTTP requests
- Connection closing because the application is shutting down
- Client sends GOAWAY with error code of NO_ERROR
- Client sends GOAWAY with error code of INTERNAL_ERROR

Tasks:

cc @noahfalk @tarekgh @lmolkova @samsp-msft

JamesNK · 2024-05-07T03:41:07Z

src/Servers/Kestrel/test/InMemory.FunctionalTests/Http2/Http2ConnectionTests.cs

@@ -1727,7 +1727,7 @@ public async Task AbortConnectionAfterTooManyEnhanceYourCalms()
        await WaitForConnectionErrorAsync<Http2ConnectionErrorException>(
            ignoreNonGoAwayFrames: true,
            expectedLastStreamId: int.MaxValue,
-            expectedErrorCode: Http2ErrorCode.INTERNAL_ERROR,
+            expectedErrorCode: Http2ErrorCode.ENHANCE_YOUR_CALM,


@amcasey I added a HttpConnection.Abort overload that has an Http2ErrorCode argument. When there are excessive resets I made the passed in value ENHANCE_YOUR_CALM instead of INTERNAL_ERROR. That seems a more appropriate error.

Did you choose INTERNAL_ERROR for a reason here, or is it returned because that is what abort already sent?

This was a hotfix, so I suspect I was making the smallest change possible, but I no longer recall.

src/Servers/Kestrel/Core/src/Internal/Http2/Http2Connection.cs

noahfalk · 2024-05-09T08:49:19Z

Is having information about all connection end reasons useful?

What was the motivation to add the data initially? I can hypothesize a reason someone might find it useful (diagnosing why connections didn't live as long as they were expected to live) but I don't know how often someone needs to diagnose that issue in practice and what alternatives would they have available if this metric attribute didn't exist?

What end reasons are an error? For example, are the following errors or not..

Any attempt at classification gets very subjective but a few suggestions at least:

Ideally errors represent situations that do not occur frequently and are undesirable. For example "Connection closing because the application is shutting down" might be infrequent but it doesn't sound undesirable.
Ideally metric error classifications would consistent with other observable behavior that implies an error classification. For example if in-proc code throws an Exception or some error code is transmitted in the wire protocol then it would consistent for the metrics to also classify that condition as an error. If "Client sends GOAWAY with error code of NO_ERROR" then it would consistent for metrics also not to treat that as an error.

src/Servers/Kestrel/Core/src/Internal/Http/Http1OutputProducer.cs

lmolkova · 2024-05-09T16:44:13Z

I think it's valuable to know the end reason even if it's not an error and even if we don't have a specific scenario in mind.
I also don't see any drawbacks from including it - it would not increase cardinality much.

The change looks great from semconv perspective! LMK if you need any help adding new attributes to otel.

samsp-msft · 2024-05-09T21:12:28Z

This seems like data that should be going into logs not metrics. Metric dimensions should be kept small as adding additional properties and values adds incremental storage. If we can reduce this data down to one property - was the connection closed cleanly or due to an error, and provide logs to give more details as to why. Metrics are supposed to be about aggregated statistics not detailed analysis as to what happened.

Anyone who is going to be doing analysis, can the use the metric to determine if the trend is changing, and then go to a log query to understand why.

Once exemplars are better supported in .NET/OTel they will provide the correlation between metrics and traces/logs.

JamesNK · 2024-05-10T00:52:16Z

@samsp-msft

There is prior art for showing more error info in error.type. That tag is already on HTTP requests for server and client in spans and metrics. Reducing error info down to a boolean is optimizing too much and goes against conventions.

http.connection.protocol_code (exact name TBD) is the HTTP connection version of request's HTTP status code. I don't think it is controversial.

kestrel.connection.end_reason is more debatable. My feeling from talking to people using Kestrel over the years is connections are a black box and people want more insight here. If there are performance/technical reasons why an extra tag is problematic, then I can reach out to ops folks to get feedback on whether end reasons for "non-error" situations would be useful.

Note that while the ConnectionEndReason enum has a lot of potential values (about 35), many of them are for protocol violations which will almost never happen, or are specific to one particular HTTP protocol (e.g. closing a critical stream is specific to HTTP/3). There are about half a dozen would occur in typical usage:

ConnectionReset
UnexpectedError
AbortedByApplication
ApplicationShutdown
ServerTimeout
IOError
ClientGoAway
TransportCompleted

That is similar to how there are many HTTP status codes, but most of them you'll never see.

amcasey · 2024-05-13T19:55:45Z

src/Servers/Kestrel/Core/src/Internal/HttpConnection.cs

@@ -64,6 +64,7 @@ public HttpConnection(BaseHttpConnectionContext context)
                    // _http2Connection must be initialized before yielding control to the transport thread,
                    // to prevent a race condition where _http2Connection.Abort() is called just as
                    // _http2Connection is about to be initialized.
+                    _context.ConnectionFeatures.Set<IProtocolErrorCodeFeature>(new ProtocolErrorCodeFeature());


I think you may already have explained, but why isn't this needed for http/3 as well?

amcasey · 2024-05-13T19:57:34Z

src/Servers/Kestrel/Core/src/Internal/HttpConnection.cs

                break;
            case TimeoutReason.RequestBodyDrain:
            case TimeoutReason.TimeoutFeature:
-                Abort(new ConnectionAbortedException(CoreStrings.ConnectionTimedOutByServer));
+                Abort(new ConnectionAbortedException(CoreStrings.ConnectionTimedOutByServer), ConnectionEndReason.ServerTimeout);


Do we want a separate reason for RequestBodyDrain? That sounds like it might be about OS timing that we don't control?

amcasey · 2024-05-13T19:59:32Z

src/Servers/Kestrel/Core/src/Internal/Http/Http1Connection.cs

        CancelRequestAbortedToken();
    }

    void IHttpOutputAborter.OnInputOrOutputCompleted()
    {
-        _http1Output.Abort(new ConnectionAbortedException(CoreStrings.ConnectionAbortedByClient));
+        _http1Output.Abort(new ConnectionAbortedException(CoreStrings.ConnectionAbortedByClient), ConnectionEndReason.TransportCompleted);


I'm a little nervous we're going to get a bug saying there was a spike in TransportCompleted and we'll need to know which of these it was.

amcasey · 2024-05-13T20:00:42Z

src/Servers/Kestrel/Core/src/Internal/Http/Http1MessageBody.cs

@@ -72,7 +72,7 @@ protected override Task OnConsumeAsync()
            _context.ReportApplicationError(connectionAbortedException);

            // Have to abort the connection because we can't finish draining the request
-            _context.StopProcessingNextRequest();
+            _context.StopProcessingNextRequest(ConnectionEndReason.AbortedByApplication);


It feels like we might want to distinguish between "the application requested an abort" and "the application failed and we had to abort".

amcasey · 2024-05-13T20:04:02Z

src/Servers/Kestrel/Core/src/Internal/Http2/Http2Connection.cs

        }
        catch (Exception ex)
        {
            Log.LogWarning(0, ex, CoreStrings.RequestProcessingEndError);
            error = ex;
            errorCode = Http2ErrorCode.INTERNAL_ERROR;
+            reason = ConnectionEndReason.UnexpectedError;


Maybe "unknown error"? It seems weird to describe it as "unexpected".

amcasey · 2024-05-13T20:10:49Z

src/Servers/Kestrel/Core/src/Internal/Http2/Http2FrameWriter.cs

        _log.Http2ConnectionError(_connectionId, connectionError);
        await WriteGoAwayAsync(int.MaxValue, Http2ErrorCode.FLOW_CONTROL_ERROR);

        // Prevent Abort() from writing an INTERNAL_ERROR GOAWAY frame after our FLOW_CONTROL_ERROR.
        Complete();
        // Stop processing any more requests and immediately close the connection.
-        _http2Connection.Abort(new ConnectionAbortedException(CoreStrings.Http2ErrorWindowUpdateSizeInvalid, connectionError));
+        _http2Connection.Abort(new ConnectionAbortedException(CoreStrings.Http2ErrorWindowUpdateSizeInvalid, connectionError), Http2ErrorCode.FLOW_CONTROL_ERROR, ConnectionEndReason.WindowUpdateSizeInvalid);


Will anything bad happen if the ConnectionEndReason gets out of sync with connectionError?

amcasey · 2024-05-13T20:13:33Z

src/Servers/Kestrel/Core/src/Internal/Http3/Http3Connection.cs

@@ -530,8 +544,14 @@ private void UpdateStreamTimeouts(long timestamp)
                    await outboundControlStreamTask;
                }

+                // Use graceful close reason if it has been set.
+                if (reason == ConnectionEndReason.Unknown && _gracefulCloseReason != ConnectionEndReason.Unknown)


Nit: I don't think && _gracefulCloseReason != ConnectionEndReason.Unknown actually accomplishes anything.

amcasey · 2024-05-13T20:27:44Z

Is having information about all connection end reasons useful? If it isn't then we could remove kestrel.connection.end_reason and just have error.type.

With the notable disclaimer that I haven't actually monitored the health of a real service...

I think I'd want to have it for all connections. Sure, the majority will be graceful shutdowns (hopefully), but it's (I assume) easy enough to filter out a few uninteresting values and which values are uninteresting seems (as mentioned above) very subjective.

Another reason to include things that don't seem like errors is for making attack signatures. Something that's "normal" for a single connection may be problematic when it happens on many connections simultaneously. Or it may not be problematic, but still indicate that a change that signals a problem will soon occur.

Personally, I think I'd have just end_reason and drop error_type altogether (with the caveat that we might want a special way to represent unhandled exceptions).

If we go the other way, we have all sorts of strange cases to consider like whether cutting off a slow-reading client is an error. Arguably, that's the system functioning as expected and desired, but it's still interesting.

amcasey · 2024-05-13T20:30:56Z

This seems like data that should be going into logs not metrics

@samsp-msft I'm not sure I'm following this line of reasoning. Given that logs are structured and queryable, why would anything not be logs-only? When would you use metrics instead?

dotnet-policy-service · 2024-05-21T04:52:10Z

Looks like this PR hasn't been active for some time and the codebase could have been changed in the meantime.
To make sure no conflicting changes have occurred, please rerun validation before merging. You can do this by leaving an /azp run comment here (requires commit rights), or by simply closing and reopening.

JamesNK added the area-networking Includes servers, yarp, json patch, bedrock, websockets, http client factory, and http abstractions label May 7, 2024

JamesNK requested a review from amcasey May 7, 2024 03:31

JamesNK requested review from halter73, BrennanConroy and mgravell as code owners May 7, 2024 03:31

JamesNK commented May 7, 2024

View reviewed changes

gfoidl reviewed May 7, 2024

View reviewed changes

src/Servers/Kestrel/Core/src/Internal/Http2/Http2Connection.cs Show resolved Hide resolved

JamesNK added 12 commits May 9, 2024 16:36

Add protocol code to HTTP/2 and HTTP/3 connection metric

bf9be17

Add reason to connection exception

a3d42a7

More

01d1171

Clean up

20c375a

HTTP/1.1 and HTTP/2

565455d

Tests

0895465

Fix build

2771ca4

Fix microbenchmarks

87604f5

Tests

95d03fc

Rename

3abf81f

Fix tests

c893100

Clean up

8a35061

JamesNK force-pushed the jamesnk/connection-protocol-code branch from 7c05f97 to 8a35061 Compare May 9, 2024 08:36

noahfalk reviewed May 9, 2024

View reviewed changes

src/Servers/Kestrel/Core/src/Internal/Http/Http1OutputProducer.cs Outdated Show resolved Hide resolved

JamesNK added 2 commits May 9, 2024 21:32

Remove NoError and always tag reason tag

7fd9dd5

Fix build

e5e02a8

JamesNK added 2 commits May 10, 2024 14:07

Report error from failed TLS handshake

605d068

Fix build

eb1b413

amcasey reviewed May 13, 2024

View reviewed changes

dotnet-policy-service bot added the pending-ci-rerun When assigned to a PR indicates that the CI checks should be rerun label May 21, 2024

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Improve Kestrel connection metrics with error reasons #55565

Improve Kestrel connection metrics with error reasons #55565

JamesNK commented May 7, 2024 •

edited

JamesNK May 7, 2024

amcasey May 13, 2024

noahfalk commented May 9, 2024

lmolkova commented May 9, 2024

samsp-msft commented May 9, 2024

JamesNK commented May 10, 2024 •

edited

amcasey May 13, 2024

amcasey May 13, 2024

amcasey May 13, 2024

amcasey May 13, 2024

amcasey May 13, 2024

amcasey May 13, 2024

amcasey May 13, 2024

amcasey commented May 13, 2024

amcasey commented May 13, 2024

dotnet-policy-service bot commented May 21, 2024

Improve Kestrel connection metrics with error reasons #55565

Are you sure you want to change the base?

Improve Kestrel connection metrics with error reasons #55565

Conversation

JamesNK commented May 7, 2024 • edited

Choose a reason for hiding this comment

Choose a reason for hiding this comment

noahfalk commented May 9, 2024

lmolkova commented May 9, 2024

samsp-msft commented May 9, 2024

JamesNK commented May 10, 2024 • edited

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

amcasey commented May 13, 2024

amcasey commented May 13, 2024

dotnet-policy-service bot commented May 21, 2024

JamesNK commented May 7, 2024 •

edited

JamesNK commented May 10, 2024 •

edited