diff --git a/src/Hosting/Hosting/src/Internal/HostingApplication.cs b/src/Hosting/Hosting/src/Internal/HostingApplication.cs index c64426c0dbc8..84363221ba38 100644 --- a/src/Hosting/Hosting/src/Internal/HostingApplication.cs +++ b/src/Hosting/Hosting/src/Internal/HostingApplication.cs @@ -114,6 +114,7 @@ internal class Context public HttpContext HttpContext { get; set; } public IDisposable Scope { get; set; } public Activity Activity { get; set; } + internal HostingRequestStartingLog StartLog { get; set; } public long StartTimestamp { get; set; } internal bool HasDiagnosticListener { get; set; } @@ -125,6 +126,7 @@ public void Reset() Scope = null; Activity = null; + StartLog = null; StartTimestamp = 0; HasDiagnosticListener = false; diff --git a/src/Hosting/Hosting/src/Internal/HostingApplicationDiagnostics.cs b/src/Hosting/Hosting/src/Internal/HostingApplicationDiagnostics.cs index 65730d67ff5d..385bcbf46d4c 100644 --- a/src/Hosting/Hosting/src/Internal/HostingApplicationDiagnostics.cs +++ b/src/Hosting/Hosting/src/Internal/HostingApplicationDiagnostics.cs @@ -78,7 +78,7 @@ public void BeginRequest(HttpContext httpContext, HostingApplication.Context con } // Non-inline - LogRequestStarting(httpContext); + LogRequestStarting(context); } } context.StartTimestamp = startTimestamp; @@ -97,7 +97,7 @@ public void RequestEnd(HttpContext httpContext, Exception exception, HostingAppl { currentTimestamp = Stopwatch.GetTimestamp(); // Non-inline - LogRequestFinished(httpContext, startTimestamp, currentTimestamp); + LogRequestFinished(context, startTimestamp, currentTimestamp); } if (_diagnosticListener.IsEnabled()) @@ -167,30 +167,34 @@ public void ContextDisposed(HostingApplication.Context context) } [MethodImpl(MethodImplOptions.NoInlining)] - private void LogRequestStarting(HttpContext httpContext) + private void LogRequestStarting(HostingApplication.Context context) { // IsEnabled is checked in the caller, so if we are here just log + var startLog = new HostingRequestStartingLog(context.HttpContext); + context.StartLog = startLog; + _logger.Log( logLevel: LogLevel.Information, eventId: LoggerEventIds.RequestStarting, - state: new HostingRequestStartingLog(httpContext), + state: startLog, exception: null, formatter: HostingRequestStartingLog.Callback); } [MethodImpl(MethodImplOptions.NoInlining)] - private void LogRequestFinished(HttpContext httpContext, long startTimestamp, long currentTimestamp) + private void LogRequestFinished(HostingApplication.Context context, long startTimestamp, long currentTimestamp) { // IsEnabled isn't checked in the caller, startTimestamp > 0 is used as a fast proxy check - // but that may be because diagnostics are enabled, which also uses startTimestamp, so check here - if (_logger.IsEnabled(LogLevel.Information)) + // but that may be because diagnostics are enabled, which also uses startTimestamp, + // so check if we logged the start event + if (context.StartLog != null) { var elapsed = new TimeSpan((long)(TimestampToTicks * (currentTimestamp - startTimestamp))); _logger.Log( logLevel: LogLevel.Information, eventId: LoggerEventIds.RequestFinished, - state: new HostingRequestFinishedLog(httpContext, elapsed), + state: new HostingRequestFinishedLog(context, elapsed), exception: null, formatter: HostingRequestFinishedLog.Callback); } diff --git a/src/Hosting/Hosting/src/Internal/HostingRequestFinishedLog.cs b/src/Hosting/Hosting/src/Internal/HostingRequestFinishedLog.cs index 63fd5f0921ea..09a132851d6b 100644 --- a/src/Hosting/Hosting/src/Internal/HostingRequestFinishedLog.cs +++ b/src/Hosting/Hosting/src/Internal/HostingRequestFinishedLog.cs @@ -9,51 +9,56 @@ namespace Microsoft.AspNetCore.Hosting { + using static HostingRequestStartingLog; + internal class HostingRequestFinishedLog : IReadOnlyList> { internal static readonly Func Callback = (state, exception) => ((HostingRequestFinishedLog)state).ToString(); - private readonly HttpContext _httpContext; - private readonly TimeSpan _elapsed; + private readonly HostingApplication.Context _context; private string _cachedToString; + public TimeSpan Elapsed { get; } - public int Count => 3; + public int Count => 11; public KeyValuePair this[int index] { get { - switch (index) + var request = _context.HttpContext.Request; + var response = _context.HttpContext.Response; + + return index switch { - case 0: - return new KeyValuePair("ElapsedMilliseconds", _elapsed.TotalMilliseconds); - case 1: - return new KeyValuePair("StatusCode", _httpContext.Response.StatusCode); - case 2: - return new KeyValuePair("ContentType", _httpContext.Response.ContentType); - default: - throw new IndexOutOfRangeException(nameof(index)); - } + 0 => new KeyValuePair("ElapsedMilliseconds", Elapsed.TotalMilliseconds), + 1 => new KeyValuePair(nameof(response.StatusCode), response.StatusCode), + 2 => new KeyValuePair(nameof(response.ContentType), response.ContentType), + 3 => new KeyValuePair(nameof(response.ContentLength), response.ContentLength), + 4 => new KeyValuePair(nameof(request.Protocol), request.Protocol), + 5 => new KeyValuePair(nameof(request.Method), request.Method), + 6 => new KeyValuePair(nameof(request.Scheme), request.Scheme), + 7 => new KeyValuePair(nameof(request.Host), request.Host.Value), + 8 => new KeyValuePair(nameof(request.PathBase), request.PathBase.Value), + 9 => new KeyValuePair(nameof(request.Path), request.Path.Value), + 10 => new KeyValuePair(nameof(request.QueryString), request.QueryString.Value), + _ => throw new IndexOutOfRangeException(nameof(index)), + }; } } - public HostingRequestFinishedLog(HttpContext httpContext, TimeSpan elapsed) + public HostingRequestFinishedLog(HostingApplication.Context context, TimeSpan elapsed) { - _httpContext = httpContext; - _elapsed = elapsed; + _context = context; + Elapsed = elapsed; } public override string ToString() { if (_cachedToString == null) { - _cachedToString = string.Format( - CultureInfo.InvariantCulture, - "Request finished in {0}ms {1} {2}", - _elapsed.TotalMilliseconds, - _httpContext.Response.StatusCode, - _httpContext.Response.ContentType); + var response = _context.HttpContext.Response; + _cachedToString = $"Request finished {_context.StartLog.ToStringWithoutPreamble()} - {response.StatusCode.ToString(CultureInfo.InvariantCulture)} {ValueOrEmptyMarker(response.ContentLength)} {EscapedValueOrEmptyMarker(response.ContentType)} {Elapsed.TotalMilliseconds.ToString("0.0000", CultureInfo.InvariantCulture)}ms"; } return _cachedToString; diff --git a/src/Hosting/Hosting/src/Internal/HostingRequestStartingLog.cs b/src/Hosting/Hosting/src/Internal/HostingRequestStartingLog.cs index 279fa06aed04..3a7586b1c90b 100644 --- a/src/Hosting/Hosting/src/Internal/HostingRequestStartingLog.cs +++ b/src/Hosting/Hosting/src/Internal/HostingRequestStartingLog.cs @@ -5,12 +5,16 @@ using System.Collections; using System.Collections.Generic; using System.Globalization; +using System.Net; using Microsoft.AspNetCore.Http; namespace Microsoft.AspNetCore.Hosting { internal class HostingRequestStartingLog : IReadOnlyList> { + private const string LogPreamble = "Request starting "; + private const string EmptyEntry = "-"; + internal static readonly Func Callback = (state, exception) => ((HostingRequestStartingLog)state).ToString(); private readonly HttpRequest _request; @@ -19,35 +23,19 @@ internal class HostingRequestStartingLog : IReadOnlyList 9; - public KeyValuePair this[int index] + public KeyValuePair this[int index] => index switch { - get - { - switch (index) - { - case 0: - return new KeyValuePair("Protocol", _request.Protocol); - case 1: - return new KeyValuePair("Method", _request.Method); - case 2: - return new KeyValuePair("ContentType", _request.ContentType); - case 3: - return new KeyValuePair("ContentLength", _request.ContentLength); - case 4: - return new KeyValuePair("Scheme", _request.Scheme); - case 5: - return new KeyValuePair("Host", _request.Host.ToString()); - case 6: - return new KeyValuePair("PathBase", _request.PathBase.ToString()); - case 7: - return new KeyValuePair("Path", _request.Path.ToString()); - case 8: - return new KeyValuePair("QueryString", _request.QueryString.ToString()); - default: - throw new IndexOutOfRangeException(nameof(index)); - } - } - } + 0 => new KeyValuePair(nameof(_request.Protocol), _request.Protocol), + 1 => new KeyValuePair(nameof(_request.Method), _request.Method), + 2 => new KeyValuePair(nameof(_request.ContentType), _request.ContentType), + 3 => new KeyValuePair(nameof(_request.ContentLength), _request.ContentLength), + 4 => new KeyValuePair(nameof(_request.Scheme), _request.Scheme), + 5 => new KeyValuePair(nameof(_request.Host), _request.Host.Value), + 6 => new KeyValuePair(nameof(_request.PathBase), _request.PathBase.Value), + 7 => new KeyValuePair(nameof(_request.Path), _request.Path.Value), + 8 => new KeyValuePair(nameof(_request.QueryString), _request.QueryString.Value), + _ => throw new IndexOutOfRangeException(nameof(index)), + }; public HostingRequestStartingLog(HttpContext httpContext) { @@ -58,18 +46,8 @@ public override string ToString() { if (_cachedToString == null) { - _cachedToString = string.Format( - CultureInfo.InvariantCulture, - "Request starting {0} {1} {2}://{3}{4}{5}{6} {7} {8}", - _request.Protocol, - _request.Method, - _request.Scheme, - _request.Host.Value, - _request.PathBase.Value, - _request.Path.Value, - _request.QueryString.Value, - _request.ContentType, - _request.ContentLength); + var request = _request; + _cachedToString = $"{LogPreamble}{request.Protocol} {request.Method} {request.Scheme}://{request.Host.Value}{request.PathBase.Value}{request.Path.Value}{request.QueryString.Value} {EscapedValueOrEmptyMarker(request.ContentType)} {ValueOrEmptyMarker(request.ContentLength)}"; ; } return _cachedToString; @@ -87,5 +65,15 @@ IEnumerator IEnumerable.GetEnumerator() { return GetEnumerator(); } + + internal string ToStringWithoutPreamble() + => ToString().Substring(LogPreamble.Length); + + internal static string EscapedValueOrEmptyMarker(string potentialValue) + // Encode space as + + => potentialValue?.Length > 0 ? potentialValue.Replace(' ', '+') : EmptyEntry; + + internal static string ValueOrEmptyMarker(T? potentialValue) where T : struct, IFormattable + => potentialValue?.ToString(null, CultureInfo.InvariantCulture) ?? EmptyEntry; } } diff --git a/src/Servers/Kestrel/test/FunctionalTests/Http2/ShutdownTests.cs b/src/Servers/Kestrel/test/FunctionalTests/Http2/ShutdownTests.cs index 03f7bb9f43fc..e521d2133b44 100644 --- a/src/Servers/Kestrel/test/FunctionalTests/Http2/ShutdownTests.cs +++ b/src/Servers/Kestrel/test/FunctionalTests/Http2/ShutdownTests.cs @@ -96,7 +96,7 @@ public async Task GracefulShutdownWaitsForRequestsToFinish() await stopTask.DefaultTimeout(); } - Assert.Contains(TestApplicationErrorLogger.Messages, m => m.Message.Contains("Request finished in")); + Assert.Contains(TestApplicationErrorLogger.Messages, m => m.Message.Contains("Request finished ")); Assert.Contains(TestApplicationErrorLogger.Messages, m => m.Message.Contains("is closing.")); Assert.Contains(TestApplicationErrorLogger.Messages, m => m.Message.Contains("is closed. The last processed stream ID was 1.")); }