转载

HttpClientFactory日志不好用,自己扩展一个?

HttpClientFactory日志不好用,自己扩展一个?

.NetCore2.1新推出 HttpClientFactory 工厂类, 替代了早期的 HttpClient ,并新增了弹性Http调用机制 (集成 Policy 组件)。

HttpClientFactory日志不好用,自己扩展一个?

替换的初衷还是简单说下:

①  using(var client= new HttpClient()) 调用Dispose()方法,并不会很快释放底层Socket连接,同时新建Socket需要时间,这在高并发场景下Socket耗尽。  传送门

②  由于①很多人会想到用单例或静态类构建HttpClient实例,但是这里还有一个坑,HttpClient会忽略DNS的变化。  传送门

HttpClientFactory日志不好用,自己扩展一个?

HttpClientFactory 以一种模块化、可命名、弹性可预期的方式重建了HttpClient的使用方式。HttpClientFactory以依赖注入的方式集成到.NETCore 框架:

HttpClientFactory典型用法

使用时从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个问题:

HttpClientFactory日志不好用,自己扩展一个?

① 在高并发使用HttpClient,日志条数众多,没有类似TraceId 这样的机制定位 某次HttpClient调用的完整日志。 

②  若是微服务/ 分布式调用,可能还有 将本次HttpClient调用日志与后置api日志 结合分析的需求, 这个日志也支持不了。

HttpClientFactory日志不好用,自己扩展一个?

因此本文打算重新构建 HttpClientFactory日志: 给某次请求的全部日志设置TraceId

结合我给出的典型用法来看IHttpClientFactory组件原理:

HttpClientFactory日志不好用,自己扩展一个? 示例中 System.Net.Http.HttpClient.bce-request.LogicalHandler System.Net.Http.HttpClient.bce-request.ClientHandler  日志头即是来自 LoggingScopeHttpMessageHandler  ,LoggingHttpMessageHandler 两个处理器。

给出手绘的UML类图: 

HttpClientFactory日志不好用,自己扩展一个?

本次要扩展的入口便是 IHttpMessageHandlerFilter 接口,核心是自定义DelegatingHandler日志处理器。

编程实践

如以上分析,使用aspNetCore2.2需要做如下扩展:

P1

实现IHttpMessageHandlerFilter接口,移除接口中默认的2个日志处理器

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。

Tip

① 这个TraceId 可以使用你业务上独具一格的标记,这样在排查时, 能根据上游业务更好的追踪日志。

② 目前这个TraceId位于LogMessage,实际上可以为nlog自定义LogoutRenderer,将该TraceId放在显著位置,便于ETL等日志集成框架过滤。

That's All, 这是本次解决HttpCl ient日志无法追踪的思路和方案, 思考+实践+UML制图,希望能给 大家一些启发。

+ https://github.com/aspnet/HttpClientFactory/blob/master/src/Microsoft.Extensions.Http/Logging/LoggingHttpMessageHandlerBuilderFilter.cs

HttpClientFactory日志不好用,自己扩展一个?

扫一扫左边二维码,
更多惊喜干货等着你。
............

HttpClientFactory日志不好用,自己扩展一个?

原文  http://mp.weixin.qq.com/s?__biz=MzAwNTMxMzg1MA==&mid=2654077047&idx=4&sn=a17d0f43fc8871f8951a48867f8aac7a
正文到此结束
Loading...