Skip to content

Commit

Permalink
[HttpClientFactory] Do not log query string by default (#103769)
Browse files Browse the repository at this point in the history
Query strings may often contain sensitive information, we should avoid logging them by default.
  • Loading branch information
antonfirsov authored Jul 4, 2024
1 parent 4071a31 commit 64efe26
Show file tree
Hide file tree
Showing 6 changed files with 374 additions and 272 deletions.
193 changes: 193 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,193 @@
// 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.Runtime.CompilerServices;
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_disableUriRedaction = GetDisableUriRedactionSettingValue();

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");
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 GetDisableUriRedactionSettingValue()
{
if (AppContext.TryGetSwitch("System.Net.Http.DisableUriRedaction", out bool value))
{
return value;
}

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

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 GetRedactedUriString call unnecessarily
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, out string? formattedUri)
{
formattedUri = GetRedactedUriString(request.RequestUri);
return _beginRequestPipelineScope(logger, request.Method, formattedUri);
}

public static void LogRequestPipelineStart(this ILogger logger, HttpRequestMessage request, string? formattedUri, Func<string, bool> shouldRedactHeaderValue)
{
_requestPipelineStart(logger, request.Method, formattedUri, null);

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;
}

if (s_disableUriRedaction)
{
return uri.IsAbsoluteUri ? uri.AbsoluteUri : uri.ToString();
}

if (!uri.IsAbsoluteUri)
{
// We cannot guarantee the redaction of UserInfo for relative Uris without implementing some subset of Uri parsing in this package.
// To avoid this, we redact the whole Uri. Seeing a relative Uri in LoggingHttpMessageHandler or LoggingScopeHttpMessageHandler
// requires a custom handler chain with custom expansion logic implemented by the user's HttpMessageHandler.
// In such advanced scenarios we recommend users to log the Uri in their handler.
return "*";
}

string pathAndQuery = uri.PathAndQuery;
int queryIndex = pathAndQuery.IndexOf('?');

bool redactQuery = queryIndex >= 0 && // Query is present.
queryIndex < pathAndQuery.Length - 1; // Query is not empty.

return (redactQuery, uri.IsDefaultPort) switch
{
(true, true) => $"{uri.Scheme}://{uri.Host}{GetPath(pathAndQuery, queryIndex)}*",
(true, false) => $"{uri.Scheme}://{uri.Host}:{uri.Port}{GetPath(pathAndQuery, queryIndex)}*",
(false, true) => $"{uri.Scheme}://{uri.Host}{pathAndQuery}",
(false, false) => $"{uri.Scheme}://{uri.Host}:{uri.Port}{pathAndQuery}"
};

#if NET
[MethodImpl(MethodImplOptions.AggressiveInlining)]
static ReadOnlySpan<char> GetPath(string pathAndQuery, int queryIndex) => pathAndQuery.AsSpan(0, queryIndex + 1);
#else
[MethodImpl(MethodImplOptions.AggressiveInlining)]
static string GetPath(string pathAndQuery, int queryIndex) => pathAndQuery.Substring(0, queryIndex + 1);
#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, out string? formattedUri))
{
Log.RequestPipelineStart(_logger, request, shouldRedactHeaderValue);
_logger.LogRequestPipelineStart(request, formattedUri, 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

0 comments on commit 64efe26

Please sign in to comment.