解剖HttpClientFactory，自由擴展HttpMessageHandler

前言

　　.NetCore2.1新推出HttpClientFactory工廠類， 替代了早期的HttpClient， 並新增了彈性Http調用機制 (集成Policy組件)。

替換的初衷還是簡單說下：

①  using(var client= new HttpClient()) 調用Dispose()方法，並不會很快釋放底層Socket連接， 同時新建Socket需要時間，這在高並發場景下Socket耗盡。 傳送門

②  由於①很多人會想到用單例或靜態類構建HttpClient實例，但是這里還有一個坑，HttpClient 會忽略DNS的變化。 傳送門

HttpClientFactory 以一種模塊化、可命名、彈性可預期的方式重建了HttpClient的使用方式。

現在的HttpClientFactory以依賴注入的方式集成到.NETCore 框架：

// 截取自Startup.cs文件服務配置部分
public void ConfigureServices(IServiceCollection services)
{
            services.AddHttpClient("bce-request", x =>
                   x.BaseAddress = new Uri(Configuration.GetSection("BCE").GetValue<string>("BaseUrl")))
                .ConfigurePrimaryHttpMessageHandler(_ => new BceAuthClientHandler()
               {
                   AccessKey = Configuration.GetSection("BCE").GetValue<string>("AccessKey"),
                   SerectAccessKey = Configuration.GetSection("BCE").GetValue<string>("SecretAccessKey"),
                   AllowAutoRedirect = true,
                   UseDefaultCredentials = true
               })
               .SetHandlerLifetime(TimeSpan.FromHours(12))
               .AddPolicyHandler(GetRetryPolicy(3));
}

static IAsyncPolicy<HttpResponseMessage> GetRetryPolicy(int  retry)
{
      var retryPolicy = HttpPolicyExtensions
                .HandleTransientHttpError()
                .OrResult(msg => msg.StatusCode == System.Net.HttpStatusCode.NotFound)
                .WaitAndRetryAsync(retry, retryAttempt => TimeSpan.FromSeconds(Math.Pow(2, retryAttempt)));
            return retryPolicy;
}

使用時從 IHttpClientFactory工廠創建所需HttpClient實例，發起業務端請求。

以下是利用NLog觀察到的文件日志：

19/12/04 11:06:46 [Info].[System.Net.Http.HttpClient.bce-request.LogicalHandler].[18}].[]
Start processing HTTP request GET http://localhost:5000/v1/eqid/b827a9400004132a000000065dc26470 
19/12/04 11:06:46 [Info].[System.Net.Http.HttpClient.bce-request.ClientHandler].[18}].[]
Sending HTTP request GET http://localhost:5000/v1/eqid/b827a9400004132a000000065dc26470 
19/12/04 11:06:46 [Info].[System.Net.Http.HttpClient.bce-request.ClientHandler].[34}].[]
Received HTTP response after 174.5088ms - OK 
19/12/04 11:06:46 [Info].[System.Net.Http.HttpClient.bce-request.LogicalHandler].[34}].[]
End processing HTTP request after 211.1478ms - OK 

頭腦風暴

　　觀察上面單次請求的日志，由外層LogicHandler和內層ClientHandler 日志頭組成。 這樣的日志可以想象到有2個問題：

 ① 在高並發使用HttpClient，日志條數眾多，沒有類似TraceId 這樣的機制定位 某次HttpClient調用的完整日志。 

 ②  若是微服務/ 分布式調用，可能還有 將本次HttpClient調用日志與后置api日志 結合分析的需求， 這個日志也支持不了。

因此本文打算重新自定義HttpClientFactory日志處理器(給請求的全部日志設置TraceId)，實際上CustomLoggingHttpMessageHandler只是一個引子，掌握如何擴展才是關鍵。

結合我給出的典型用法來看IHttpClientFactory組件原理：

 

 示例中System.Net.Http.HttpClient.bce-request.LogicalHandler，System.Net.Http.HttpClient.bce-request.ClientHandler 日志頭即是來自LoggingScopeHttpMessageHandler ，LoggingHttpMessageHandler 兩個處理器，

 給出手繪的UML類圖： 

 

本次要擴展的入口便是 IHttpMessageHandlerFilter接口， 核心是自定義DelegatingHandler日志處理器

+ https://github.com/dotnet/extensions/blob/master/src/HttpClientFactory/Http/src/Logging/LoggingHttpMessageHandlerBuilderFilter.cs

編程實踐

   如以上分析，

P1  實現 IHttpMessageHandlerFilter接口，在接口中移除默認的兩個日志處理器

    public class TraceIdLoggingMessageHandlerFilter : IHttpMessageHandlerBuilderFilter
    {
        private readonly ILoggerFactory _loggerFactory;

        public TraceIdLoggingMessageHandlerFilter(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.Clear();
                builder.AdditionalHandlers.Insert(0,new CustomLoggingScopeHttpMessageHandler(outerLogger));
            };
        }
    }

P2  實現帶有TraceId能力的HttpClient 日志處理器， 並加入到 IHttpMessageHandlerFilter接口實現類

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,string,Exception> _requestPipelineEnd =
                LoggerMessage.Define<HttpStatusCode,string>(
                    LogLevel.Information,
                    EventIds.PipelineEnd,
                    "End processing HTTP request - {StatusCode}, [Correlation: {CorrelationId}]");

            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)
            {
                var correlationId = GetCorrelationIdFromRequest(response.RequestMessage);
                _requestPipelineEnd(logger, response.StatusCode, correlationId, null);
            }

            private static string GetCorrelationIdFromRequest(HttpRequestMessage request)
            {
                string correlationId;
                if (request.Headers.TryGetValues("X-Correlation-ID", out var values))
                    correlationId = values.First();
                else
                   {correlationId = Guid.NewGuid().ToString()； request.Headers.Add("X-Correlation-ID",correlationId)；}

　　　　　　　　  return correlationId; }
           }
 }

   以上TraceId的實現思路，參考了我前一篇博文《被忽略的TraceId，可以用起來了》的思路，為每次HttpClient調用過程設定  全局唯一的GUID標記， 后置api服務可酌情修改以上代碼處理。

其中寫入日志的代碼Copy自HttpClientFactory源代碼。

P3  在DI框架中替換原有的 IHttpMessageHandlerFilter 實現

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

  發起兩次HttpClient請求， 輸出的日志如下:

19/12/04 12:59:22 [Info].[System.Net.Http.HttpClient.bce-request.LogicalHandler].[17}].[]
Start processing HTTP request GET http://localhost:5000/v1/eqid/ad78deef00444ed7000000035de704e8 [Correlation: 03de676d-680e-4a92-aef5-749bcc3ba499] 
19/12/04 12:59:22 [Info].[System.Net.Http.HttpClient.bce-request.LogicalHandler].[4}].[]
End processing HTTP request - OK, [Correlation: 03de676d-680e-4a92-aef5-749bcc3ba499] 
19/12/04 12:59:48 [Info].[System.Net.Http.HttpClient.bce-request.LogicalHandler].[17}].[]
Start processing HTTP request GET http://localhost:5000/v1/eqid/8ea0c3b66b60f0ff100000005de704fb [Correlation: 6f14393a-3a2b-45c4-a9b4-0b4ab874ef1d] 
19/12/04 12:59:48 [Info].[System.Net.Http.HttpClient.bce-request.LogicalHandler].[42}].[]
End processing HTTP request - OK, [Correlation: 6f14393a-3a2b-45c4-a9b4-0b4ab874ef1d] 

可以看到每次請求的開始和結束都帶上了設定的guid TraceId。

值得提醒的是：

 ① 這個TraceId 可以使用你業務上獨具一格的標記，這樣在排查時， 能根據上游業務更好的追蹤日志。

 ② 現在這個TraceId位於LogMessage，實際上可以為nlog自定義LogoutRenderer，將該TraceId放在顯著位置，便於ETL等日志集成框架過濾。

That's All， 本次為解決HttpClientFactory日志無追蹤機制的探索，思考 + 實踐 + UML制圖。

實現CustomLoggingScopeHttpMessageHandler只是擴展HttpClientFactory能力的一個引子，如何擴展HttpClientFactory能力才是關鍵，希望能給大家一些啟發。 

 

--------------------------------------------------------------2019.12.06 更新------------------------

實際上HttpClientFactory內原生LoggingHandler是支持LoggingScope, 在Console 輸出如下：

info: System.Net.Http.HttpClient.bce-request.LogicalHandler[100]
      => ConnectionId:0HLRQ6DAF0JKV => RequestId:0HLRQ6DAF0JKV:00000004 RequestPath:/eqid/f53990dc0002adf0000000045de9c421 => EqidManager.Controllers.DebugController.ResolveEqid (EqidManager) => HTTP GET http://localhost:5000/v1/eqid/f53990dc0002adf0000000045de9c421
      Start processing HTTP request GET http://localhost:5000/v1/eqid/f53990dc0002adf0000000045de9c421
info: System.Net.Http.HttpClient.bce-request.ClientHandler[100]
      => ConnectionId:0HLRQ6DAF0JKV => RequestId:0HLRQ6DAF0JKV:00000004 RequestPath:/eqid/f53990dc0002adf0000000045de9c421 => EqidManager.Controllers.DebugController.ResolveEqid (EqidManager) => HTTP GET http://localhost:5000/v1/eqid/f53990dc0002adf0000000045de9c421
      Sending HTTP request GET http://localhost:5000/v1/eqid/f53990dc0002adf0000000045de9c421

info: System.Net.Http.HttpClient.bce-request.ClientHandler[101]
      => ConnectionId:0HLRQ6DAF0JKV => RequestId:0HLRQ6DAF0JKV:00000004 RequestPath:/eqid/f53990dc0002adf0000000045de9c421 => EqidManager.Controllers.DebugController.ResolveEqid (EqidManager) => HTTP GET http://localhost:5000/v1/eqid/f53990dc0002adf0000000045de9c421
      Received HTTP response after 195.1112ms - OK
info: System.Net.Http.HttpClient.bce-request.LogicalHandler[101]
      => ConnectionId:0HLRQ6DAF0JKV => RequestId:0HLRQ6DAF0JKV:00000004 RequestPath:/eqid/f53990dc0002adf0000000045de9c421 => EqidManager.Controllers.DebugController.ResolveEqid (EqidManager) => HTTP GET http://localhost:5000/v1/eqid/f53990dc0002adf0000000045de9c421
      End processing HTTP request after 232.4906ms - OK

Scope需要LoggingProvider 支持，而我們使用的NLog不支持scope， 所以最上面的nlog 文件日志沒有輸出Scope。

這就引出了本文的目的，所以本文通過解構HttpClientFactory的HttpMessageHandler，為請求響應添加TraceId， 當然你也可以根據HttpClient業務加入其它HttpMessageHandler