ASP.NET Core 1.0基础之日志

过年出去玩了一圈,回来继续翻译。前两天偷懒没有翻译,只是转了两篇C# 7计划中的新features,大家还是很支持的。现在继续完善这个系列。

来源https://docs.asp.net/en/latest/fundamentals/logging.html

ASP.NET Core 1.0提供了内置的日志模块,当然开发者也能使用自己偏爱的日志框架。使用日志模块的化,需要现在应用中添加很少的一点setup 代码。做完这些,你就可以在应用中随处可以添加日志啦。

在应用中实现日志模块##

通过依赖注入请求ILoggerFactory或者ILogger可以添加日志到应用中的模块中。如果请求的是ILoggerFactory那么logger必须使用它的CreateLogger方法来创建。如下展示了如何在在Startup类中的Configure方法中进行设置。

public void Configure(IApplicationBuilder app,
    IHostingEnvironment env,
    ILoggerFactory loggerFactory)
{
    loggerFactory.AddConsole(minLevel:LogLevel.Verbose);

    app.UseStaticFiles();

    app.UseMvc();

    // Create a catch-all response
    app.Run(async (context) =>
    {
        var logger = loggerFactory.CreateLogger("Catchall Endpoint");
        logger.LogInformation("No endpoint found for request {path}", context.Request.Path);
        await context.Response.WriteAsync("No endpoint found - try /api/todo.");
    });

logger创建时必须提供category名字。该名字指定了日志事件的来源。按照约定名字是分层级的,category是由dot(.)来分开的。利用这项约定,一些日志provider有过滤功能,这样就可以更方便的定位日志。如上例子,logging配置成使用内置的ConsoleLogger。你可以运行命令行web命令,请求配置好的url(localhost:5000),就可以ConsoleLogger在运行的。输出类似下图。
ASP.NET Core 1.0基础之日志

如上,当每次使用浏览器请求时,会在Console中看到多条日志记录,因为大部分浏览器会在加载网页时发出多次请求的。注意到Console logger显示的info类型的日志,并且日志信息是显示在category [Catchall Endpoint]之后的。
log方法调用可以使用带有命名占位符的格式化字符串,这些占位符可以按顺序填充调用时传给方法的参数。一些logging provider会将参数名和对应的值作为字典存储起来以备稍后使用。如下例子,请求路径作为命名占位符传进来。

var logger = loggerFactory.CreateLogger("Catchall Endpoint");
logger.LogInformation("No endpoint found for request {path}", context.Request.Path);

在实际应用中,你可能想添加应用层级的日志,而不是框架层级的日志。例如,你创建了Web Api项目来管理To-Do项目,你可能需要对于针对todo项目的各种操作来记录日志。
假设API的逻辑是在TodoController内,它通过构造器注入来请求服务。理想情况下,类应该像该例子中的一样,使用构造器来显式定义他们的依赖参数。而不是显式的请求ILoggerFactory并创建ILogger实例。TodoController显示了另一种在应用中使用logger的方式,你可以请求ILogger(这里T是请求logger的类)。

[Route("api/[controller]")]
public class TodoController : Controller
{
    private readonly ITodoRepository _todoRepository;
    private readonly ILogger<TodoController> _logger;

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

    [HttpGet]
    public IEnumerable<TodoItem> GetAll()
    {
        _logger.LogInformation(LoggingEvents.LIST_ITEMS, "Listing all items");
        EnsureItems();
        return _todoRepository.GetAll();
    }

在controller内的每个action内,是通过类内的私有字段_logger来写日志的。这种方法不仅可以用在Congroller内,也可以通过依赖注入在应用中的其他服务中使用。

使用ILogger##

如上所示,在应用中,可以通过类构造器来请求ILogger,其中T是执行日志记录的类。TodoController中就是该方法的一个例子。使用这项技术时,logger是自动使用类型的名字作为category的名字。通过请求ILogger实例,类就不需要使用ILoggerFactory来创建logger实例。你可以在任何地方使用这种方式,只要你不需要ILoggerFactory提供的其他额外的功能。

日志级别##

在应用中添加日志时,必须指定LogLevel。LogLevel允许你控制应用的日志输出,以及将不同类型的日志输入到不同的logger。例如,你可能希望将debug日志输出到本地文件,但是输出错误到machine event log或者数据库。

ASP.NET Core 1.0定义了6中不同级别。
Debuge
适用于最详细的日志信息,尤其对开发者在进行debug时特别有用。这些信息可能包含应用敏感信息,因此在生产环境是不应该使用的。默认是Disabled的。敏感信息如Credentials: {"User":"someuser", "Password":"P@ssword"}
Verbose
这种类型的信息是在开发中临时有用的。可能包含了对debug有用的信息,但是没有长期价值。这是大部分日志默认的级别。例如Entering method Configure with flag set to true。
Infomation
这种信息用来追踪应用的一般流程(General flow)。这些日志应该具有长期价值。例如Request received for path /foo
Warning
Warning级别用于记录应用程序流程中反常的未预期的事件。它可能包含了一些错误,也可能是一些并没有引起程序down的但是需要在未来进行处理的情况。处理异常通常使用Warning级别的日志。例如Login failed for IP 127.0.0.1 or FileNotFoundException for file foo.txt。
Error
由于某些错误,应用程序的当前流程必须停止时,需要记录Error级别的日志,比如未处理或不能恢复的异常。这些信息标识当前活动或操作(比如当前http请求)出现失败,而不是application-wide层级的错误。
Critical
Critical日志用来记录uncoverable应用和系统错误,或者需要立马处理的灾难性的错误。例如data loss scenarios, stack overflows, out of disk space。

Logging包对这些标准的日志级别提供了一些helper扩展方法,允许你调用LogInformation而不是更verbose的Log方法(如LogLeve.Infomation)。每种LogeLevel特定的扩展方法有几个重载,允许你传递如下参数的一些或者全部。

string data
log信息。
int eventId
日志相关的数字Id,用来关联日志事件。事件Id应该是static的,针对特定的类型的日志事件。例如,你可以把事件id 1000关联到添加物品到购物车的事件,而完成购买的事件则是关联到1001的Id。这允许智能过滤和process of log statement。
string format
格式化的log信息。
object[] args
需要格式化的对象数组。
Exception Error
需要记录的异常实例。

Note: 一些logger,比如内置的ConsoleLogger,会忽略eventId。如果你需要显示它,你需要将它包含在message字符串中。接下来的例子中,就是这种做法,你可以轻易的看到eventId关联到每个信息,但是实际中你可能不会将其包含在log message中。

在TodoController的例子中,对每个事件定义一个事件id常量,log statements are configured at the appropriate verbosity level based on the success of the operation。在本例中,成功操作的日志级别为Information,未找到的操作日记记录为Warning级别(未显示错误处理)。

[HttpGet]
    public IEnumerable<TodoItem> GetAll()
    {
        _logger.LogInformation(LoggingEvents.LIST_ITEMS, "Listing all items");
        EnsureItems();
        return _todoRepository.GetAll();
    }

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

Note: 推荐在应用级别和它的API级别记录日志,而不是框架级别。框架已经有了内置的日志,可以通过合适的日志verbosity level来开启。

为了看更详细的框架级别的日志,你可以调整你的logging provider的LogLevel为更verbose的层级(如Debug或者Verbose)。例如,如果在Configure方法修改AddConsole调用为LogLevel.Verbose,然后运行程序,会显示更多框架级别的请求相关的详细信息。
ASP.NET Core 1.0基础之日志

The console logger prefixes verbose output with “verbose: ” and uses a gray font to make it easier to distinguish it from other levels of log output.

Scopes##

在应用程序中记录日志时,你可以把一个scope内的一系列逻辑相关的操作分为一个group。scope是由调用BeginScopeImpl方法返回的IDisposable类型,它从创建持续到Dispose。内置的 TraceSource logger 就返回一个scope实例,它负责开始和结束tracing操作。任何日志状态,如trnsaction id,都在scope创建时附加进来。

scope并不是必须的,如果使用的话,应该节俭的使用。它应该针对那些有明显开始和结束的操作来使用,如涉及多个资源的事务。

在应用中配置日志##

在ASP.NET应用中配置日志,你应该在Startup类中的Configure方法中解析ILoggerFacotry。当添加该类型的参数到Configure方法中,ASP.NET会自动通过依赖注入提供一个ILoggerFactory实例。一旦你添加了ILoggerFactory 作为参数,你可以在Configure方法中,通过调用loggerfactory的扩展方法来配置logger。在本文初,我们已经看到这样的一个例子,其中我们通过调用loggerFacotry.AddConsole添加了一个Console logging。除了添加logger,我们还可以通过loggerfacotry的MinimumLevel属性来控制应用中日志的verbosity级别。默认的verbosity是Verbose。
Note:对于每个特定的logger provider你也可以指定日志minimum级别。例如,AddConsole扩展方法支持可选参数来设置它的minimum日志级别。

配置TraceSource日志###

内置的 TraceSourceLogger provier提供一种简单的方式利用当前的System.Diagnostics.TraceSource库和provider来配置记录日志信息,包括接入windows event log。这种已证明的将信息路由到不同的listeners,已经被广泛使用。TraceSourceLogger 可以让开发者来使用这种方法。

首先,确保在项目的Project.json中添加了Microsoft.Extensions.Logging.TraceSource包。

"dependencies": {
    "Microsoft.AspNet.Mvc": "6.0.0-rc1-final",
    "Microsoft.AspNet.Server.Kestrel": "1.0.0-rc1-final",
    "Microsoft.AspNet.StaticFiles": "1.0.0-rc1-final",
    "Microsoft.Extensions.Logging": "1.0.0-rc1-final",
    "Microsoft.Extensions.Logging.Console": "1.0.0-rc1-final",
    "Microsoft.Extensions.Logging.TraceSource": "1.0.0-rc1-final"
  },

如下例子显示了如何在应用中配置两个相互独立的TraceSourceLogger实例,两个都是记录critical级别的信息。每次调用AddTraceSource 方法都接收一个TraceListener。第一个调用配置了ConsoleTraceListener。第二个配置了EventLogTraceListener,来写应用事件日志。这两个listener在DNX Core中都是不可用的,因此这些配置是包含的条件编译中的。

            loggerFactory.MinimumLevel = LogLevel.Debug;
#if DNX451
            var sourceSwitch = new SourceSwitch("LoggingSample");
            sourceSwitch.Level = SourceLevels.Critical;
            loggerFactory.AddTraceSource(sourceSwitch,
                new ConsoleTraceListener(false));
            loggerFactory.AddTraceSource(sourceSwitch,
                new EventLogTraceListener("Application"));
#endif

如上例子也展示了设置logger factory的MinimumLevel。然而,这只是对新的facotry的简单默认设置,仍然可以被单独的配置logger来重写的。在本例中,sourceSwitch配置为SourceLevels.Critical,所以只有critical的信息才会被两个listener所收集。

为了测试代码,用如下代码替代catch-all响应。

app.Run(async context =>
{
        if (context.Request.Path.Value.Contains("boom"))
        {
                throw new Exception("boom!");
        }
        await context.Response.WriteAsync("Hello World!");
});

之后,当程序在windows上运行时,请求路径为http://localhost:5000/boom,控制台将输出如下。
ASP.NET Core 1.0基础之日志

在Windows Event Viewer中查看应用事件日志,如下事件会在本次请求后被记录。
ASP.NET Core 1.0基础之日志

除了使用TraceSourceLogger,你也可以利用 EventLog logging provider直接将日志记录到event log中。使用Debug logging provider可以支持使用System.Diagnostics.Debug.WriteLine来记录日志,其输出可以在vs的OutPut window中看到。

配置其他的provider###

除了内置的logger,你也可以使用别的provider配置logging。添加合适的包到project.json中,然后像其他provider一样进行配置。一般情况下,这些包应该包括ILoggerFactory的扩展方法,以便于方便添加他们。
Note:目前ASP.NET团队在和第三方logging provider合作,来支持这种logging model。 Once these ship, we will include links to them here。

当然你也可以创建自己的provider,来支持别的logging框架或者自己内部的需求。

日志记录推荐做法##

如下是一些推荐做法,当在ASP.NET应用中实施日志时会带来帮助。

  1. 使用正确的LogLevel来记录日志。这样可以基于日志的重要程度来合适的消费和路由日志。
  2. 避免记录冗余或无关的日志,而是记录可以快速定位错误的日志。
  3. 保持日志精简而不牺牲重要的信息。
  4. 尽管在disabled的情况下logger不会工作,consider adding code guards around logging methods to prevent extra method calls and log message setup overhead, especially within loops and performance critical methods。
  5. 使用唯一的前缀来命名logger,这样他们能被方便的filtered和disabled。记住Create会创建已类型的全名来命名的logger。
  6. 保守的使用scope,仅仅针对有明确开始和结束的操作来使用。例如,框架针对MVC action提供了scope。避免在scope中嵌套较多的scope。
  7. 应用日志代码应该与应用程序的业务关注点相关管。提高logging verbosity来显示额外的框架级别的关注点,而不是实现自己的。

总结##

ASP.NET提供了内置的对日志的支持,可以在Startup类中方便配置,然后在整个应用中使用。Logging verbosity can be configured globally and per logging provider to ensure actionable information is logged appropriately. Built-in providers for console and trace source logging are included in the framework; other logging frameworks can easily be configured as well.