Skip to content

Betterize Hosting Log #10102

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
merged 4 commits into from
Aug 20, 2019
Merged

Betterize Hosting Log #10102

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
4 commits
Select commit Hold shift + click to select a range
811d53b
Betterize Hosting Log
benaadams Jun 30, 2019
3eddc18
Handle encoding
benaadams Jul 23, 2019
26032c1
Feedback
benaadams Jul 25, 2019
d5fa619
Encode space only as +
benaadams Aug 15, 2019
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
2 changes: 2 additions & 0 deletions src/Hosting/Hosting/src/Internal/HostingApplication.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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; }
Expand All @@ -125,6 +126,7 @@ public void Reset()

Scope = null;
Activity = null;
StartLog = null;

StartTimestamp = 0;
HasDiagnosticListener = false;
Expand Down
20 changes: 12 additions & 8 deletions src/Hosting/Hosting/src/Internal/HostingApplicationDiagnostics.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -78,7 +78,7 @@ public void BeginRequest(HttpContext httpContext, HostingApplication.Context con
}

// Non-inline
LogRequestStarting(httpContext);
LogRequestStarting(context);
}
}
context.StartTimestamp = startTimestamp;
Expand All @@ -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())
Expand Down Expand Up @@ -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);
}
Expand Down
49 changes: 27 additions & 22 deletions src/Hosting/Hosting/src/Internal/HostingRequestFinishedLog.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -9,51 +9,56 @@

namespace Microsoft.AspNetCore.Hosting
{
using static HostingRequestStartingLog;
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

More @pranavkm points 😄 I see this was introduced "way back" in C# 6, but I haven't seen this used much.


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 TimeSpan _elapsed;
private readonly HostingApplication.Context _context;

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:
return new KeyValuePair<string, object>("ElapsedMilliseconds", _elapsed.TotalMilliseconds);
case 1:
return new KeyValuePair<string, object>("StatusCode", _httpContext.Response.StatusCode);
case 2:
return new KeyValuePair<string, object>("ContentType", _httpContext.Response.ContentType);
default:
throw new IndexOutOfRangeException(nameof(index));
}
0 => new KeyValuePair<string, object>("ElapsedMilliseconds", Elapsed.TotalMilliseconds),
1 => new KeyValuePair<string, object>(nameof(response.StatusCode), response.StatusCode),
2 => new KeyValuePair<string, object>(nameof(response.ContentType), response.ContentType),
3 => new KeyValuePair<string, object>(nameof(response.ContentLength), response.ContentLength),
4 => new KeyValuePair<string, object>(nameof(request.Protocol), request.Protocol),
5 => new KeyValuePair<string, object>(nameof(request.Method), request.Method),
6 => new KeyValuePair<string, object>(nameof(request.Scheme), request.Scheme),
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;
_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;
Expand Down
68 changes: 28 additions & 40 deletions src/Hosting/Hosting/src/Internal/HostingRequestStartingLog.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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<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;
Expand All @@ -19,35 +23,19 @@ internal class HostingRequestStartingLog : IReadOnlyList<KeyValuePair<string, ob

public int Count => 9;

public KeyValuePair<string, object> this[int index]
public KeyValuePair<string, object> this[int index] => index switch
{
get
{
switch (index)
{
case 0:
return new KeyValuePair<string, object>("Protocol", _request.Protocol);
case 1:
return new KeyValuePair<string, object>("Method", _request.Method);
case 2:
return new KeyValuePair<string, object>("ContentType", _request.ContentType);
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));
}
}
}
0 => new KeyValuePair<string, object>(nameof(_request.Protocol), _request.Protocol),
1 => new KeyValuePair<string, object>(nameof(_request.Method), _request.Method),
2 => new KeyValuePair<string, object>(nameof(_request.ContentType), _request.ContentType),
3 => new KeyValuePair<string, object>(nameof(_request.ContentLength), _request.ContentLength),
4 => new KeyValuePair<string, object>(nameof(_request.Scheme), _request.Scheme),
5 => new KeyValuePair<string, object>(nameof(_request.Host), _request.Host.Value),
6 => new KeyValuePair<string, object>(nameof(_request.PathBase), _request.PathBase.Value),
7 => new KeyValuePair<string, object>(nameof(_request.Path), _request.Path.Value),
8 => new KeyValuePair<string, object>(nameof(_request.QueryString), _request.QueryString.Value),
_ => throw new IndexOutOfRangeException(nameof(index)),
};

public HostingRequestStartingLog(HttpContext httpContext)
{
Expand All @@ -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;
Expand All @@ -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>(T? potentialValue) where T : struct, IFormattable
=> potentialValue?.ToString(null, CultureInfo.InvariantCulture) ?? EmptyEntry;
}
}
2 changes: 1 addition & 1 deletion src/Servers/Kestrel/test/FunctionalTests/Http2/ShutdownTests.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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."));
}
Expand Down