日誌記錄不僅對於我們開發的應用,還是對於ASP.NET Core框架功能都是一項非常重要的功能特性。我們知道ASP.NET Core使用的是一個極具擴充套件性的日誌系統,該系統由Logger、LoggerFactory和LoggerProvider這三個核心物件組成。我們可以通過簡單的配置實現對LoggerFactory的定製,以及對LoggerProvider新增。 [ 本文已經同步到《ASP.NET Core框架揭祕》之中]

目錄
一、 配置LoggerFactory
二、以當前請求作為日誌範圍
三、記錄異常日誌

一、 配置LoggerFactory

我們在上面一節演示了一個展示ASP.NET Core預設註冊服務的例項,細心的讀者一定會看到顯示的列表中就包含了針對LoggerFactory的服務。如果這個預設的LoggerFactory服務不能滿足我們的需求,我們完全可以配置任何一個需要的LoggerFactory,針對LoggerFactory的設定可以直接呼叫WebHostBuilder的UseLoggerFactory方法來實現。

   1: public interface IWebHostBuilder
   2: {
   3:     IWebHostBuilder UseLoggerFactory(ILoggerFactory loggerFactory);
   4:     IWebHostBuilder ConfigureLogging(Action<ILoggerFactory> configureLogging);
   5:     ...
   6: }
.

不過針對日誌的配置更多地還是體現在針對某種LoggerProvider的新增,而這可以通過呼叫WebHostBuilder的ConfigureLogging方法來完成。我們在上面演示的例項中就曾經採用如下的方式將一個ConsoleLoggerProvider註冊到LoggerFactory之上,這樣我們可以直接在宿主應用的擴展臺上看到記錄的日誌資訊。

   1: new WebHostBuilder()
   2:     .ConfigureLogging(factory=>factory.AddConsole())
   3:     ...

既然LoggerFactory已經作為一個服務進行了註冊,那麼我們完全按照依賴注入的來獲取這個物件,並利用它建立對應的Logger物件來寫日誌。如果我們需要在一個定義的中介軟體中寫入某種型別的日誌,就可以按照如下的方式在Invoke方法中定義ILoggerFactory型別的引數注入這個LoggerFactory。

   1: public class FoobarMiddleware
   2: {
   3:     private RequestDelegate _next;
   4:  
   5:     public FoobarMiddleware(RequestDelegate next)
   6:     {
   7:         _next = next;
   8:     }
   9:  
  10:     public async Task Invoke(HttpContext context, ILoggerFactory loggerFactory)
  11:     {
  12:         ILogger<FoobarMiddleware> logger = loggerFactory.CreateLogger<FoobarMiddleware>();
  13:         logger.LogInformation("...");
  14:         await _next(context);
  15:     }
  16: }

不僅僅我們開發的應用或者中介軟體可以利用註冊的LoggerFactory來建立進行日誌記錄的Logger物件,ASP.NET Core管道本身也會在處理請求過程中採用相同的方式記錄一些日誌。比如管道每次處理請求的開始和結束時候分別會寫入兩條Information等級的日誌,我們現在就來通過一個簡單的例項看看這兩條日誌資訊具有怎樣的內容。

   1: public class Program
   2: {
   3:     public static void Main()
   4:     {
   5:         new WebHostBuilder()
   6:             .ConfigureLogging(factory=>factory.AddConsole())
   7:             .UseKestrel()
   8:             .UseStartup<Startup>()                
   9:             .Build()
  10:             .Run();
  11:     }
  12: }
  13:  
  14: public class Startup
  15: {
  16:     public void Configure(IApplicationBuilder app, ILoggerFactory loggerFactory)
  17:     {
  18:         app.Run(async context =>
  19:         {
  20:             loggerFactory.CreateLogger("App").LogInformation("Log entry for test...");
  21:             await context.Response.WriteAsync("Hello world!");
  22:         });
  23:     }
  24: }

如上所示的程式碼有兩處與日誌有關,第一個地方是呼叫WebHostBuilder的ConfigureLogging方法通過呼叫擴充套件方法AddConsole將一個ConsoleProvider新增到當前LoggerFactory之上,另一個地方就是啟動類的Configure方法註冊的中介軟體在執行過程中會利用注入的LoggerFactory建立一個Logger物件,我們利用後者寫入了一條Information等級的日誌。我們執行程式之後利用瀏覽器訪問目標地址後,宿主控制檯上會出現如下圖所示的三條日誌。除了第二條日誌是由我們自己編寫的程式碼寫入的之外,其餘兩條都是ASP.NET Core框架自己寫入的。第一條日誌包含不僅僅包含請求的目標地址,還包括請求採用的協議(HTTP/1.1)和HTTP方法(GET),第三條則反映了整個請求處理過程所花的時間。

6

由於ASP.NET Core管道對請求的處理總是在一個由HttpApplication建立的執行上下文中進行,所以上下文的建立和回收釋放可以視為 整個請求處理流程開始和結束的標識。對於上述的這兩條分別在處理請求開始和結束時寫入的日誌,實際上是在HostingApplication的CreateContext和DisposeContext方法分別被呼叫的時候被記錄下來的。之所以在結束的時候能夠計算出整個請求處理過程所花的時間,是因為建立的這個上下文物件儲存了開始處理請求的時間戳,該時間戳對應著Context結構的StartTimestamp屬性。

   1: public class HostingApplication : IHttpApplication<HostingApplication.Context>
   2: {
   3:     public struct Context
   4:     {
   5:         public HttpContext      HttpContext { get; set; }
   6:         public IDisposable      Scope { get; set; }
   7:         public long          StartTimestamp { get; set; }
   8:     }
   9: }

二、以當前請求作為日誌範圍

我們知道日誌系統有一個叫做“日誌範圍”的概念,它的目的在於為多次相關的日誌記錄建立一個上下文範圍,併為這個範圍提供一個唯一標識,這個標識會作為日誌內容的一部分被寫入。當我們在進行日誌分析的時候,可以根據日誌範圍標識將一組原本獨立的日誌關聯起來。這個概念對於Web應用尤為重要,因為很多情況下我們所做的日誌分析都是針對某一個請求,這就要求我們必須明確地分辨出被記錄下來的日誌隸屬於哪一個請求,只有這樣才能將針對同一請求的所有日誌提取出來做綜合的分析以得出一個準確的結論。

從上個例項最終寫入的三條日誌來看,它們並不攜帶當前請求的標識資訊。但是這不是ASP.NET Core的問題,而是我們在呼叫LoggerFactory的擴充套件方法AddConsole註冊ConsoleLoggerProvider的時候並未顯式開啟針對日誌範圍的支援。為了讓註冊的ConsoleLoggerProvider建立的Logger能夠支援日誌範圍,我們只需按照如下的方式在呼叫AddConsole方法的時候新增一個額外的引數(true)即可。

   1: new WebHostBuilder()
   2:     .ConfigureLogging(factory=>factory.AddConsole(true))
   3:     .UseKestrel()
   4:     .UseStartup<Startup>()                
   5:     .Build()
   6:     .Run();

我們再次請求應用並利用瀏覽器對目標地址傳送兩次請求,六條寫入的日誌將會以如下圖所示的形式輸出到控制檯上。不同於上面的輸出結果,本次輸出的日誌包含請求的ID(Request Id),在同一個請求下被記錄下來的日誌具有相同的ID。除了請求ID,記錄的日誌還攜帶了請求的路徑(Request Path)。

7

日誌範圍攜帶的用於唯一標識當前請求的ID,同時也可以視為當前HttpContext的唯一標識,它對應著HttpContext的TranceIdentifier屬性。對於DefaultHttpContext來說,針對這個屬性的讀寫是藉助一個名為HttpRequestIdentifierFeature的特性實現的,下面的程式碼提供了該物件對應的介面IHttpRequestIdentifierFeature和預設實現類HttpRequestIdentifierFeature的定義。

   1: public abstract class HttpContext
   2: {
   3:     //省略其他成員
   4:     public abstract string TraceIdentifier { get; set; }
   5: }
   6:  
   7: public interface IHttpRequestIdentifierFeature
   8: {
   9:     string TraceIdentifier { get; set; }
  10: }
  11:  
  12: public class HttpRequestIdentifierFeature : IHttpRequestIdentifierFeature
  13: {
  14:     private string _id;
  15:     private static long _requestId = DateTime.UtcNow.Ticks;
  16:     private static unsafe string GenerateRequestId(long id);
  17:     public string TraceIdentifier
  18:     {
  19:         get
  20:         {
  21:             return _id??(id= GenerateRequestId(Interlocked.Increment(ref _requestId)));
  22:         }
  23:         set
  24:         {
  25:             this._id = value;
  26:         }
  27:     }
  28: }

HttpRequestIdentifierFeature生成TraceIdentifier的邏輯很簡單。如上面的程式碼片斷所示,它具有一個靜態長整型欄位_requestId,其初始值為當前時間戳。對於某個具體的HttpRequestIdentifierFeature物件來說,它的TraceIdentifier屬性的預設值返回的是這個欄位_requestId加1之後轉換的字串。具體的轉換邏輯定義在GenerateRequestId方法中,它會採用相應的演算法 將指定的整數轉換一個長度為13的字串。

和開始請求處理的時間戳一樣,被創建出來的日誌範圍實際被儲存在HostingApplication的上下文物件中,它對應著Context結構的Scope屬性。當HostingApplication建立這個Context物件的時候,它會從當前HttpContext中提取出請求的ID和路徑,創建出這個日誌範圍並賦值給這個屬性。整個請求的處理其實就在這個日誌範圍中進行,請求處理結束,當前日誌範文也被回收釋放。

   1: public class HostingApplication : IHttpApplication<HostingApplication.Context>
   2: {
   3:     public struct Context
   4:     {
   5:         public HttpContext     HttpContext { get; set; }
   6:         public IDisposable     Scope { get; set; }
   7:         public long            StartTimestamp { get; set; }
   8:     }
   9: }

三、記錄異常日誌

由於ASP.NET Core在處理請求過程中導致的異常並不會導致應用終止,考慮到安全,丟擲的異常的詳細資訊也不應該直接返回到客戶端。所以在很多情況下我們根本感知不到應用發生了異常,即使感知到了,也不知道導致異常的根源在何處。在這種情況下,我們就需要使用記錄的日誌進行差錯和糾錯,因為ASP.NET Core在處理請求遇到的異常都會記錄到日誌中。

比如針對如下這段程式,毫無疑問它針對任何一個請求的處理都會丟擲一個DivideByZeroException的異常。如果我們利用瀏覽器來訪問站點地址,它只會得到一個狀態為500的響應,並簡單的提示服務端出現錯誤。對於宿主程式來說,我們根本就是感知不到任何異常發生。

0.001291036605835