Add timing, log 500 on failure

Author: rynowak

src/Microsoft.AspNet.Hosting/Internal/HostingEngine.cs

@@ -96,22 +96,27 @@ public virtual IApplication Start()
 
                     var requestIdentifier = GetRequestIdentifier(httpContext);
 
-                    contextAccessor.HttpContext = httpContext;
-                    
                     if (diagnosticSource.IsEnabled("Microsoft.AspNet.Hosting.BeginRequest"))
                     {
                         diagnosticSource.Write("Microsoft.AspNet.Hosting.BeginRequest", new { httpContext = httpContext });
                     }
 
                     using (logger.RequestScope(httpContext))
                     {
+                        int startTime = 0;
                         try
                         {
                             logger.RequestStarting(httpContext);
+
+                            startTime = Environment.TickCount;
                             await application(httpContext);
+
+                            logger.RequestFinished(httpContext, startTime);
                         }
                         catch (Exception ex)
                         {
+                            logger.RequestFailed(httpContext, startTime);
+
                             if (diagnosticSource.IsEnabled("Microsoft.AspNet.Hosting.UnhandledException"))
                             {
                                 diagnosticSource.Write("Microsoft.AspNet.Hosting.UnhandledException", new { httpContext = httpContext, exception = ex });
@@ -120,7 +125,6 @@ public virtual IApplication Start()
                         }
                         finally
                         {
-                            logger.RequestFinished(httpContext);
                         }
 
                     }

src/Microsoft.AspNet.Hosting/Internal/HostingLoggerExtensions.cs

@@ -29,19 +29,35 @@ public static void RequestStarting(this ILogger logger, HttpContext httpContext)
             }
         }
 
-        public static void RequestFinished(this ILogger logger, HttpContext httpContext)
+        public static void RequestFinished(this ILogger logger, HttpContext httpContext, int startTimeInTicks)
         {
             if (logger.IsEnabled(LogLevel.Information))
             {
+                var elapsed = new TimeSpan(Environment.TickCount - startTimeInTicks);
                 logger.Log(
                     logLevel: LogLevel.Information,
                     eventId: 2,
-                    state: new HostingRequestFinished(httpContext),
+                    state: new HostingRequestFinished(httpContext, elapsed),
                     exception: null,
                     formatter: HostingRequestFinished.Callback);
             }
         }
 
+        public static void RequestFailed(this ILogger logger, HttpContext httpContext, int startTimeInTicks)
+        {
+            if (logger.IsEnabled(LogLevel.Information))
+            {
+                var elapsed = new TimeSpan(Environment.TickCount - startTimeInTicks);
+                logger.Log(
+                    logLevel: LogLevel.Information,
+                    eventId: 2,
+                    state: new HostingRequestFailed(httpContext, elapsed),
+                    exception: null,
+                    formatter: HostingRequestFailed.Callback);
+            }
+        }
+
+
         private class HostingLogScope : ILogValues
         {
             private readonly HttpContext _httpContext;
@@ -110,29 +126,64 @@ private class HostingRequestFinished
             internal static readonly Func<object, Exception, string> Callback = (state, exception) => ((HostingRequestFinished)state).ToString();
 
             private readonly HttpContext _httpContext;
+            private readonly TimeSpan _elapsed;
 
             private IEnumerable<KeyValuePair<string, object>> _cachedGetValues;
             private string _cachedToString;
 
-            public HostingRequestFinished(HttpContext httpContext)
+            public HostingRequestFinished(HttpContext httpContext, TimeSpan elapsed)
             {
                 _httpContext = httpContext;
+                _elapsed = elapsed;
             }
 
             public override string ToString() => _cachedToString ?? Interlocked.CompareExchange(
                 ref _cachedToString,
-                $"Request finished {_httpContext.Response.StatusCode} {_httpContext.Response.ContentType}",
+                $"Request finished in {_elapsed.TotalMilliseconds}ms {_httpContext.Response.StatusCode} {_httpContext.Response.ContentType}",
                 null);
 
             public IEnumerable<KeyValuePair<string, object>> GetValues() => _cachedGetValues ?? Interlocked.CompareExchange(
                 ref _cachedGetValues,
                 new[]
                 {
+                    new KeyValuePair<string, object>("ElapsedMilliseconds", _elapsed.TotalMilliseconds),
                     new KeyValuePair<string, object>("StatusCode", _httpContext.Response.StatusCode),
                     new KeyValuePair<string, object>("ContentType", _httpContext.Response.ContentType),
                 },
                 null);
         }
+
+        private class HostingRequestFailed
+        {
+            internal static readonly Func<object, Exception, string> Callback = (state, exception) => ((HostingRequestFailed)state).ToString();
+
+            private readonly HttpContext _httpContext;
+            private readonly TimeSpan _elapsed;
+
+            private IEnumerable<KeyValuePair<string, object>> _cachedGetValues;
+            private string _cachedToString;
+
+            public HostingRequestFailed(HttpContext httpContext, TimeSpan elapsed)
+            {
+                _httpContext = httpContext;
+                _elapsed = elapsed;
+            }
+
+            public override string ToString() => _cachedToString ?? Interlocked.CompareExchange(
+                ref _cachedToString,
+                $"Request finished in {_elapsed.TotalMilliseconds}ms 500",
+                null);
+
+            public IEnumerable<KeyValuePair<string, object>> GetValues() => _cachedGetValues ?? Interlocked.CompareExchange(
+                ref _cachedGetValues,
+                new[]
+                {
+                    new KeyValuePair<string, object>("ElapsedMilliseconds", _elapsed.TotalMilliseconds),
+                    new KeyValuePair<string, object>("StatusCode", 500),
+                    new KeyValuePair<string, object>("ContentType", null),
+                },
+                null);
+        }
     }
 }