Skip to content
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.

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

[HttpClientFactory] Do not log query string by default #103769

Merged
merged 21 commits into from
Jul 4, 2024
Merged
Show file tree
Hide file tree
Changes from 15 commits
Commits
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
197 changes: 197 additions & 0 deletions src/libraries/Microsoft.Extensions.Http/src/Logging/LogHelper.cs
Original file line number Diff line number Diff line change
@@ -0,0 +1,197 @@
// Licensed to the .NET Foundation under one or more agreements.
// The .NET Foundation licenses this file to you under the MIT license.

using System;
using System.Diagnostics;
using System.Net.Http;
using System.Threading;
using System.Threading.Tasks;
using Microsoft.Extensions.Internal;
using Microsoft.Extensions.Logging;

namespace Microsoft.Extensions.Http.Logging
{
internal static class LogHelper
{
private static readonly LogDefineOptions s_skipEnabledCheckLogDefineOptions = new LogDefineOptions() { SkipEnabledCheck = true };
private static readonly bool s_disableUriQueryRedaction = GetDisableUriQueryRedactionSettingValue();

private static class EventIds
{
public static readonly EventId RequestStart = new EventId(100, "RequestStart");
public static readonly EventId RequestEnd = new EventId(101, "RequestEnd");

public static readonly EventId RequestHeader = new EventId(102, "RequestHeader");
public static readonly EventId ResponseHeader = new EventId(103, "ResponseHeader");

public static readonly EventId PipelineStart = new EventId(100, "RequestPipelineStart");
public static readonly EventId PipelineEnd = new EventId(101, "RequestPipelineEnd");

public static readonly EventId RequestPipelineRequestHeader = new EventId(102, "RequestPipelineRequestHeader");
antonfirsov marked this conversation as resolved.
Show resolved Hide resolved
public static readonly EventId RequestPipelineResponseHeader = new EventId(103, "RequestPipelineResponseHeader");
}

private static readonly Action<ILogger, HttpMethod, string?, Exception?> _requestStart = LoggerMessage.Define<HttpMethod, string?>(
LogLevel.Information,
EventIds.RequestStart,
"Sending HTTP request {HttpMethod} {Uri}",
s_skipEnabledCheckLogDefineOptions);

private static readonly Action<ILogger, double, int, Exception?> _requestEnd = LoggerMessage.Define<double, int>(
LogLevel.Information,
EventIds.RequestEnd,
"Received HTTP response headers after {ElapsedMilliseconds}ms - {StatusCode}");

private static readonly Func<ILogger, HttpMethod, string?, IDisposable?> _beginRequestPipelineScope = LoggerMessage.DefineScope<HttpMethod, string?>("HTTP {HttpMethod} {Uri}");

private static readonly Action<ILogger, HttpMethod, string?, Exception?> _requestPipelineStart = LoggerMessage.Define<HttpMethod, string?>(
LogLevel.Information,
EventIds.PipelineStart,
"Start processing HTTP request {HttpMethod} {Uri}");

private static readonly Action<ILogger, double, int, Exception?> _requestPipelineEnd = LoggerMessage.Define<double, int>(
LogLevel.Information,
EventIds.PipelineEnd,
"End processing HTTP request after {ElapsedMilliseconds}ms - {StatusCode}");

private static bool GetDisableUriQueryRedactionSettingValue()
{
if (AppContext.TryGetSwitch("Microsoft.Extensions.Http.DisableUriQueryRedaction", out bool value))
{
return value;
}

string? envVar = Environment.GetEnvironmentVariable("DOTNET_MICROSOFT_EXTENSIONS_HTTP_DISABLEURIQUERYREDACTION");

if (bool.TryParse(envVar, out value))
{
return value;
}
else if (uint.TryParse(envVar, out uint intVal))
{
return intVal != 0;
}

return false;
}

public static void LogRequestStart(this ILogger logger, HttpRequestMessage request, Func<string, bool> shouldRedactHeaderValue)
{
// We check here to avoid allocating in the GetUriString call unnecessarily
antonfirsov marked this conversation as resolved.
Show resolved Hide resolved
if (logger.IsEnabled(LogLevel.Information))
{
_requestStart(logger, request.Method, GetRedactedUriString(request.RequestUri), null);
}

if (logger.IsEnabled(LogLevel.Trace))
{
logger.Log(
LogLevel.Trace,
EventIds.RequestHeader,
new HttpHeadersLogValue(HttpHeadersLogValue.Kind.Request, request.Headers, request.Content?.Headers, shouldRedactHeaderValue),
null,
(state, ex) => state.ToString());
}
}

public static void LogRequestEnd(this ILogger logger, HttpResponseMessage response, TimeSpan duration, Func<string, bool> shouldRedactHeaderValue)
{
_requestEnd(logger, duration.TotalMilliseconds, (int)response.StatusCode, null);

if (logger.IsEnabled(LogLevel.Trace))
{
logger.Log(
LogLevel.Trace,
EventIds.ResponseHeader,
new HttpHeadersLogValue(HttpHeadersLogValue.Kind.Response, response.Headers, response.Content?.Headers, shouldRedactHeaderValue),
null,
(state, ex) => state.ToString());
}
}

public static IDisposable? BeginRequestPipelineScope(this ILogger logger, HttpRequestMessage request)
{
return _beginRequestPipelineScope(logger, request.Method, GetRedactedUriString(request.RequestUri));
}

public static void LogRequestPipelineStart(this ILogger logger, HttpRequestMessage request, Func<string, bool> shouldRedactHeaderValue)
{
_requestPipelineStart(logger, request.Method, GetRedactedUriString(request.RequestUri), null);
MihaZupan marked this conversation as resolved.
Show resolved Hide resolved

if (logger.IsEnabled(LogLevel.Trace))
{
logger.Log(
LogLevel.Trace,
EventIds.RequestPipelineRequestHeader,
new HttpHeadersLogValue(HttpHeadersLogValue.Kind.Request, request.Headers, request.Content?.Headers, shouldRedactHeaderValue),
null,
(state, ex) => state.ToString());
}
}

public static void LogRequestPipelineEnd(this ILogger logger, HttpResponseMessage response, TimeSpan duration, Func<string, bool> shouldRedactHeaderValue)
{
_requestPipelineEnd(logger, duration.TotalMilliseconds, (int)response.StatusCode, null);

if (logger.IsEnabled(LogLevel.Trace))
{
logger.Log(
LogLevel.Trace,
EventIds.RequestPipelineResponseHeader,
new HttpHeadersLogValue(HttpHeadersLogValue.Kind.Response, response.Headers, response.Content?.Headers, shouldRedactHeaderValue),
null,
(state, ex) => state.ToString());
}
}

internal static string? GetRedactedUriString(Uri? uri)
{
if (uri is null)
{
return null;
}

string uriString = uri.IsAbsoluteUri
? uri.GetComponents(UriComponents.AbsoluteUri & ~UriComponents.UserInfo, UriFormat.UriEscaped)
: uri.ToString();
antonfirsov marked this conversation as resolved.
Show resolved Hide resolved

if (s_disableUriQueryRedaction)
{
return uriString;
}

int fragmentOffset = uriString.IndexOf('#');
int queryOffset = uriString.IndexOf('?');
if (fragmentOffset >= 0 && queryOffset > fragmentOffset)
{
// Not a query delimiter, but a '?' in the fragment.
queryOffset = -1;
}

if (queryOffset < 0 || queryOffset == uriString.Length - 1 || queryOffset == fragmentOffset - 1)
{
// No query or empty query.
return uriString;
}

if (fragmentOffset < 0)
{
#if NET
return $"{uriString.AsSpan(0, queryOffset + 1)}*";
#else
return $"{uriString.Substring(0, queryOffset + 1)}*";
#endif
}
else
{
#if NET
ReadOnlySpan<char> uriSpan = uriString.AsSpan();
return $"{uriSpan[..(queryOffset + 1)]}*{uriSpan[fragmentOffset..]}";
#else
return $"{uriString.Substring(0, queryOffset + 1)}*{uriString.Substring(fragmentOffset)}";
#endif
}

}
}
}
Original file line number Diff line number Diff line change
Expand Up @@ -2,6 +2,7 @@
// The .NET Foundation licenses this file to you under the MIT license.

using System;
using System.Diagnostics;
using System.Net.Http;
using System.Threading;
using System.Threading.Tasks;
Expand Down Expand Up @@ -58,7 +59,7 @@ async Task<HttpResponseMessage> Core(HttpRequestMessage request, bool useAsync,

// Not using a scope here because we always expect this to be at the end of the pipeline, thus there's
// not really anything to surround.
Log.RequestStart(_logger, request, shouldRedactHeaderValue);
_logger.LogRequestStart(request, shouldRedactHeaderValue);
var stopwatch = ValueStopwatch.StartNew();
HttpResponseMessage response = useAsync
? await base.SendAsync(request, cancellationToken).ConfigureAwait(false)
Expand All @@ -67,7 +68,7 @@ async Task<HttpResponseMessage> Core(HttpRequestMessage request, bool useAsync,
#else
: throw new NotImplementedException("Unreachable code");
#endif
Log.RequestEnd(_logger, response, stopwatch.GetElapsedTime(), shouldRedactHeaderValue);
_logger.LogRequestEnd(response, stopwatch.GetElapsedTime(), shouldRedactHeaderValue);

return response;
}
Expand All @@ -84,72 +85,5 @@ protected override Task<HttpResponseMessage> SendAsync(HttpRequestMessage reques
protected override HttpResponseMessage Send(HttpRequestMessage request, CancellationToken cancellationToken)
=> SendCoreAsync(request, useAsync: false, cancellationToken).GetAwaiter().GetResult();
#endif

// Used in tests.
internal static class Log
{
public static class EventIds
{
public static readonly EventId RequestStart = new EventId(100, "RequestStart");
public static readonly EventId RequestEnd = new EventId(101, "RequestEnd");

public static readonly EventId RequestHeader = new EventId(102, "RequestHeader");
public static readonly EventId ResponseHeader = new EventId(103, "ResponseHeader");
}

private static readonly LogDefineOptions _skipEnabledCheckLogDefineOptions = new LogDefineOptions() { SkipEnabledCheck = true };

private static readonly Action<ILogger, HttpMethod, string?, Exception?> _requestStart = LoggerMessage.Define<HttpMethod, string?>(
LogLevel.Information,
EventIds.RequestStart,
"Sending HTTP request {HttpMethod} {Uri}",
_skipEnabledCheckLogDefineOptions);

private static readonly Action<ILogger, double, int, Exception?> _requestEnd = LoggerMessage.Define<double, int>(
LogLevel.Information,
EventIds.RequestEnd,
"Received HTTP response headers after {ElapsedMilliseconds}ms - {StatusCode}");

public static void RequestStart(ILogger logger, HttpRequestMessage request, Func<string, bool> shouldRedactHeaderValue)
{
// We check here to avoid allocating in the GetUriString call unnecessarily
if (logger.IsEnabled(LogLevel.Information))
{
_requestStart(logger, request.Method, GetUriString(request.RequestUri), null);
}

if (logger.IsEnabled(LogLevel.Trace))
{
logger.Log(
LogLevel.Trace,
EventIds.RequestHeader,
new HttpHeadersLogValue(HttpHeadersLogValue.Kind.Request, request.Headers, request.Content?.Headers, shouldRedactHeaderValue),
null,
(state, ex) => state.ToString());
}
}

public static void RequestEnd(ILogger logger, HttpResponseMessage response, TimeSpan duration, Func<string, bool> shouldRedactHeaderValue)
{
_requestEnd(logger, duration.TotalMilliseconds, (int)response.StatusCode, null);

if (logger.IsEnabled(LogLevel.Trace))
{
logger.Log(
LogLevel.Trace,
EventIds.ResponseHeader,
new HttpHeadersLogValue(HttpHeadersLogValue.Kind.Response, response.Headers, response.Content?.Headers, shouldRedactHeaderValue),
null,
(state, ex) => state.ToString());
}
}

private static string? GetUriString(Uri? requestUri)
{
return requestUri?.IsAbsoluteUri == true
? requestUri.AbsoluteUri
: requestUri?.ToString();
}
}
}
}
Original file line number Diff line number Diff line change
Expand Up @@ -58,17 +58,17 @@ async Task<HttpResponseMessage> Core(HttpRequestMessage request, bool useAsync,

Func<string, bool> shouldRedactHeaderValue = _options?.ShouldRedactHeaderValue ?? _shouldNotRedactHeaderValue;

using (Log.BeginRequestPipelineScope(_logger, request))
using (_logger.BeginRequestPipelineScope(request))
{
Log.RequestPipelineStart(_logger, request, shouldRedactHeaderValue);
_logger.LogRequestPipelineStart(request, shouldRedactHeaderValue);
HttpResponseMessage response = useAsync
? await base.SendAsync(request, cancellationToken).ConfigureAwait(false)
#if NET
: base.Send(request, cancellationToken);
#else
: throw new NotImplementedException("Unreachable code");
#endif
Log.RequestPipelineEnd(_logger, response, stopwatch.GetElapsedTime(), shouldRedactHeaderValue);
_logger.LogRequestPipelineEnd(response, stopwatch.GetElapsedTime(), shouldRedactHeaderValue);

return response;
}
Expand All @@ -86,72 +86,5 @@ protected override Task<HttpResponseMessage> SendAsync(HttpRequestMessage reques
protected override HttpResponseMessage Send(HttpRequestMessage request, CancellationToken cancellationToken)
=> SendCoreAsync(request, useAsync: false, cancellationToken).GetAwaiter().GetResult();
#endif

// Used in tests
internal static class Log
{
public static class EventIds
{
public static readonly EventId PipelineStart = new EventId(100, "RequestPipelineStart");
public static readonly EventId PipelineEnd = new EventId(101, "RequestPipelineEnd");

public static readonly EventId RequestHeader = new EventId(102, "RequestPipelineRequestHeader");
public static readonly EventId ResponseHeader = new EventId(103, "RequestPipelineResponseHeader");
}

private static readonly Func<ILogger, HttpMethod, string?, IDisposable?> _beginRequestPipelineScope = LoggerMessage.DefineScope<HttpMethod, string?>("HTTP {HttpMethod} {Uri}");

private static readonly Action<ILogger, HttpMethod, string?, Exception?> _requestPipelineStart = LoggerMessage.Define<HttpMethod, string?>(
LogLevel.Information,
EventIds.PipelineStart,
"Start processing HTTP request {HttpMethod} {Uri}");

private static readonly Action<ILogger, double, int, Exception?> _requestPipelineEnd = LoggerMessage.Define<double, int>(
LogLevel.Information,
EventIds.PipelineEnd,
"End processing HTTP request after {ElapsedMilliseconds}ms - {StatusCode}");

public static IDisposable? BeginRequestPipelineScope(ILogger logger, HttpRequestMessage request)
{
return _beginRequestPipelineScope(logger, request.Method, GetUriString(request.RequestUri));
}

public static void RequestPipelineStart(ILogger logger, HttpRequestMessage request, Func<string, bool> shouldRedactHeaderValue)
{
_requestPipelineStart(logger, request.Method, GetUriString(request.RequestUri), null);

if (logger.IsEnabled(LogLevel.Trace))
{
logger.Log(
LogLevel.Trace,
EventIds.RequestHeader,
new HttpHeadersLogValue(HttpHeadersLogValue.Kind.Request, request.Headers, request.Content?.Headers, shouldRedactHeaderValue),
null,
(state, ex) => state.ToString());
}
}

public static void RequestPipelineEnd(ILogger logger, HttpResponseMessage response, TimeSpan duration, Func<string, bool> shouldRedactHeaderValue)
{
_requestPipelineEnd(logger, duration.TotalMilliseconds, (int)response.StatusCode, null);

if (logger.IsEnabled(LogLevel.Trace))
{
logger.Log(
LogLevel.Trace,
EventIds.ResponseHeader,
new HttpHeadersLogValue(HttpHeadersLogValue.Kind.Response, response.Headers, response.Content?.Headers, shouldRedactHeaderValue),
null,
(state, ex) => state.ToString());
}
}

private static string? GetUriString(Uri? requestUri)
{
return requestUri?.IsAbsoluteUri == true
? requestUri.AbsoluteUri
: requestUri?.ToString();
}
}
}
}
Loading