《ASP.NET Core 6框架揭秘》实例演示[26]：跟踪应用接收的每一次请求

Posted 2022-09-16 dotNET跨平台

很多人可能对ASP.NET Core框架自身记录的诊断日志并不关心，其实这些日志对纠错排错和性能监控提供了很有用的信息。如果需要创建一个APM（Application Performance Management）系统来监控ASP.NET Core应用处理请求的性能及出现的异常，我们完全可以将HostingApplication对象记录的日志作为收集的原始数据。实际上，目前很多APM（如OpenTelemetry.NET 、Elastic APM和SkyWalking APM等）针对都是利用这种方式收集分布式跟踪日志的。[本文节选《ASP.NET Core 6框架揭秘》第17章]

[S1701]ASP.NET针对请求的诊断日志（源代码）
[S1702]收集DiagnosticSource输出的日志（源代码）
[S1703]收集EventSource输出的日志（源代码）

[S1701]ASP.NET针对请求的诊断日志

为了确定什么样的信息会被作为诊断日志记录下来，我们通过一个简单的实例演示将HostingApplication对象写入的诊断日志输出到控制台上。HostingApplication对象会将相同的诊断信息以三种不同的方式进行记录，其中包含第8章“诊断日志（中篇）”介绍的日志系统。如下的演示程序利用WebApplicationBuilder的Logging属性得到返回的ILoggingBuilder对象，并调用它的AddSimpleConsole扩展方法为默认注册的ConsoleLoggerProvider开启了针对日志范围的支持。我们最后调用IApplicationBuilder接口的Run扩展方法注册了一个中间件，该中间件在处理请求时会利用依赖注入容器提取出用于发送日志事件的ILogger<Program>对象，并利用它写入一条Information等级的日志。如果请求路径为“/error”，那么该中间件会抛出一个InvalidOperationException类型的异常。

var builder = WebApplication.CreateBuilder(args);
builder.Logging.AddSimpleConsole(
    options => options.IncludeScopes = true);
var app = builder.Build();
app.Run(HandleAsync);
app.Run();

static Task HandleAsync(HttpContext httpContext)

    var logger = httpContext.RequestServices
        .GetRequiredService<ILogger<Program>>();
    logger.LogInformation($"Log for event Foobar");
    if (httpContext.Request.Path == new PathString("/error"))
    
        throw new InvalidOperationException("Manually throw exception.");
    
    return Task.CompletedTask;

在启动程序之后，我们利用浏览器采用不同的路径（“/foobar”和“/error”）向应用发送了两次请求，控制台上会输出如图1所示的七条日志。由于开启了日志范围的支持，所以输出的日志都会携带日志范围的信息，日志范围提供了很多有用的分布式跟踪信息，比如Trace ID、Span ID、Parent Span ID以及请求的ID和路径等。请求ID（Request ID），它由当前的连接ID和一个序列号组成。从图1可以看出，两次请求的ID分别是“0HMG97FD188VR:00000002”和“0HMG97FD188VR:00000003”。由于采用的是长连接，并且两次请求共享同一个连接，所以它们具有相同的连接ID（“0HMG97FD188VR”）。同一连接的多次请求将一个自增的序列号（“00000002”和“00000003”）作为唯一标识。

图1　捕捉HostingApplication记录的诊断日志

对于两次请求输出的七条日志，类别为“Program”的日志是应用程序自行写入的，HostingApplication写入日志的类别为“Microsoft.AspNetCore.Hosting.Diagnostics”。对于第一次请求的三条日志消息，第一条是在开始处理请求时写入的，我们利用这条日志获知请求的HTTP版本（HTTP/1.1）、HTTP方法（GET）和请求URL。对于包含主体内容的请求，请求主体内容的媒体类型（Content-Type）和大小（Content-Length）也会一并记录下来。当请求处理结束后第三条日志被输出，日志承载的信息包括请求处理耗时（9.9482毫秒）和响应状态码（200）。如果响应具有主体内容，对应的媒体类型同样会被记录下来。

对于第二次请求，由于我们人为抛出了异常，所以异常的信息被写入日志。如果足够仔细，就会发现这条等级为Error的日志并不是由HostingApplication对象写入的，而是作为服务器的KestrelServer写入的，因为该日志采用的类别为“Microsoft.AspNetCore.Server.Kestrel”。

[S1702]收集DiagnosticSource输出的日志

HostingApplication采用的三种日志形式还包括基于DiagnosticSource对象的诊断日志，所以我们可以通过注册诊断监听器来收集诊断信息。如果通过这种方式获取诊断信息，就需要预先知道诊断日志事件的名称和内容荷载的数据结构。通过查看HostingApplication类型的源代码，我们会发现它针对“开始请求”、“结束请求”和“未处理异常”这三类诊断日志事件会采用如下的命名方式。

• 开始请求：Microsoft.AspNetCore.Hosting.BeginRequest。

• 结束请求：Microsoft.AspNetCore.Hosting.EndRequest。

• 未处理异常：Microsoft.AspNetCore.Hosting.UnhandledException。

至于针对诊断日志消息的内容荷载（Payload）的结构，上述三类诊断事件具有两个相同的成员，分别是表示当前请求上下文的HttpContext和通过一个Int64整数表示的当前时间戳，对应的数据成员的名称分别为“httpContext”和“timestamp”。对于未处理异常诊断事件，它承载的内容荷载还包括抛出异常，对应的成员名称为“exception”。我们的演示程序定义了如下这个的DiagnosticCollector类型作为诊断监听器，它定义针对上述三个诊断事件的监听方法。

public class DiagnosticCollector

    [DiagnosticName("Microsoft.AspNetCore.Hosting.BeginRequest")]
    public void OnRequestStart(
        HttpContext httpContext, 
        long timestamp)
    
        var request = httpContext.Request;
        Console.WriteLine(
            $"\\nRequest starting request.Protocol request.Method 
            request.Scheme://request.Hostrequest.PathBaserequest.Path");
        httpContext.Items["StartTimestamp"] = timestamp;
    

    [DiagnosticName("Microsoft.AspNetCore.Hosting.EndRequest")]
    public void OnRequestEnd(
        HttpContext httpContext, 
        long timestamp)
    
        var startTimestamp = long.Parse(
            httpContext.Items["StartTimestamp"]!.ToString());
        var timestampToTicks = TimeSpan.TicksPerSecond / (double)Stopwatch.Frequency;
        var elapsed = new TimeSpan((long)(
            timestampToTicks * (timestamp - startTimestamp)));
        Console.WriteLine(
            $"Request finished in elapsed.TotalMillisecondsms 
            httpContext.Response.StatusCode");
    
    [DiagnosticName("Microsoft.AspNetCore.Hosting.UnhandledException")]
    public void OnException(
        HttpContext httpContext, 
        long timestamp, 
        Exception exception)
    
        OnRequestEnd(httpContext, timestamp);
        Console.WriteLine(
            $"exception.Message\\nType:exception.GetType()\\nStacktrace: 
            exception.StackTrace");
    

针对“开始请求”事件的OnRequestStart方法输出了当前请求的HTTP版本、HTTP方法和URL。为了能够计算整个请求处理的耗时，它将当前时间戳保存在HttpContext上下文的Items集合中。针对“结束请求”事件的OnRequestEnd方法将这个时间戳从HttpContext上下文中提取出来，结合当前时间戳计算出请求处理耗时，该耗时和响应的状态码最终会被写入控制台。针对“未处理异常”诊断事件的OnException方法则在调用OnRequestEnd方法之后将异常的消息、类型和跟踪堆栈输出到控制台上。如下所示的演示程序中利用WebApplication的Services提供的依赖注入容器提取出注册的DiagnosticListener对象，并调用它的SubscribeWithAdapter扩展方法将DiagnosticCollector对象注册为订阅者。我们调用Run扩展方法注册了一个中间件，该中间件会在请求路径为“/error”的情况下抛出异常。

using App;
using System.Diagnostics;

var builder = WebApplication.CreateBuilder(args);
builder.Logging.ClearProviders();
var app = builder.Build();
var listener = app.Services
    .GetRequiredService<DiagnosticListener>();
listener.SubscribeWithAdapter(new DiagnosticCollector());
app.Run(HandleAsync);
app.Run();

static Task HandleAsync(HttpContext httpContext)

    var listener = httpContext.RequestServices
        .GetRequiredService<DiagnosticListener>();
    if (httpContext.Request.Path == new PathString("/error"))
    
        throw new InvalidOperationException("Manually throw exception.");
    
    return Task.CompletedTask;

待演示实例正常启动后，可以采用不同的路径（“/foobar”和“/error”）对应用程序发送两个请求，服务端控制台会以图2所示的形式输出DiagnosticCollector对象收集的诊断信息。

图2　利用注册的诊断监听器获取诊断日志

[S1703]收集EventSource输出的日志

HostingApplication在处理每个请求的过程中还会利用名称为“Microsoft.AspNetCore.Hosting”EventSource对象发出相应的日志事件。这个EventSource对象来回在在启动和关闭应用程序时发出相应的事件。涉及的五个日志事件对应的名称如下：

• 启动应用程序：HostStart。

• 开始处理请求：RequestStart。

• 请求处理结束：RequestStop。

• 未处理异常：UnhandledException。

• 关闭应用程序：HostStop。

如下所示的演示程序利用创建的EventListener对象来监听上述五个日志事件。如代码片段所示，我们定义了派生于抽象类EventListener的DiagnosticCollector类型，并在启动应用前创建了这个对象，我们通过注册它的EventSourceCreated事件开启了针对上述EventSource的监听。注册的EventWritten事件会将监听到的事件名称的负载内容输出到控制台上。

using System.Diagnostics.Tracing;

var listener = new DiagnosticCollector();
listener.EventSourceCreated += (sender, args) =>

    if (args.EventSource?.Name == "Microsoft.AspNetCore.Hosting")
    
        listener.EnableEvents(
            args.EventSource, 
            EventLevel.LogAlways);
    
;
listener.EventWritten += (sender, args) =>

    Console.WriteLine(args.EventName);
    for (int index = 0; 
        index < args.PayloadNames?.Count; 
        index++)
    
        Console.WriteLine(
            $"\\targs.PayloadNames[index] = args.Payload?[index]");
    
;


var builder = WebApplication.CreateBuilder(args);
builder.Logging.ClearProviders();
var app = builder.Build();
app.Run(HandleAsync);
app.Run();

static Task HandleAsync(HttpContext httpContext)

    if (httpContext.Request.Path == new PathString("/error"))
    
        throw new InvalidOperationException(
            "Manually throw exception.");
    
    return Task.CompletedTask;


public class DiagnosticCollector : EventListener  

以命令行的形式启动这个演示程序后，从图3所示的输出结果可以看到名为HostStart的事件被发出。然后我们采用目标地址“http://localhost:5000/foobar”和“http:// http://localhost:5000/error”对应用程序发送两个请求，从输出结果可以看出，应用程序针对前者的处理过程会发出RequestStart事件和RequestStop事件，针对后者的处理则会因为抛出的异常发出额外的事件UnhandledException。输入“Ctrl+C”关闭应用后，名称为HostStop的事件被发出。对于通过EventSource发出的五个事件，只有RequestStart事件会将请求的HTTP方法（GET）和路径（“/foobar”和“/error”）作为负载内容，其他事件都不会携带任何负载内容。

图3　利用注册EventListener监听器获取诊断日志