Log time-taken more precisely (dotnet#35863)

* Log time-taken more precisely * Log to other field * Feedback * Update src/Middleware/HttpLogging/src/W3CLoggingMiddleware.cs Co-authored-by: Kahbazi <[email protected]> * Fix test * Feedback Co-authored-by: Kahbazi <[email protected]>
AJ-72 · Sep 1, 2021 · 916e008 · 916e008
1 parent 0500820
commit 916e008
Show file tree

Hide file tree

Showing 5 changed files with 48 additions and 17 deletions.
diff --git a/src/Middleware/HttpLogging/src/Microsoft.AspNetCore.HttpLogging.csproj b/src/Middleware/HttpLogging/src/Microsoft.AspNetCore.HttpLogging.csproj
@@ -20,5 +20,6 @@
     <Compile Include="$(RepoRoot)src\Shared\TaskToApm.cs" Link="Internal\TaskToApm.cs" />
     <Compile Include="$(SharedSourceRoot)Buffers\**\*.cs" LinkBase="Internal\" />
     <Compile Include="$(SharedSourceRoot)ValueStringBuilder\**\*.cs" />
+    <Compile Include="$(SharedSourceRoot)ValueStopwatch\*.cs" />
   </ItemGroup>
 </Project>
diff --git a/src/Middleware/HttpLogging/src/W3CLogger.cs b/src/Middleware/HttpLogging/src/W3CLogger.cs
@@ -48,16 +48,6 @@ public void Log(string[] elements)
 
         private string Format(string[] elements)
         {
-            // Need to calculate TimeTaken now, if applicable
-            var date = elements[W3CLoggingMiddleware._dateIndex];
-            var time = elements[W3CLoggingMiddleware._timeIndex];
-            if (!string.IsNullOrEmpty(date) && !string.IsNullOrEmpty(time) && _loggingFields.HasFlag(W3CLoggingFields.TimeTaken))
-            {
-                DateTime start = DateTime.ParseExact(date + time, "yyyy-MM-ddHH:mm:ss", CultureInfo.InvariantCulture);
-                var elapsed = DateTime.UtcNow.Subtract(start);
-                elements[W3CLoggingMiddleware._timeTakenIndex] = elapsed.TotalMilliseconds.ToString(CultureInfo.InvariantCulture);
-            }
-
             // 200 is around the length of an average cookie-less entry
             var sb = new ValueStringBuilder(200);
             var firstElement = true;

diff --git a/src/Middleware/HttpLogging/src/W3CLoggingMiddleware.cs b/src/Middleware/HttpLogging/src/W3CLoggingMiddleware.cs
@@ -11,6 +11,7 @@
 using System.Threading.Tasks;
 using Microsoft.AspNetCore.Http;
 using Microsoft.Extensions.Hosting;
+using Microsoft.Extensions.Internal;
 using Microsoft.Extensions.Options;
 using Microsoft.Net.Http.Headers;
 
@@ -91,6 +92,7 @@ public async Task Invoke(HttpContext context)
             bool shouldLog = false;
 
             var now = DateTime.UtcNow;
+            var stopWatch = ValueStopwatch.StartNew();
             if (options.LoggingFields.HasFlag(W3CLoggingFields.Date))
             {
                 shouldLog |= AddToList(elements, _dateIndex, now.ToString("yyyy-MM-dd", CultureInfo.InvariantCulture));
@@ -215,6 +217,11 @@ public async Task Invoke(HttpContext context)
                 shouldLog |= AddToList(elements, _protocolStatusIndex, response.StatusCode.ToString(CultureInfo.InvariantCulture));
             }
 
+            if (options.LoggingFields.HasFlag(W3CLoggingFields.TimeTaken))
+            {
+                shouldLog |= AddToList(elements, _timeTakenIndex, stopWatch.GetElapsedTime().TotalMilliseconds.ToString(CultureInfo.InvariantCulture));
+            }
+
             // Write the log
             if (shouldLog)
             {

diff --git a/src/Middleware/HttpLogging/test/W3CLoggerTests.cs b/src/Middleware/HttpLogging/test/W3CLoggerTests.cs
@@ -28,7 +28,7 @@ public async Task WritesDateTime()
             var now = DateTime.Now;
             var options = new W3CLoggerOptions()
             {
-                LoggingFields = W3CLoggingFields.Date | W3CLoggingFields.Time | W3CLoggingFields.TimeTaken,
+                LoggingFields = W3CLoggingFields.Date | W3CLoggingFields.Time,
                 LogDirectory = path
             };
             try
@@ -50,11 +50,9 @@ public async Task WritesDateTime()
                     // Assert that the log was written in the last 10 seconds
                     Assert.True(now.Subtract(startDate).TotalSeconds < 10);
 
-                    Assert.Equal("#Fields: date time time-taken", lines[2]);
+                    Assert.Equal("#Fields: date time", lines[2]);
 
-                    Assert.StartsWith("2021-01-02 03:04:05 ", lines[3]);
-                    // Assert that the log's time-taken is within 10 seconds of DateTime.Now minus our arbitary start time (01/02/21 at 3:04:05)
-                    Assert.True(now.Subtract(_timestampOne).TotalSeconds - Convert.ToDouble(lines[3].Substring(20), CultureInfo.InvariantCulture) < 10);
+                    Assert.StartsWith("2021-01-02 03:04:05", lines[3]);
                 }
             }
             finally
@@ -67,7 +65,7 @@ public async Task WritesDateTime()
         public async Task HandlesNullValuesAsync()
         {
             var path = Path.GetTempFileName() + "_";
-            var now = DateTime.Now;
+            var now = DateTime.UtcNow;
             var options = new W3CLoggerOptions()
             {
                 LoggingFields = W3CLoggingFields.UriQuery | W3CLoggingFields.Host | W3CLoggingFields.ProtocolStatus,

diff --git a/src/Middleware/HttpLogging/test/W3CLoggingMiddlewareTests.cs b/src/Middleware/HttpLogging/test/W3CLoggingMiddlewareTests.cs
@@ -107,7 +107,42 @@ public async Task DefaultDoesNotLogOptionalFields()
             Assert.True(now.Subtract(startDate).TotalSeconds < 10);
 
             Assert.Equal("#Fields: date time c-ip s-computername s-ip s-port cs-method cs-uri-stem cs-uri-query sc-status time-taken cs-version cs-host cs(User-Agent) cs(Referer)", lines[2]);
-            Assert.DoesNotContain(lines[2], "Snickerdoodle");
+            Assert.DoesNotContain(lines[3], "Snickerdoodle");
+        }
+
+        [Fact]
+        public async Task TimeTakenIsInMilliseconds()
+        {
+            var options = CreateOptionsAccessor();
+            options.CurrentValue.LoggingFields = W3CLoggingFields.TimeTaken;
+            var logger = new TestW3CLogger(options, new HostingEnvironment(), NullLoggerFactory.Instance);
+
+            var middleware = new W3CLoggingMiddleware(
+                c =>
+                {
+                    c.Response.StatusCode = 200;
+                    return Task.CompletedTask;
+                },
+                options,
+                logger);
+
+            var httpContext = new DefaultHttpContext();
+
+            var now = DateTime.Now;
+            await middleware.Invoke(httpContext);
+            await logger.Processor.WaitForWrites(4).DefaultTimeout();
+
+            var lines = logger.Processor.Lines;
+            Assert.Equal("#Version: 1.0", lines[0]);
+
+            Assert.StartsWith("#Start-Date: ", lines[1]);
+            var startDate = DateTime.Parse(lines[1].Substring(13), CultureInfo.InvariantCulture);
+            // Assert that the log was written in the last 10 seconds
+            Assert.True(now.Subtract(startDate).TotalSeconds < 10);
+
+            Assert.Equal("#Fields: time-taken", lines[2]);
+            double num;
+            Assert.True(Double.TryParse(lines[3], NumberStyles.Number, CultureInfo.InvariantCulture, out num));
         }
 
         private IOptionsMonitor<W3CLoggerOptions> CreateOptionsAccessor()