ASP.NET Core 源碼學習之 Logging[1]:Introduction

在ASP.NET 4.X中，我們通常使用 log4net, NLog 等來記錄日志，但是當我們引用的一些第三方類庫使用不同的日志框架時，就比較混亂了。而在 ASP.Net Core 中內置了日志系統，並提供了一個統一的日志接口，ASP.Net Core 系統以及其它第三方類庫等都使用這個日志接口來記錄日志，而不關注日志的具體實現，這樣便可以在我們的應用程序中進行統一的配置，並能很好的與第三方日志框架集成。

注冊日志服務

ASP.NET Core 全部使用依賴注入，更好的規范我們的代碼。想要使用日志系統，首先要進行注冊和配置：

public void ConfigureServices(IServiceCollection services)  
{
    services.AddLogging(builder =>
    {
        builder
            .AddConfiguration(loggingConfiguration.GetSection("Logging"))
            .AddFilter("Microsoft", LogLevel.Warning)
            .AddConsole();
    });
}

如上，通過 AddLogging ，將日志系統注冊到了 DI 系統中，而 AddConfiguration 是對日志系統的全局配置， AddFilter 則是對日志過濾器的一些配置，最后 AddConsole 添加了一個 Console 的日志提供者（將日志輸出到控制台）。

記錄日志

在我們需要記錄日志的時候，只需要通過構造函數注入ILogger<T>就可以了：

public class TodoController : Controller
{
    private readonly ITodoRepository _todoRepository;
    private readonly ILogger _logger;

    public TodoController(ITodoRepository todoRepository, ILogger<TodoController> logger)
    {
        _todoRepository = todoRepository;
        _logger = logger;
    }

    [HttpGet]
    public IActionResult GetById(string id)
    {
        _logger.LogInformation(LoggingEvents.GET_ITEM, "Getting item {ID}", id);
        var item = _todoRepository.Find(id);
        if (item == null)
        {
            _logger.LogWarning(LoggingEvents.GET_ITEM_NOTFOUND, "GetById({ID}) NOT FOUND", id);
            return NotFound();
        }
        return new ObjectResult(item);
    }  
}

ILogger<T> 中的 T 表示日記的類別，在我們查看日志時，非常有用，在本文后面會講。

日志輸出示例

使用上面的示例代碼，當我們通過控制台來運行時，訪問 http://localhost:5000/api/todo/0 將會看到如下的日志輸出：

info: Microsoft.AspNetCore.Hosting.Internal.WebHost[1]
      Request starting HTTP/1.1 GET http://localhost:5000/api/todo/invalidid
info: Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker[1]
      Executing action method TodoApi.Controllers.TodoController.GetById (TodoApi) with arguments (invalidid) - ModelState is Valid
info: TodoApi.Controllers.TodoController[1002]
      Getting item invalidid
warn: TodoApi.Controllers.TodoController[4000]
      GetById(invalidid) NOT FOUND
info: Microsoft.AspNetCore.Mvc.StatusCodeResult[1]
      Executing HttpStatusCodeResult, setting HTTP status code 404
info: Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker[2]
      Executed action TodoApi.Controllers.TodoController.GetById (TodoApi) in 243.2636ms
info: Microsoft.AspNetCore.Hosting.Internal.WebHost[2]
      Request finished in 628.9188ms 404

如果我們訪問 http://localhost:55070/api/todo/0 ，將會看到：

Microsoft.AspNetCore.Hosting.Internal.WebHost:Information: Request starting HTTP/1.1 GET http://localhost:55070/api/todo/invalidid
Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker:Information: Executing action method TodoApi.Controllers.TodoController.GetById (TodoApi) with arguments (invalidid) - ModelState is Valid
TodoApi.Controllers.TodoController:Information: Getting item invalidid
TodoApi.Controllers.TodoController:Warning: GetById(invalidid) NOT FOUND
Microsoft.AspNetCore.Mvc.StatusCodeResult:Information: Executing HttpStatusCodeResult, setting HTTP status code 404
Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker:Information: Executed action TodoApi.Controllers.TodoController.GetById (TodoApi) in 12.5003ms
Microsoft.AspNetCore.Hosting.Internal.WebHost:Information: Request finished in 19.0913ms 404

通過這個示例，可以看到我們記錄到了 ASP.NET Core 框架自身的日志，這也是統一的日志框架才能實現的功能。

日志類別

我們創建的每一個日志器都指定了一個類別。它可以是任意的字符串，但是約定使用寫入類的完整限定名，如：“TodoApi.Controllers.TodoController”。如果要顯式的指定日志的種類，則可以使用 ILoggerFactory 中的 CreateLogger 方法：

public class TodoController : Controller
{
    private readonly ILogger _logger;

    public TodoController(ILoggerFactory logger)
    {
        _logger = logger.CreateLogger("TodoApi.Controllers.TodoController");
    }
}

不過，大多數時候，我們還是使用 ILogger<T>，更加方便：

public class TodoController : Controller
{
    private readonly ILogger _logger;

    public TodoController(ILogger<TodoController> logger)
    {
        _logger = logger;
    }
}

這等效於使用 T 類型的完整限定名來調用 CreateLogger 方法。

日志級別

在我們記錄日志時，需要指定日志的級別，這對我們過濾日志非常有用，比如在測試環境中，我們希望提供非常的詳細的日志信息，包括一些敏感信息等，但是在生產環境中，我們希望只記錄嚴重的錯誤，這時候只需要簡單的通過 AddFilter 對日志的過濾級別配置一下就行了。

ASP.NET Core Logging 系統提供了六個日志級別，通過增加重要性或嚴重程度排序如下：

• Trace 用於記錄最詳細的日志消息，通常僅用於開發階段調試問題。這些消息可能包含敏感的應用程序數據，因此不應該用於生產環境。默認應禁用。

• Debug 這種消息在開發階段短期內比較有用。它們包含一些可能會對調試有所助益、但沒有長期價值的信息。默認情況下這是最詳細的日志。

• Information 這種消息被用於跟蹤應用程序的一般流程。與 Verbose 級別的消息相反，這些日志應該有一定的長期價值。

• Warning 當應用程序出現錯誤或其它不會導致程序停止的流程異常或意外事件時使用警告級別，以供日后調查。在一個通用的地方處理警告級別的異常。

• Error 當應用程序由於某些故障停止工作則需要記錄錯誤日志。這些消息應該指明當前活動或操作（比如當前的 HTTP 請求），而不是應用程序范圍的故障。

• Critical 當應用程序或系統崩潰、遇到災難性故障，需要立即被關注時，應當記錄關鍵級別的日志。如數據丟失、磁盤空間不夠等。

日志事件ID

每次寫日志的時候，我們可以指定一個 event ID：

public class LoggingEvents
{
    public const int GET_ITEM = 1002;
    public const int GET_ITEM_NOTFOUND = 4000;
}

public IActionResult GetById(string id)
{
    _logger.LogInformation(LoggingEvents.GET_ITEM, "Getting item {ID}", id);
    var item = _todoRepository.Find(id);
    if (item == null)
    {
        _logger.LogWarning(LoggingEvents.GET_ITEM_NOTFOUND, "GetById({ID}) NOT FOUND", id);
        return NotFound();
    }
    return new ObjectResult(item);
}

event ID 是一個整數，它可以將一組日志事件關聯到一起。與日志類別類似，但是更加細化。而它的輸出取決於日志提供者，Console 提供者輸出格式如下，在日志類別后面，並用一對中括號包裹着：

info: TodoApi.Controllers.TodoController[1002]
      Getting item invalidid
warn: TodoApi.Controllers.TodoController[4000]
      GetById(invalidid) NOT FOUND

日志格式化字符串

每次記錄日志時，都會提供一條文本消息，而在這個消息字符串中，我們可以使用命名占位符：

public IActionResult GetById(string id)
{
    _logger.LogInformation(LoggingEvents.GET_ITEM, "Getting item {ID}", id);
    var item = _todoRepository.Find(id);
    if (item == null)
    {
        _logger.LogWarning(LoggingEvents.GET_ITEM_NOTFOUND, "GetById({ID}) NOT FOUND", id);
        return NotFound();
    }
    return new ObjectResult(item);
}

但是占位符的順序決定了使用哪個參數，而不是它的名字，如下示例：

string p1 = "parm1";
string p2 = "parm2";
_logger.LogInformation("Parameter values: {p2}, {p1}", p1, p2);

輸出結果為：

Parameter values: parm1, parm2

那這樣做有什么意義呢？

日志框架使用這種消息格式化方式，使日志提供者能夠實現 語義化日志，也稱結構化日志。因為參數本身被傳遞到日志系統中，而不僅僅是格式化的字符串，因此日志提供者可以將參數的值作為字段存儲單獨的存儲。比如：如果使用 Azure Table Storage，我們可以使用如下方法來記錄日志：

_logger.LogInformation("Getting item {ID} at {RequestTime}", id, DateTime.Now);

每一個 Azure Table 都可以有 ID 和 RequestTime 屬性，這將簡化對日志數據的查詢，你可以查找指定 RequestTime 范圍內的所有日志，而不必花費解析文本消息的開銷。

過濾器

過濾器可以讓你根據日志的級別和類別來選擇是輸出，還是忽略。我們可以為不同的日志提供者指定不同的過濾器，如下代碼所示，讓 Console 提供者忽略低於 warning 級別的日志，而 Debug 提供者則忽略 TodoApi 類別的日志。

public void Configure(IApplicationBuilder app, ILoggerFactory loggerFactory)
{
    loggerFactory
        .AddConsole(LogLevel.Warning)
        .AddDebug((category, logLevel) => (category.Contains("TodoApi") && logLevel >= LogLevel.Trace));
}

而我們還可以指定全局過濾器，作用於所有的日志提供者，如下示例，我們對於以 "Microsoft" 和 "System" 開頭的日志類別忽略掉低於 Warning 級別的日志：

public void Configure(IApplicationBuilder app, ILoggerFactory loggerFactory)
{
    loggerFactory
        .AddFilter("Microsoft", LogLevel.Warning)
        .AddFilter("System", LogLevel.Warning)
        .AddFilter("SampleApp.Program", LogLevel.Debug)
        .AddDebug();
}

作用域

我們可以將一組邏輯操作放在一個有序的 Scope 中，將 Scope 的標識附加到范圍內的所有日志中。例如，我們可以在處理事務的時候，使事務內的每一個操作日志都包含這個事務的ID。

使用ILgger.BeginScope<TState> 方法創建一個 Scope，並返回一個 IDisposable 類型，當我們 Dispose的時候，這個 Scope 也就結束了，非常適合於使用 using 的方式：

public IActionResult GetById(string id)
{
    TodoItem item;
    using (_logger.BeginScope("Message attached to logs created in the using block"))
    {
        _logger.LogInformation(LoggingEvents.GET_ITEM, "Getting item {ID}", id);
        item = _todoRepository.Find(id);
        if (item == null)
        {
            _logger.LogWarning(LoggingEvents.GET_ITEM_NOTFOUND, "GetById({ID}) NOT FOUND", id);
            return NotFound();
        }
    }
    return new ObjectResult(item);
}

每一個日志將包括 Scope 的信息：

info: TodoApi.Controllers.TodoController[1002]
      => RequestId:0HKV9C49II9CK RequestPath:/api/todo/0 => TodoApi.Controllers.TodoController.GetById (TodoApi) => Message attached to logs created in the using block
      Getting item 0
warn: TodoApi.Controllers.TodoController[4000]
      => RequestId:0HKV9C49II9CK RequestPath:/api/todo/0 => TodoApi.Controllers.TodoController.GetById (TodoApi) => Message attached to logs created in the using block
      GetById(0) NOT FOUND

總結

ASP.NET Core 提供了統一的日志框架，能方便地通過 Startup 類進行配置，靈活的集成第三方日志框架，並使用依賴注入的方式在應用程序中使用。本文整體的概述了一下 Logging 系統，在下一章中，會來分析一下 Logging 中配置的源碼。

參考微軟官方文檔：Introduction to Logging in ASP.NET Core