日志記錄不僅對於我們開發的應用，還是對於ASP.NET Core框架功能都是一項非常重要的功能特性。我們知道ASP.NET Core使用的是一個極具擴展性的日志系統，該系統由Logger、LoggerFactory和LoggerProvider這三個核心對象組成。我們可以通過簡單的配置實現對LoggerFactory的定制，以及對LoggerProvider添加。
一、 配置LoggerFactory
我們在上面一節演示了一個展示ASP.NET Core默認注冊服務的實例，細心的讀者一定會看到顯示的列表中就包含了針對LoggerFactory的服務。如果這個默認的LoggerFactory服務不能滿足我們的需求，我們完全可以配置任何一個需要的LoggerFactory，針對LoggerFactory的設置可以直接調用WebHostBuilder的UseLoggerFactory方法來實現。
public interface IWebHostBuilder
{
IWebHostBuilder UseLoggerFactory(ILoggerFactory loggerFactory);
IWebHostBuilder ConfigureLogging(Action<ILoggerFactory> configureLogging);
...
}
不過針對日志的配置更多地還是體現在針對某種LoggerProvider的添加，而這可以通過調用WebHostBuilder的ConfigureLogging方法來完成。我們在上面演示的實例中就曾經采用如下的方式將一個ConsoleLoggerProvider注冊到LoggerFactory之上，這樣我們可以直接在宿主應用的擴展台上看到記錄的日志信息。
new WebHostBuilder()
.ConfigureLogging(factory=>factory.AddConsole())
...
既然LoggerFactory已經作為一個服務進行了注冊，那麼我們完全按照依賴注入的來獲取這個對象，並利用它創建對應的Logger對象來寫日志。如果我們需要在一個定義的中間件中寫入某種類型的日志，就可以按照如下的方式在Invoke方法中定義ILoggerFactory類型的參數注入這個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);
}
}
不僅僅我們開發的應用或者中間件可以利用注冊的LoggerFactory來創建進行日志記錄的Logger對象，ASP.NET Core管道本身也會在處理請求過程中采用相同的方式記錄一些日志。比如管道每次處理請求的開始和結束時候分別會寫入兩條Information等級的日志，我們現在就來通過一個簡單的實例看看這兩條日志信息具有怎樣的內容。
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!");
});
}
}
如上所示的代碼有兩處與日志有關，第一個地方是調用WebHostBuilder的ConfigureLogging方法通過調用擴展方法AddConsole將一個ConsoleProvider添加到當前LoggerFactory之上，另一個地方就是啟動類的Configure方法注冊的中間件在執行過程中會利用注入的LoggerFactory創建一個Logger對象，我們利用後者寫入了一條Information等級的日志。我們運行程序之後利用浏覽器訪問目標地址後，宿主控制台上會出現如下圖所示的三條日志。除了第二條日志是由我們自己編寫的代碼寫入的之外，其余兩條都是ASP.NET Core框架自己寫入的。第一條日志包含不僅僅包含請求的目標地址，還包括請求采用的協議（HTTP/1.1）和HTTP方法（GET），第三條則反映了整個請求處理過程所花的時間。
由於ASP.NET Core管道對請求的處理總是在一個由HttpApplication創建的執行上下文中進行，所以上下文的創建和回收釋放可以視為 整個請求處理流程開始和結束的標識。對於上述的這兩條分別在處理請求開始和結束時寫入的日志，實際上是在HostingApplication的CreateContext和DisposeContext方法分別被調用的時候被記錄下來的。之所以在結束的時候能夠計算出整個請求處理過程所花的時間，是因為創建的這個上下文對象保存了開始處理請求的時間戳，該時間戳對應著Context結構的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; }
}
}
二、以當前請求作為日志范圍
我們知道日志系統有一個叫做“日志范圍”的概念，它的目的在於為多次相關的日志記錄創建一個上下文范圍，並為這個范圍提供一個唯一標識，這個標識會作為日志內容的一部分被寫入。當我們在進行日志分析的時候，可以根據日志范圍標識將一組原本獨立的日志關聯起來。這個概念對於Web應用尤為重要，因為很多情況下我們所做的日志分析都是針對某一個請求，這就要求我們必須明確地分辨出被記錄下來的日志隸屬於哪一個請求，只有這樣才能將針對同一請求的所有日志提取出來做綜合的分析以得出一個准確的結論。
從上個實例最終寫入的三條日志來看，它們並不攜帶當前請求的標識信息。但是這不是ASP.NET Core的問題，而是我們在調用LoggerFactory的擴展方法AddConsole注冊ConsoleLoggerProvider的時候並未顯式開啟針對日志范圍的支持。為了讓注冊的ConsoleLoggerProvider創建的Logger能夠支持日志范圍，我們只需按照如下的方式在調用AddConsole方法的時候添加一個額外的參數（true）即可。
new WebHostBuilder()
.ConfigureLogging(factory=>factory.AddConsole(true))
.UseKestrel()
.UseStartup<Startup>()
.Build()
.Run();
我們再次請求應用並利用浏覽器對目標地址發送兩次請求，六條寫入的日志將會以如下圖所示的形式輸出到控制台上。不同於上面的輸出結果，本次輸出的日志包含請求的ID（Request Id），在同一個請求下被記錄下來的日志具有相同的ID。除了請求ID，記錄的日志還攜帶了請求的路徑（Request Path）。
日志范圍攜帶的用於唯一標識當前請求的ID，同時也可以視為當前HttpContext的唯一標識，它對應著HttpContext的TranceIdentifier屬性。對於DefaultHttpContext來說，針對這個屬性的讀寫是借助一個名為HttpRequestIdentifierFeature的特性實現的，下面的代碼提供了該對象對應的接口IHttpRequestIdentifierFeature和默認實現類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的邏輯很簡單。如上面的代碼片斷所示，它具有一個靜態長整型字段_requestId，其初始值為當前時間戳。對於某個具體的HttpRequestIdentifierFeature對象來說，它的TraceIdentifier屬性的默認值返回的是這個字段_requestId加1之後轉換的字符串。具體的轉換邏輯定義在GenerateRequestId方法中，它會采用相應的算法 將指定的整數轉換一個長度為13的字符串。
和開始請求處理的時間戳一樣，被創建出來的日志范圍實際被保存在HostingApplication的上下文對象中，它對應著Context結構的Scope屬性。當HostingApplication創建這個Context對象的時候，它會從當前HttpContext中提取出請求的ID和路徑，創建出這個日志范圍並賦值給這個屬性。整個請求的處理其實就在這個日志范圍中進行，請求處理結束，當前日志范文也被回收釋放。
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在處理請求過程中導致的異常並不會導致應用終止，考慮到安全，拋出的異常的詳細信息也不應該直接返回到客戶端。所以在很多情況下我們根本感知不到應用發生了異常，即使感知到了，也不知道導致異常的根源在何處。在這種情況下，我們就需要使用記錄的日志進行差錯和糾錯，因為ASP.NET Core在處理請求遇到的異常都會記錄到日志中。
比如針對如下這段程序，毫無疑問它針對任何一個請求的處理都會拋出一個DivideByZeroException的異常。如果我們利用浏覽器來訪問站點地址，它只會得到一個狀態為500的響應，並簡單的提示服務端出現錯誤。對於宿主程序來說，我們根本就是感知不到任何異常發生。
new WebHostBuilder()
.UseKestrel()
.Configure(app=>app.Run(async context=> {
int x = 1;
int y = 0;
await context.Response.WriteAsync((x / y).ToString());
}))
.Build()
.Run();
在這種情況下我們可以通過查看日志得到異常的詳細信息，不過在這之前必須為LoggerFactory注冊相應的LoggerProvider。如果我們采用控制台應用作為宿主，在開發或者調試的時候最簡單的莫過於按照如下的方式注冊一個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，對於服務端出現的未處理的任何異常，我們都可以直接在宿主控制台上看到錯誤的詳細信息，下圖就是上面這個例子拋出的DivideByZeroException異常的詳細信息。
以上就是本文的全部內容，希望對大家的學習有所幫助，也希望大家多多支持腳本之家。
