Betterize Hosting Log (#10102)

* Handle encoding
* Encode space only as +

src/Hosting/Hosting/src/Internal/HostingApplication.cs

@@ -114,6 +114,7 @@ namespace Microsoft.AspNetCore.Hosting
             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 @@ namespace Microsoft.AspNetCore.Hosting
 
                 Scope = null;
                 Activity = null;
+                StartLog = null;
 
                 StartTimestamp = 0;
                 HasDiagnosticListener = false;

src/Hosting/Hosting/src/Internal/HostingApplicationDiagnostics.cs

@@ -78,7 +78,7 @@ namespace Microsoft.AspNetCore.Hosting
                     }
 
                     // Non-inline
-                    LogRequestStarting(httpContext);
+                    LogRequestStarting(context);
                 }
             }
             context.StartTimestamp = startTimestamp;
@@ -97,7 +97,7 @@ namespace Microsoft.AspNetCore.Hosting
             {
                 currentTimestamp = Stopwatch.GetTimestamp();
                 // Non-inline
-                LogRequestFinished(httpContext, startTimestamp, currentTimestamp);
+                LogRequestFinished(context, startTimestamp, currentTimestamp);
             }
 
             if (_diagnosticListener.IsEnabled())
@@ -167,30 +167,34 @@ namespace Microsoft.AspNetCore.Hosting
         }
 
         [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
+            // but that may be because diagnostics are enabled, which also uses startTimestamp,
-            if (_logger.IsEnabled(LogLevel.Information))
+            // 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);
             }

src/Hosting/Hosting/src/Internal/HostingRequestFinishedLog.cs

@@ -9,51 +9,56 @@ using Microsoft.AspNetCore.Http;
 
 namespace Microsoft.AspNetCore.Hosting
 {
+    using static HostingRequestStartingLog;
+
     internal class HostingRequestFinishedLog : IReadOnlyList<KeyValuePair<string, object>>
     {
         internal static readonly Func<object, Exception, string> Callback = (state, exception) => ((HostingRequestFinishedLog)state).ToString();
 
-        private readonly HttpContext _httpContext;
+        private readonly HostingApplication.Context _context;
-        private readonly TimeSpan _elapsed;
 
         private string _cachedToString;
+        public TimeSpan Elapsed { get; }
 
-        public int Count => 3;
+        public int Count => 11;
 
         public KeyValuePair<string, object> this[int index]
         {
             get
             {
-                switch (index)
+                var request = _context.HttpContext.Request;
+                var response = _context.HttpContext.Response;
+
+                return index switch
                 {
-                    case 0:
+                    0 => new KeyValuePair<string, object>("ElapsedMilliseconds", Elapsed.TotalMilliseconds),
-                        return new KeyValuePair<string, object>("ElapsedMilliseconds", _elapsed.TotalMilliseconds);
+                    1 => new KeyValuePair<string, object>(nameof(response.StatusCode), response.StatusCode),
-                    case 1:
+                    2 => new KeyValuePair<string, object>(nameof(response.ContentType), response.ContentType),
-                        return new KeyValuePair<string, object>("StatusCode", _httpContext.Response.StatusCode);
+                    3 => new KeyValuePair<string, object>(nameof(response.ContentLength), response.ContentLength),
-                    case 2:
+                    4 => new KeyValuePair<string, object>(nameof(request.Protocol), request.Protocol),
-                        return new KeyValuePair<string, object>("ContentType", _httpContext.Response.ContentType);
+                    5 => new KeyValuePair<string, object>(nameof(request.Method), request.Method),
-                    default:
+                    6 => new KeyValuePair<string, object>(nameof(request.Scheme), request.Scheme),
-                        throw new IndexOutOfRangeException(nameof(index));
+                    7 => new KeyValuePair<string, object>(nameof(request.Host), request.Host.Value),
-                }
+                    8 => new KeyValuePair<string, object>(nameof(request.PathBase), request.PathBase.Value),
+                    9 => new KeyValuePair<string, object>(nameof(request.Path), request.Path.Value),
+                    10 => new KeyValuePair<string, object>(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;
+            _context = context;
-            _elapsed = elapsed;
+            Elapsed = elapsed;
         }
 
         public override string ToString()
         {
             if (_cachedToString == null)
             {
-                _cachedToString = string.Format(
+                var response = _context.HttpContext.Response;
-                    CultureInfo.InvariantCulture,
+                _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";
-                    "Request finished in {0}ms {1} {2}",
-                    _elapsed.TotalMilliseconds,
-                    _httpContext.Response.StatusCode,
-                    _httpContext.Response.ContentType);
             }
 
             return _cachedToString;

src/Hosting/Hosting/src/Internal/HostingRequestStartingLog.cs

@@ -5,12 +5,16 @@ using System;
 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<KeyValuePair<string, object>>
     {
+        private const string LogPreamble = "Request starting ";
+        private const string EmptyEntry = "-";
+
         internal static readonly Func<object, Exception, string> Callback = (state, exception) => ((HostingRequestStartingLog)state).ToString();
 
         private readonly HttpRequest _request;
@@ -19,35 +23,19 @@ namespace Microsoft.AspNetCore.Hosting
 
         public int Count => 9;
 
-        public KeyValuePair<string, object> this[int index]
+        public KeyValuePair<string, object> this[int index] => index switch
         {
-            get
+            0 => new KeyValuePair<string, object>(nameof(_request.Protocol), _request.Protocol),
-            {
+            1 => new KeyValuePair<string, object>(nameof(_request.Method), _request.Method),
-                switch (index)
+            2 => new KeyValuePair<string, object>(nameof(_request.ContentType), _request.ContentType),
-                {
+            3 => new KeyValuePair<string, object>(nameof(_request.ContentLength), _request.ContentLength),
-                    case 0:
+            4 => new KeyValuePair<string, object>(nameof(_request.Scheme), _request.Scheme),
-                        return new KeyValuePair<string, object>("Protocol", _request.Protocol);
+            5 => new KeyValuePair<string, object>(nameof(_request.Host), _request.Host.Value),
-                    case 1:
+            6 => new KeyValuePair<string, object>(nameof(_request.PathBase), _request.PathBase.Value),
-                        return new KeyValuePair<string, object>("Method", _request.Method);
+            7 => new KeyValuePair<string, object>(nameof(_request.Path), _request.Path.Value),
-                    case 2:
+            8 => new KeyValuePair<string, object>(nameof(_request.QueryString), _request.QueryString.Value),
-                        return new KeyValuePair<string, object>("ContentType", _request.ContentType);
+            _ => throw new IndexOutOfRangeException(nameof(index)),
-                    case 3:
+        };
-                        return new KeyValuePair<string, object>("ContentLength", _request.ContentLength);
-                    case 4:
-                        return new KeyValuePair<string, object>("Scheme", _request.Scheme);
-                    case 5:
-                        return new KeyValuePair<string, object>("Host", _request.Host.ToString());
-                    case 6:
-                        return new KeyValuePair<string, object>("PathBase", _request.PathBase.ToString());
-                    case 7:
-                        return new KeyValuePair<string, object>("Path", _request.Path.ToString());
-                    case 8:
-                        return new KeyValuePair<string, object>("QueryString", _request.QueryString.ToString());
-                    default:
-                        throw new IndexOutOfRangeException(nameof(index));
-                }
-            }
-        }
 
         public HostingRequestStartingLog(HttpContext httpContext)
         {
@@ -58,18 +46,8 @@ namespace Microsoft.AspNetCore.Hosting
         {
             if (_cachedToString == null)
             {
-                _cachedToString = string.Format(
+                var request = _request;
-                    CultureInfo.InvariantCulture,
+                _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)}"; ;
-                    "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);
             }
 
             return _cachedToString;
@@ -87,5 +65,15 @@ namespace Microsoft.AspNetCore.Hosting
         {
             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>(T? potentialValue) where T : struct, IFormattable
+            => potentialValue?.ToString(null, CultureInfo.InvariantCulture) ?? EmptyEntry;
     }
 }

src/Servers/Kestrel/test/FunctionalTests/Http2/ShutdownTests.cs

@@ -96,7 +96,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel.FunctionalTests.Http2
                 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."));
         }