[引子]HttpClientFactory日誌不好用,自己擴充套件一個?
前言
.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例項,發起業務端請求。
觀察Info級別日誌:
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/aspnet/HttpClientFactory/blob/master/src/Microsoft.Extensions.Http/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 = Guid.NewGuid().ToString(); if (request.Headers.TryGetValues("X-Correlation-ID", out var values)) correlationId = values.First(); else 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能力才是關鍵,希望能被大家一些啟發。