From 9f8f64d645cc61aafa8a3656d763030c9355a7f4 Mon Sep 17 00:00:00 2001
From: "github-actions[bot]"
<41898282+github-actions[bot]@users.noreply.github.com>
Date: Thu, 2 Sep 2021 00:55:13 +0000
Subject: [PATCH] [release/6.0] Log time-taken more precisely (#36066)
* Log time-taken more precisely
* Log to other field
* Feedback
* Update src/Middleware/HttpLogging/src/W3CLoggingMiddleware.cs
Co-authored-by: Kahbazi <akahbazi@gmail.com>
* Fix test
* Feedback
Co-authored-by: Will Godbe <wigodbe@microsoft.com>
Co-authored-by: Kahbazi <akahbazi@gmail.com>
---
.../Microsoft.AspNetCore.HttpLogging.csproj | 1 +
src/Middleware/HttpLogging/src/W3CLogger.cs | 10 -----
.../HttpLogging/src/W3CLoggingMiddleware.cs | 7 ++++
.../HttpLogging/test/W3CLoggerTests.cs | 10 ++---
.../test/W3CLoggingMiddlewareTests.cs | 37 ++++++++++++++++++-
5 files changed, 48 insertions(+), 17 deletions(-)
diff --git a/src/Middleware/HttpLogging/src/Microsoft.AspNetCore.HttpLogging.csproj b/src/Middleware/HttpLogging/src/Microsoft.AspNetCore.HttpLogging.csproj
index 63a679810cc..7fc0102e131 100644
--- 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
index 0ee38ad3495..d9c6c96ef9e 100644
--- a/src/Middleware/HttpLogging/src/W3CLogger.cs
+++ b/src/Middleware/HttpLogging/src/W3CLogger.cs
@@ -48,16 +48,6 @@ namespace Microsoft.AspNetCore.HttpLogging
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
index 158759fba80..b9aff3aa483 100644
--- a/src/Middleware/HttpLogging/src/W3CLoggingMiddleware.cs
+++ b/src/Middleware/HttpLogging/src/W3CLoggingMiddleware.cs
@@ -11,6 +11,7 @@ using System.Text;
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 @@ namespace Microsoft.AspNetCore.HttpLogging
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 @@ namespace Microsoft.AspNetCore.HttpLogging
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
index cba4ed42bf3..759f6354ea8 100644
--- a/src/Middleware/HttpLogging/test/W3CLoggerTests.cs
+++ b/src/Middleware/HttpLogging/test/W3CLoggerTests.cs
@@ -28,7 +28,7 @@ namespace Microsoft.AspNetCore.HttpLogging
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 @@ namespace Microsoft.AspNetCore.HttpLogging
// 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 @@ namespace Microsoft.AspNetCore.HttpLogging
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
index 0928c70b7da..e1f1d0ab684 100644
--- a/src/Middleware/HttpLogging/test/W3CLoggingMiddlewareTests.cs
+++ b/src/Middleware/HttpLogging/test/W3CLoggingMiddlewareTests.cs
@@ -107,7 +107,42 @@ namespace Microsoft.AspNetCore.HttpLogging
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()
--
GitLab