HttpClientFactory in ASP.NET Core 2.1 Part 5: 日志

HttpClientFactory in ASP.NET Core 2.1 Part 5: 日志

原文地址：https://www.stevejgordon.co.uk/httpclientfactory-asp-net-core-logging

在 2.1 版本的 IHttpClientFactory 发布中，ASP.NET 团队包括了对由工厂创建的 HttpClient 对象的内建的对 Http 调用的日志。它对诊断失效很有用，以及了解完成对外部服务的 Http 调用所花费的时间有帮助。

本文中，我将探索默认可用的日志，如何控制记录的内容，日志是如何实现的，最后，如果在我们的实现中替换日志。

本文完全是技术细节。我希望它证明 IHttpClientFactory 有用和有趣的工作。点击这里，如果你希望跳到通过替换默认日志实现来进行定制。

什么是日志？

IHttpClientFactory 包含两个级别的日志，在 Information 级别，花费的处理和发送请求的时间被包括。在监控外部请求的缓慢响应时非常有用，例如，这里是在 Information 级别启用的时候，在控制台中的输出。

info: System.Net.Http.HttpClient.MyClient.LogicalHandler[100]
  Start processing HTTP request GET https://api.github.com/repos/aspnet/docs/branches

info: System.Net.Http.HttpClient.MyClient.ClientHandler[100]
  Sending HTTP request GET https://api.github.com/repos/aspnet/docs/branches

info: System.Net.Http.HttpClient.MyClient.ClientHandler[101]
  Received HTTP response after 682.9818ms - OK

info: System.Net.Http.HttpClient.MyClient.LogicalHandler[101]
  End processing HTTP request after 693.1094ms - OK

如果你需要更详细的日志，可以使用 Trace 级别的日志。随着 Trace 级别的日志启用。关于请求和响应头的详细内容将被包含到日志信息中，这里是 Trace 级别日志启用后的日志示例。

info: System.Net.Http.HttpClient.MyClient.LogicalHandler[100]
 Start processing HTTP request GET https://api.github.com/repos/aspnet/docs/branches

trce: System.Net.Http.HttpClient.MyClient.LogicalHandler[102]
  Request Headers:
  Accept: application/vnd.github.v3+json
  User-Agent: HttpClientFactory-Sample

info: System.Net.Http.HttpClient.MyClient.ClientHandler[100]
  Sending HTTP request GET https://api.github.com/repos/aspnet/docs/branches

trce: System.Net.Http.HttpClient.MyClient.ClientHandler[102]
  Request Headers:
  Accept: application/vnd.github.v3+json
  User-Agent: HttpClientFactory-Sample

info: System.Net.Http.HttpClient.MyClient.ClientHandler[101]
  Received HTTP response after 795.6954ms - OK

trce: System.Net.Http.HttpClient.MyClient.ClientHandler[103]
  Response Headers:
  Server: GitHub.com
  Date: Sun, 08 Jul 2018 09:44:09 GMT
  Status: 200 OK
  X-RateLimit-Limit: 60
  X-RateLimit-Remaining: 58
  X-RateLimit-Reset: 1531046594
  Cache-Control: public, max-age=60, s-maxage=60
  Vary: Accept
  ETag: "f0452653b55e5fef139a58372e3a7bf3"
  X-GitHub-Media-Type: github.v3; format=json
  Access-Control-Expose-Headers: ETag, Link, Retry-After, X-GitHub-OTP, X-RateLimit-Limit, X-RateLimit-Remaining, X-RateLimit-Reset, X-OAuth-Scopes, X-Accepted-OAuth-Scopes, X-Poll-Interval
  Access-Control-Allow-Origin: *
  Strict-Transport-Security: max-age=31536000; includeSubdomains; preload
  X-Frame-Options: deny
  X-Content-Type-Options: nosniff
  X-XSS-Protection: 1; mode=block
  Referrer-Policy: origin-when-cross-origin, strict-origin-when-cross-origin
  Content-Security-Policy: default-src 'none'
  X-Runtime-rack: 0.029792
  X-GitHub-Request-Id: DCD6:3C9D:688D222:D064A9D:5B41DCE9
  Content-Type: application/json; charset=utf-8
  Content-Length: 2642

info: System.Net.Http.HttpClient.MyClient.LogicalHandler[101]
  End processing HTTP request after 818.4525ms - OK

trce: System.Net.Http.HttpClient.MyClient.LogicalHandler[103]
  Response Headers:
  Server: GitHub.com
  Date: Sun, 08 Jul 2018 09:44:09 GMT
  Status: 200 OK
  X-RateLimit-Limit: 60
  X-RateLimit-Remaining: 58
  X-RateLimit-Reset: 1531046594
  Cache-Control: public, max-age=60, s-maxage=60
  Vary: Accept
  ETag: "f0452653b55e5fef139a58372e3a7bf3"
  X-GitHub-Media-Type: github.v3; format=json
  Access-Control-Expose-Headers: ETag, Link, Retry-After, X-GitHub-OTP, X-RateLimit-Limit, X-RateLimit-Remaining, X-RateLimit-Reset, X-OAuth-Scopes, X-Accepted-OAuth-Scopes, X-Poll-Interval
  Access-Control-Allow-Origin: *
  Strict-Transport-Security: max-age=31536000; includeSubdomains; preload
  X-Frame-Options: deny
  X-Content-Type-Options: nosniff
  X-XSS-Protection: 1; mode=block
  Referrer-Policy: origin-when-cross-origin, strict-origin-when-cross-origin
  Content-Security-Policy: default-src 'none'
  X-Runtime-rack: 0.029792
  X-GitHub-Request-Id: DCD6:3C9D:688D222:D064A9D:5B41DCE9
  Content-Type: application/json; charset=utf-8
  Content-Length: 2642

如你所见和所愿，在 Trace 级别，详情非常丰富。这对于在开发阶段获得更详细的理解请求头和响应头很有帮助。并不建议在生产环境这样启用，因为它将不仅很快填满日志，还可能暴露安全数据，例如验证令牌等。

每条日志信息包含一个事件 Id，所以你可以快速过滤感兴趣的日志，默认有 2 个日志器可用。一个是 LogicalHandler 日志器，它封装整个的处理器管线。它支持整条管线的计时包含到日志中。另外，它是整个管线中的第一个，在其它处理器之前，它记录开始的请求头。其它处理器可能会修改这些请求头。使用 trace 级别日志，它可以在日志中捕获这些信息，在诊断失效的时候比较有用。

内部的日志器在类别名称上有一个 ClientHandler 的前缀。它将是最里面的处理器，因此是在请求被发送到网上之前最终的定制处理器，结果，它将可以记录最终的请求头。

作为参考，这些日志起包含的事件 ID 如下所示：

Outer “LogicalHandler”

100	RequestPipelineStart
101	RequestPipelineEnd
102	RequestPipelineRequestHeader
103	RequestPipelineResponseHeader

Inner “ClientHandler”

100	RequestStart
101	RequestEnd
102	RequestHeader
103	ResponseHeader

IHttpClientFactory 是如何进行日志工作的？

IHttpClientFactory 正好在 HttpMessageHandlerBuilder.Build() 方法被调用之前被应用到管线，并返回 HttpMessageHandler 管线。

这是通过 HttpMessageHandlerBuilder 过滤器的帮助做到的，他通过 DefaultHttpClientFactory 实现被应用。名为 IHttpMessageHandlerBuilderFilter 的接口存在并被实现，以便于定义过滤器。默认，该接口有一个被称为 LoggingHttpMessageHandlerBuilderFilter 的实现，它在 DI 中被注册。基于该接口，可以有多于一个的实现。随着该接口注册到 DI 中，当构建管线的时候每一个都可以被执行。

在 LoggingHttpMessageHandlerBuilderFilter 中的代码实现 Configure() 方法，负责创建两个日志器，并传递给日志处理器。它们自己被实现为抽象类 DelegatingHandler 的实现。LoggingHttpMessageHandlerBuilderFilter.Configure() 中的代码如下：

public Action<HttpMessageHandlerBuilder> Configure(Action<HttpMessageHandlerBuilder> next)
{
    if (next == null)
    {
        throw new ArgumentNullException(nameof(next));
    }

    return (builder) =>
    {
        // Run other configuration first, we want to decorate.
        next(builder);

        // We want all of our logging message to show up as-if they are coming from HttpClient,
        // but also to include the name of the client for more fine-grained control.
        var outerLogger = _loggerFactory.CreateLogger($"System.Net.Http.HttpClient.{builder.Name}.LogicalHandler");
        var innerLogger = _loggerFactory.CreateLogger($"System.Net.Http.HttpClient.{builder.Name}.ClientHandler");

        // The 'scope' handler goes first so it can surround everything.
        builder.AdditionalHandlers.Insert(0, new LoggingScopeHttpMessageHandler(outerLogger));

        // We want this handler to be last so we can log details about the request after
        // service discovery and security happen.
        builder.AdditionalHandlers.Add(new LoggingHttpMessageHandler(innerLogger));
    };
}

当委托链被调用的时候，next(builder) 调用 (line 11) 将执行下一个委托 ( Action<HttpMessageHandlerBuilder>) 以确保整个处理器管线被配置。

然后，2 个日志器被创建出来，使用来自构建器的名称。它将是给予命名客户端的名称或者类型化客户端的名称。

外部的处理器被添加到索引 0 到 AdditionalHandlers 列表中，所以它包围了所有其它的处理器并首先执行。内部的处理器被添加到 AdditionalHandlers 列表的最后，所以它将是在内部的处理器处理 Http 请求时最后的处理器。

每个日志处理器负责记录在调用其它的 SendAsync() 之前和之后的消息。使用这种方式，定时器可以在 SendAsync() 调用之前启动，且在最后被使用以记录整个的 Http 请求时间。我不再复制这些处理器的代码，它们很长，相反，如果你感兴趣的话，可以在 GitHub 中查阅。

外部处理器的代码可以在这里查看。

该类创建了一个日志范围，并记录日志消息。可选地，如果 Trace 被启用，还将遍历请求和响应头。将它们记录到日志中。此类中使用的模式是 LoggerMessage 方式的一个示例，提供缓存日志委托以提高性能。你可以在 official documentation at docs.microsoft.com 中阅读关于此方式的更多信息。这超出了本文的范围。

内部的 "ClientHandler" 日志器使用类似的方式来记录日志消息，源代码可以在这里查看。

配置日志输出

由于所有的日志使用 Microsoft.Extensions.Logging 库，你可以使用配置来控制日志的生成。

在 appsettings.json 文件中，你可以控制和过滤记录的日志。默认的产品配置 json 文件如下所示：

{
  "Logging": {
    "LogLevel": {
      "Default": "Warning"
    }
  }
}

在上面的配置中，只有 Warning 和更高级别被记录并输出。没有来自 IHttpClientFactory 处理器的日志。为了启用日志，我们可以添加附加的日志级别设置。如果你阅读了上面的 "如何工作" 一节，你会回忆起使用的用来记录 Http 请求的日志消息的日志器，它的类型名以 "System.Net.Http" 开头。

一种方式是针对 System 命名空间启用 Information 日志。

{
  "Logging": {
    "LogLevel": {
      "Default": "Debug",
      "System": "Information"
    }
  }
}

但是，这将会启用其它 System 命名空间中所有组件的日志。因此最好限制配置为 System.Net.Http.HttpClient 以便仅仅记录通过 HttpClientFactory 进行的 Http 请求的日志。

{
  "Logging": {
    "LogLevel": {
      "Default": "Warning",
      "System.Net.Http.HttpClient": "Information"
    }
  }
}

我们还可以进一步控制到命名或者类型化的客户端。对于类型话的客户端，名字来自注册的名称。

想象我们仅仅希望记录名为 MyClient 的类型化客户端日志，另外，我们还可能仅仅希望看到 Http 请求的计时，在该例中，我们可以仅仅启用 MyClient 的 ClientHandler 日志：

{
  "Logging": {
    "LogLevel": {
      "Default": "Warning",
      "System.Net.Http.HttpClient.MyClient.ClientHandler": "Information"
    }
  }
}

定制日志消息

你也可能希望针对由 IHttpClientFactory 管理的客户端增加额外的日志。一种方式是，引入额外的处理器到管线中，本系列的 #3，我探索了添加新的中间件处理器到客户端配置中。使用这种处理器，你可以查看请求和响应，记录任何需要的数据。

如果你想完全替换默认的日志器，以完全定制输出的消息，来自开发团队的建议方式是替换默认的 IHttpMessageHandlerBuilderFilter 接口实现，实际上，本文的灵感来自 IHttpClientFactory GitHub 仓库的一个问题。我们看一下如何替换日志器，以记录 correlation ID 到控制台消息中。因为我需要额外的日志消息，所以我们希望替换默认的实现。

首先，我们需要创建 IHttpMessageHandlerBuilderFilter 接口的新的实现。

public class CustomLoggingFilter : IHttpMessageHandlerBuilderFilter
{
    private readonly ILoggerFactory _loggerFactory;

    public CustomLoggingFilter(ILoggerFactory loggerFactory)
    {
        _loggerFactory = loggerFactory ?? throw new ArgumentNullException(nameof(loggerFactory));
    }

    public Action<HttpMessageHandlerBuilder> Configure(Action<HttpMessageHandlerBuilder> next)
    {
        if (next == null)
        {
            throw new ArgumentNullException(nameof(next));
        }

        return (builder) =>
        {
            // Run other configuration first, we want to decorate.
            next(builder);

            var outerLogger =
                _loggerFactory.CreateLogger($"System.Net.Http.HttpClient.{builder.Name}.LogicalHandler");

            builder.AdditionalHandlers.Insert(0, new CustomLoggingScopeHttpMessageHandler(outerLogger));
        };
    }
}

基本上我复制了过滤器的默认实现。主要的区别是我仅仅使用一个外部的日志器进行演示。创建了一个日志器，然后添加新的 CustomLoggingScopeHttpMessageHandler 到管线中。

CustomLoggingScopeHttpMessageHandler 如下所示：

public class CustomLoggingScopeHttpMessageHandler : DelegatingHandler
{
    private readonly ILogger _logger;

    public CustomLoggingScopeHttpMessageHandler(ILogger logger)
    {
        _logger = logger ?? throw new ArgumentNullException(nameof(logger));
    }

    protected override async Task<HttpResponseMessage> SendAsync(HttpRequestMessage request,
        CancellationToken cancellationToken)
    {
        if (request == null)
        {
            throw new ArgumentNullException(nameof(request));
        }

        using (Log.BeginRequestPipelineScope(_logger, request))
        {
            Log.RequestPipelineStart(_logger, request);
            var response = await base.SendAsync(request, cancellationToken);
            Log.RequestPipelineEnd(_logger, response);

            return response;
        }
    }

    private static class Log
    {
        private static class EventIds
        {
            public static readonly EventId PipelineStart = new EventId(100, "RequestPipelineStart");
            public static readonly EventId PipelineEnd = new EventId(101, "RequestPipelineEnd");
        }

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

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

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

        public static IDisposable BeginRequestPipelineScope(ILogger logger, HttpRequestMessage request)
        {
            var correlationId = GetCorrelationIdFromRequest(request);
            return _beginRequestPipelineScope(logger, request.Method, request.RequestUri, correlationId);
        }

        public static void RequestPipelineStart(ILogger logger, HttpRequestMessage request)
        {
            var correlationId = GetCorrelationIdFromRequest(request);
            _requestPipelineStart(logger, request.Method, request.RequestUri, correlationId, null);
        }

        public static void RequestPipelineEnd(ILogger logger, HttpResponseMessage response)
        {
            _requestPipelineEnd(logger, response.StatusCode, null);
        }

        private static string GetCorrelationIdFromRequest(HttpRequestMessage request)
        {
            var correlationId = "Not set";

            if (request.Headers.TryGetValues("X-Correlation-ID", out var values))
            {
                correlationId = values.First();
            }

            return correlationId;
        }
    }
}

确实有点多，但是多数是静态的日志类和它的方法。我不会深入它们，因为它们遵循 LoggerMessage 建议来更有效日志，详见 read in the docs。多数是根据需要对现存的 LoggingScopeHttpMessageHandler 进行调整。

第一关注点是整个操作被封装在一个日志范围之内。在 SendAsync() 调用之前和之后，我们使用静态的 Log() 方法来记录事件 (行 20 和 22)

在日志类中，一些定义的私有委托定义为格式化期望的日志消息。

_beginRequestPipelineScope 和 _requestPipelineStart 两者接收一个字符串，它将是 correlation ID。它们使用该值来记录 correlation ID 到 Scope 属性中，也在请求开始的消息中。

简单的助手方法被添加，它对期望的 correlation id 解析 Http 请求头，如果提供了，返回它，BeginRequestPipelineScope 和 RequestPipelineStart 两者使用该方法来提取 correlation ID。

在我们过滤器中最终的步骤注册到 DI 容器中，替换现存的默认过滤器。

在 Startup 类内部，ConfigureServices() 方法中，我们可以在 ServiceCollection 上调用 Replace() 方法来使用我们的实现来清除默认实现。

services.Replace(ServiceDescriptor.Singleton<IHttpMessageHandlerBuilderFilter, CustomLoggingFilter>());

Replace() 方法将发现第一个注册的 IHttpMessageHandlerBuilderFilter 服务，并使用新的替换原来的注册。CustomLoggingFilter 是我们的实现。

现在，当我们运行应用的时候，控制台日志包含了我们的 Correlation ID

info: System.Net.Http.HttpClient.MyClient.LogicalHandler[100]
      Start processing HTTP request GET https://api.github.com/repos/aspnet/docs/branches [Correlation: 447c8d6b-e280-4538-bd31-56d508266b5b]

info: System.Net.Http.HttpClient.MyClient.LogicalHandler[101]
      End processing HTTP request - OK

另外，过滤器方式是很好对整个应用程序添加公共的跨边界的方式。可以注册额外的过滤器，每个可以通过 HttpClientFactory 添加自己的处理器到所有的客户端上

总结

本文中，我们关注内建的日志器的可用类型信息，包括作为 HttpClientFactory 库中的一部分。我们如何使用日志配置来控制哪些日志信息可见，日志是如何在库中实现的，最后，我们探索了使用 IHttpMessageHandlerBuilderFilter 接口来替换默认的日志过滤器。

Part 1 – HttpClientFactory in ASP.NET Core 2.1 Part 1 介绍
Part 2 – HttpClientFactory in ASP.NET Core 2.1 Part 2：定义命名和类型化的客户端

Part 3 – HttpClientFactory in ASP.NET Core 2.1 Part 3: 对处理器使用对外请求中间件
Part 4 – HttpClientFacotry Part 4: 集成 Polly 处理瞬时失效
Part 5 – HttpClientFactory in ASP.NET Core 2.1 Part 5: 日志