Implement IHttpRequestIdentifierFeature on Frame by natemcmaster · Pull Request #1578 · aspnet/KestrelHttpServer

natemcmaster · 2017-03-31T16:47:06Z

This feature generates a unique ID per request. This unique ID can be used in event source and logging.

Also, this change improves KestrelEventSource by moving it back into the Kestrel.Core assembly and de-coupling from the Libuv transport. This adds two new events, RequestStart and RequestStop, which can be used to identify the correlation between connection ID and request trace
identifier.

Resolves #1367

Benchmark

-n Plaintext --kestrelThreadCount 2
dev
RPS: 1344136.86
RPS: 1374674.53

log-request-id
RPS: 1341543.62
RPS: 1360439.85

natemcmaster · 2017-03-31T16:49:00Z

src/Microsoft.AspNetCore.Server.Kestrel.Core/Internal/Infrastructure/CorrelationIdGenerator.cs

+
+namespace Microsoft.AspNetCore.Server.Kestrel.Internal.Infrastructure
+{
+    internal static class CorrelationIdGenerator


Depending on the outcome of dotnet/extensions#197, this may move to Microsoft.Extensions.Primitives

Why not leave it in HttpAbstractions? Kestrel and Hosting would have access to it there. Or does something else need it?

I'll refer you to dotnet/extensions#197 on that one. @muratg is looking into it.

natemcmaster · 2017-03-31T17:12:27Z

Sample log when application request has an error:

fail: Microsoft.AspNetCore.Server.Kestrel[13]
      Connection id "0HL3OB48ARG6C", Request id "0HL3OB48ARG6H": An unhandled exception was thrown by the application.

Tratcher · 2017-03-31T17:16:23Z

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

        bool IHttpResponseFeature.HasStarted
        {
-            get { return HasResponseStarted; }
+            get => HasResponseStarted;


These can be reduced to bool IHttpResponseFeature.HasStarted => HasResponseStarted; right?

Yes. Will update.

davidfowl · 2017-03-31T17:20:53Z

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

                        {
                            try
                            {
+                                KestrelEventSource.Log.RequestStart(this);


I wonder if we need these events. Hosting does the exact same thing what value do we add here?

Hosting only logs method and path. This logs connectionId and requestId to make it possible to correlate connections and requests.

cesarblum · 2017-03-31T17:19:04Z

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

-            var stop = Assert.Single(events, e => e.EventName == "ConnectionStop");
-            Assert.All(new[] { "connectionId" }, p => Assert.Contains(p, stop.PayloadNames));
-            Assert.Same(KestrelEventSource.Log, stop.EventSource);
+            {


Why the scopes?

avoiding copy+paste errors. Because the asserts for each event type looks so similar.

cesarblum · 2017-03-31T17:20:03Z

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

+                var id = Encoding.ASCII.GetBytes(context.TraceIdentifier);
+                Assert.Equal(IdentifierLength, id.Length);
+                context.Response.ContentLength = id.Length;
+                context.Response.Body.Write(id, 0, id.Length);


WriteAsync

Returns chunked encoding, which made it more difficult to pull the response body via StreamReader.

cesarblum · 2017-03-31T17:21:22Z

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

+            }))
+            {
+                var usedIds = new HashSet<string>();
+                var usedIdsLock = new object();


Why not ConcurrentBag instead of set + lock?

Yeah, i'll use that. will update

cesarblum · 2017-03-31T17:21:46Z

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

+                });
+
+                // requests on same connection
+                using (var conn = server.CreateConnection())


nit: call it connection since that's we call it in all other tests

cesarblum · 2017-03-31T17:32:16Z

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

+                // requests on same connection
+                using (var conn = server.CreateConnection())
+                {
+                    var buff = new char[IdentifierLength];


Buff is a funny name, call it either buf or buffer 😄

ᕙ༼ຈل͜ຈ༽ᕗ

cesarblum · 2017-03-31T17:33:34Z

test/Microsoft.AspNetCore.Server.KestrelTests/FrameTests.cs

+            Assert.NotNull(id);
+            Assert.Equal(id, _frame.TraceIdentifier);
+
+            _frame.TraceIdentifier = null;


Assert.NotNull again?

It's implicit as we already asserted id != null.

halter73 · 2017-03-31T17:47:22Z

src/Microsoft.AspNetCore.Server.Kestrel.Core/Internal/Infrastructure/IKestrelTrace.cs

        void NotAllConnectionsAborted();

-        void ApplicationError(string connectionId, Exception ex);
+        void ApplicationError(string connectionId, string traceIdentifier, Exception ex);


halter73 · 2017-03-31T17:48:28Z

Would it make sense to give connection and request id's unique prefixes to make them easier to distinguish in logs?

halter73 · 2017-03-31T17:52:17Z

...t.AspNetCore.Server.Kestrel.Transport.Libuv/Internal/Infrastructure/EventSourceExtensions.cs

+{
+    public static class EventSourceExtensions
+    {
+        public static void ConnectionStart(this KestrelEventSource eventSource, Connection connection)


Since you are moving KestrelEventSource back to the Core project, can this change also move the connection start/stop logging to core? It would be nice if this tracing could be shared between transports.

This change was required to decouple Connection which is in Transport.Libuv and KestrelEventSource which is now in Core. ConnectionStop/Start are still on KestrelEventSource which is in Kestrel.Core, but the public methods now take string arguments directly instead of Connection.

I still think this is worth doing now. Rather than partially moving KestrelEventSource to Core, let's move it completely. I think this might require adding some sort of OnConnectionClosed() method to IConnectionContext, but it should still be a pretty quick/simple change.

natemcmaster · 2017-03-31T17:53:59Z

Would it make sense to give connection and request id's unique prefixes to make them easier to distinguish in logs?

@shirhatti thoughts?

Another idea I played with making each request ID contain the connection id so correlation is even easier.

// pseudocode
var count = _connectionRequests++;
var requestId = $"{_connectionId}:{count}";

natemcmaster · 2017-03-31T21:17:07Z

🆙 📅

cesarblum · 2017-03-31T19:47:03Z

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

+                    {
+                        await connection.Send("GET / HTTP/1.1",
+                            "Content-Length: 0",
+                            "Host: localhost",


No need to send Content-Length and Host here.

cesarblum · 2017-03-31T19:47:20Z

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

+
+                        await connection.Receive($"HTTP/1.1 200 OK",
+                           $"Date: {server.Context.DateHeaderValue}",
+                           "Content-Length: " + IdentifierLength,


nit: use $""

shirhatti · 2017-03-31T21:27:45Z

Another idea I played with making each request ID contain the connection id so correlation is even easier.

YES please!

@glennc Thoughts?

natemcmaster · 2017-03-31T21:48:50Z

@shirhatti I will follow up via email. Not everyone checks PR comments.

halter73 · 2017-03-31T23:47:15Z

src/Microsoft.AspNetCore.Server.Kestrel.Core/Transport/IConnectionContext.cs

        string ConnectionId { get; }
        IPipeWriter Input { get; }
        IPipeReader Output { get; }
+        void OnConnectionClosed();


Nit: Move below "// TODO: Remove these (Use Pipes instead?)"

There is a task that will be added to Pipes that should let us track when SocketOutputConsumer complete's it's pipe reader which will be right after disposing the socket.

This feature generates a unique ID per request. This unique ID can be used in event source and logging. Also, this change improves KestrelEventSource by moving it back into the Kestrel.Core assembly and de-coupling from the Libuv transport. This adds two new events, RequestStart and RequestStop, which can be used to identify the correlation between connection ID and request trace identifier.

natemcmaster requested review from Tratcher, cesarblum and halter73 March 31, 2017 16:47

dnfclas added the cla-already-signed label Mar 31, 2017

natemcmaster commented Mar 31, 2017

View reviewed changes

Tratcher reviewed Mar 31, 2017

View reviewed changes

davidfowl reviewed Mar 31, 2017

View reviewed changes

cesarblum reviewed Mar 31, 2017

View reviewed changes

halter73 reviewed Mar 31, 2017

View reviewed changes

halter73 suggested changes Mar 31, 2017

View reviewed changes

cesarblum reviewed Mar 31, 2017

View reviewed changes

halter73 reviewed Mar 31, 2017

View reviewed changes

halter73 approved these changes Mar 31, 2017

View reviewed changes

natemcmaster force-pushed the log-request-id branch from c05230e to 8395888 Compare March 31, 2017 23:54

natemcmaster mentioned this pull request Apr 1, 2017

Change request trace ID format #1591

Closed

natemcmaster merged commit 8395888 into aspnet:dev Apr 1, 2017

natemcmaster deleted the log-request-id branch April 1, 2017 00:08

Conversation

natemcmaster commented Mar 31, 2017 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Benchmark

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!

natemcmaster commented Mar 31, 2017

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!

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!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

halter73 commented Mar 31, 2017

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!

natemcmaster commented Mar 31, 2017

Uh oh!

natemcmaster commented Mar 31, 2017

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!

shirhatti commented Mar 31, 2017

Uh oh!

natemcmaster commented Mar 31, 2017

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

7 participants

natemcmaster commented Mar 31, 2017 •

edited

Loading