ASP.NET Core 6框架揭秘實例演示[26]：跟蹤應用接收的每一次請求

很多人可能對ASP.NET Core框架自身記錄的診斷日志並不關心，其實這些日志對糾錯排錯和性能監控提供了很有用的信息。如果需要創建一個APM（Application Performance Management）系統來監控ASP.NET Core應用處理請求的性能及出現的異常，我們完全可以將HostingApplication對象記錄的日志作為收集的原始數據。實際上，目前很多APM（如OpenTelemetry.NET 、Elastic APM和SkyWalking APM等）針對都是利用這種方式收集分布式跟蹤日志的。(本篇提供的實例已經匯總到《ASP.NET Core 6框架揭秘-實例演示版》）

[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”）向應用發送了兩次請求，控制台上會輸出如圖17-4所示的七條日志。由於開啟了日志范圍的支持，所以輸出的日志都會攜帶日志范圍的信息，日志范圍提供了很多有用的分布式跟蹤信息，比如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.Host}{request.PathBase}{request.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.TotalMilliseconds}ms {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($"\t{args.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監聽器獲取診斷日志