日志記錄不僅對于我們開發(fā)的應(yīng)用，還是對于ASP.NET Core框架功能都是一項非常重要的功能特性。我們知道ASP.NET Core使用的是一個極具擴展性的日志系統(tǒng)，該系統(tǒng)由Logger、LoggerFactory和LoggerProvider這三個核心對象組成。我們可以通過簡單的配置實現(xiàn)對LoggerFactory的定制，以及對LoggerProvider添加。

一、 配置LoggerFactory

我們在上面一節(jié)演示了一個展示ASP.NET Core默認(rèn)注冊服務(wù)的實例，細(xì)心的讀者一定會看到顯示的列表中就包含了針對LoggerFactory的服務(wù)。如果這個默認(rèn)的LoggerFactory服務(wù)不能滿足我們的需求，我們完全可以配置任何一個需要的LoggerFactory，針對LoggerFactory的設(shè)置可以直接調(diào)用WebHostBuilder的UseLoggerFactory方法來實現(xiàn)。

public interface IWebHostBuilder
  {
    IWebHostBuilder UseLoggerFactory(ILoggerFactory loggerFactory);
    IWebHostBuilder ConfigureLogging(Action<ILoggerFactory> configureLogging);
    ...
  }

不過針對日志的配置更多地還是體現(xiàn)在針對某種LoggerProvider的添加，而這可以通過調(diào)用WebHostBuilder的ConfigureLogging方法來完成。我們在上面演示的實例中就曾經(jīng)采用如下的方式將一個ConsoleLoggerProvider注冊到LoggerFactory之上，這樣我們可以直接在宿主應(yīng)用的擴展臺上看到記錄的日志信息。

 new WebHostBuilder()
    .ConfigureLogging(factory=>factory.AddConsole())
    ...

既然LoggerFactory已經(jīng)作為一個服務(wù)進行了注冊，那么我們完全按照依賴注入的來獲取這個對象，并利用它創(chuàng)建對應(yīng)的Logger對象來寫日志。如果我們需要在一個定義的中間件中寫入某種類型的日志，就可以按照如下的方式在Invoke方法中定義ILoggerFactory類型的參數(shù)注入這個LoggerFactory。

 public class FoobarMiddleware
  {
    private RequestDelegate _next;
   
    public FoobarMiddleware(RequestDelegate next)
    {
      _next = next;
    }
   
    public async Task Invoke(HttpContext context, ILoggerFactory loggerFactory)
    {
      ILogger<FoobarMiddleware> logger = loggerFactory.CreateLogger<FoobarMiddleware>();
      logger.LogInformation("...");
      await _next(context);
    }
  }

不僅僅我們開發(fā)的應(yīng)用或者中間件可以利用注冊的LoggerFactory來創(chuàng)建進行日志記錄的Logger對象，ASP.NET Core管道本身也會在處理請求過程中采用相同的方式記錄一些日志。比如管道每次處理請求的開始和結(jié)束時候分別會寫入兩條Information等級的日志，我們現(xiàn)在就來通過一個簡單的實例看看這兩條日志信息具有怎樣的內(nèi)容。

public class Program
  {
    public static void Main()
    {
      new WebHostBuilder()
        .ConfigureLogging(factory=>factory.AddConsole())
        .UseKestrel()
        .UseStartup<Startup>()        
        .Build()
        .Run();
    }
  }
  
  public class Startup
  {
    public void Configure(IApplicationBuilder app, ILoggerFactory loggerFactory)
    {
      app.Run(async context =>
      {
        loggerFactory.CreateLogger("App").LogInformation("Log entry for test...");
        await context.Response.WriteAsync("Hello world!");
      });
    }
  }

如上所示的代碼有兩處與日志有關(guān)，第一個地方是調(diào)用WebHostBuilder的ConfigureLogging方法通過調(diào)用擴展方法AddConsole將一個ConsoleProvider添加到當(dāng)前LoggerFactory之上，另一個地方就是啟動類的Configure方法注冊的中間件在執(zhí)行過程中會利用注入的LoggerFactory創(chuàng)建一個Logger對象，我們利用后者寫入了一條Information等級的日志。我們運行程序之后利用瀏覽器訪問目標(biāo)地址后，宿主控制臺上會出現(xiàn)如下圖所示的三條日志。除了第二條日志是由我們自己編寫的代碼寫入的之外，其余兩條都是ASP.NET Core框架自己寫入的。第一條日志包含不僅僅包含請求的目標(biāo)地址，還包括請求采用的協(xié)議（HTTP/1.1）和HTTP方法（GET），第三條則反映了整個請求處理過程所花的時間。

由于ASP.NET Core管道對請求的處理總是在一個由HttpApplication創(chuàng)建的執(zhí)行上下文中進行，所以上下文的創(chuàng)建和回收釋放可以視為 整個請求處理流程開始和結(jié)束的標(biāo)識。對于上述的這兩條分別在處理請求開始和結(jié)束時寫入的日志，實際上是在HostingApplication的CreateContext和DisposeContext方法分別被調(diào)用的時候被記錄下來的。之所以在結(jié)束的時候能夠計算出整個請求處理過程所花的時間，是因為創(chuàng)建的這個上下文對象保存了開始處理請求的時間戳，該時間戳對應(yīng)著Context結(jié)構(gòu)的StartTimestamp屬性。

 public class HostingApplication IHttpApplication<HostingApplication.Context>
  {
    public struct Context
    {
      public HttpContext   HttpContext { get; set; }
      public IDisposable   Scope { get; set; }
      public long     StartTimestamp { get; set; }
    }
  }

二、以當(dāng)前請求作為日志范圍

我們知道日志系統(tǒng)有一個叫做“日志范圍”的概念，它的目的在于為多次相關(guān)的日志記錄創(chuàng)建一個上下文范圍，并為這個范圍提供一個唯一標(biāo)識，這個標(biāo)識會作為日志內(nèi)容的一部分被寫入。當(dāng)我們在進行日志分析的時候，可以根據(jù)日志范圍標(biāo)識將一組原本獨立的日志關(guān)聯(lián)起來。這個概念對于Web應(yīng)用尤為重要，因為很多情況下我們所做的日志分析都是針對某一個請求，這就要求我們必須明確地分辨出被記錄下來的日志隸屬于哪一個請求，只有這樣才能將針對同一請求的所有日志提取出來做綜合的分析以得出一個準(zhǔn)確的結(jié)論。

從上個實例最終寫入的三條日志來看，它們并不攜帶當(dāng)前請求的標(biāo)識信息。但是這不是ASP.NET Core的問題，而是我們在調(diào)用LoggerFactory的擴展方法AddConsole注冊ConsoleLoggerProvider的時候并未顯式開啟針對日志范圍的支持。為了讓注冊的ConsoleLoggerProvider創(chuàng)建的Logger能夠支持日志范圍，我們只需按照如下的方式在調(diào)用AddConsole方法的時候添加一個額外的參數(shù)（true）即可。

 new WebHostBuilder()
    .ConfigureLogging(factory=>factory.AddConsole(true))
    .UseKestrel()
    .UseStartup<Startup>()        
    .Build()
    .Run();

我們再次請求應(yīng)用并利用瀏覽器對目標(biāo)地址發(fā)送兩次請求，六條寫入的日志將會以如下圖所示的形式輸出到控制臺上。不同于上面的輸出結(jié)果，本次輸出的日志包含請求的ID（Request Id），在同一個請求下被記錄下來的日志具有相同的ID。除了請求ID，記錄的日志還攜帶了請求的路徑（Request Path）。

日志范圍攜帶的用于唯一標(biāo)識當(dāng)前請求的ID，同時也可以視為當(dāng)前HttpContext的唯一標(biāo)識，它對應(yīng)著HttpContext的TranceIdentifier屬性。對于DefaultHttpContext來說，針對這個屬性的讀寫是借助一個名為HttpRequestIdentifierFeature的特性實現(xiàn)的，下面的代碼提供了該對象對應(yīng)的接口IHttpRequestIdentifierFeature和默認(rèn)實現(xiàn)類HttpRequestIdentifierFeature的定義。

public abstract class HttpContext
  {
    //省略其他成員
    public abstract string TraceIdentifier { get; set; }
  }
   
  public interface IHttpRequestIdentifierFeature
  {
    string TraceIdentifier { get; set; }
  }
  
  public class HttpRequestIdentifierFeature IHttpRequestIdentifierFeature
  {
    private string _id;
    private static long _requestId = DateTime.UtcNow.Ticks;
    private static unsafe string GenerateRequestId(long id);
    public string TraceIdentifier
    {
      get
      {
        return _id??(id= GenerateRequestId(Interlocked.Increment(ref _requestId)));
      }
      set
      {
        this._id = value;
      }
    }
  }

HttpRequestIdentifierFeature生成TraceIdentifier的邏輯很簡單。如上面的代碼片斷所示，它具有一個靜態(tài)長整型字段_requestId，其初始值為當(dāng)前時間戳。對于某個具體的HttpRequestIdentifierFeature對象來說，它的TraceIdentifier屬性的默認(rèn)值返回的是這個字段_requestId加1之后轉(zhuǎn)換的字符串。具體的轉(zhuǎn)換邏輯定義在GenerateRequestId方法中，它會采用相應(yīng)的算法 將指定的整數(shù)轉(zhuǎn)換一個長度為13的字符串。

和開始請求處理的時間戳一樣，被創(chuàng)建出來的日志范圍實際被保存在HostingApplication的上下文對象中，它對應(yīng)著Context結(jié)構(gòu)的Scope屬性。當(dāng)HostingApplication創(chuàng)建這個Context對象的時候，它會從當(dāng)前HttpContext中提取出請求的ID和路徑，創(chuàng)建出這個日志范圍并賦值給這個屬性。整個請求的處理其實就在這個日志范圍中進行，請求處理結(jié)束，當(dāng)前日志范文也被回收釋放。

 public class HostingApplication IHttpApplication<HostingApplication.Context>
  {
    public struct Context
    {
      public HttpContext   HttpContext { get; set; }
      public IDisposable   Scope { get; set; }
      public long      StartTimestamp { get; set; }
    }
  }

三、記錄異常日志

由于ASP.NET Core在處理請求過程中導(dǎo)致的異常并不會導(dǎo)致應(yīng)用終止，考慮到安全，拋出的異常的詳細(xì)信息也不應(yīng)該直接返回到客戶端。所以在很多情況下我們根本感知不到應(yīng)用發(fā)生了異常，即使感知到了，也不知道導(dǎo)致異常的根源在何處。在這種情況下，我們就需要使用記錄的日志進行差錯和糾錯，因為ASP.NET Core在處理請求遇到的異常都會記錄到日志中。

比如針對如下這段程序，毫無疑問它針對任何一個請求的處理都會拋出一個DivideByZeroException的異常。如果我們利用瀏覽器來訪問站點地址，它只會得到一個狀態(tài)為500的響應(yīng)，并簡單的提示服務(wù)端出現(xiàn)錯誤。對于宿主程序來說，我們根本就是感知不到任何異常發(fā)生。

 new WebHostBuilder()
    .UseKestrel()
    .Configure(app=>app.Run(async context=> {
      int x = 1;
      int y = 0;
      await context.Response.WriteAsync((x / y).ToString());
    }))
    .Build()
  .Run();

在這種情況下我們可以通過查看日志得到異常的詳細(xì)信息，不過在這之前必須為LoggerFactory注冊相應(yīng)的LoggerProvider。如果我們采用控制臺應(yīng)用作為宿主，在開發(fā)或者調(diào)試的時候最簡單的莫過于按照如下的方式注冊一個ConsoleLoggerProvider讓日志可以直接寫入宿主程序的控制臺。

 new WebHostBuilder()
    .ConfigureLogging(factory=>factory.AddConsole (true))
    .UseKestrel()
    .Configure(app=>app.Run(async context=> {
      int x = 1;
      int y = 0;
      await context.Response.WriteAsync((x / y).ToString());
    }))
    .Build()
    .Run();

一旦為LoggerFactory注冊了這么一個ConsoleLoggerProvider，對于服務(wù)端出現(xiàn)的未處理的任何異常，我們都可以直接在宿主控制臺上看到錯誤的詳細(xì)信息，下圖就是上面這個例子拋出的DivideByZeroException異常的詳細(xì)信息。

以上就是本文的全部內(nèi)容，希望對大家的學(xué)習(xí)有所幫助，也希望大家多多支持腳本之家。