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

語言: CN / TW / HK

很多人可能對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監聽器獲取診斷日誌