总结:利用asp.net core日志进行生产环境下的错误排查,asp.net core version 2.2,用IIS做服务器

概述

调试asp.net core程序时,在输出窗口中,在输出来源选择“调试”或“xxx-ASP.NET Core Web服务器”时,可以看到类似“info:Microsoft.AspNetCore.Hosting.Internal.WebHost[2] Request finished in 285.6ms 200 text/css”这样的内容,这就是asp.net core的日志。如果出现了未捕获的异常,在输出窗口中可以看到出错信息,如:fail: Microsoft.AspNetCore.Server.Kestrel[13]……An unhandled exception was thrown by the application. System.NullReferenceException: 未将对象引用设置到对象的实例。在……行号 xx 在……行号 xx。在网站运行过程中,如果可以把这些出错信息保存下来,就可以排查代码错误了。方法很简单:把web.config文件中aspNetCore标签的stdoutLogEnabled属性设置为true,这样,在网站运行后,默认会在/logs文件夹下产生一个stdout_xxx_xxx.log的文件,日志会保存到这里面。

logging provider

从名称“stdoutLogEnabled”来看,stdout,表示“标准输出”,即控制台输出。试着写一句Console.WriteLine(xxx),在.log文件中果然就可以看到输出的内容。如果是在调试环境,可以在输出窗口/ASP.NET Core Web服务器看到Console输出的内容。asp.net core mvc项目代码模板默认添加了三个logging provider:Console、Debug、EventSource。VS的输出窗口/ASP.NET Core Web服务器,显示的就是Console这个logging provider输出的内容,而输出窗口/调试,显示的是Debug的。所以,stdout_xxx_xxx.log文件,保存的就是Console logging provider输出的日志。

观察VS的输出窗口,可以发现,同一条日志内容,Console和Debug这两个logging provider的输出格式是不同的。

日志级别

ASP.NET Core定义了几个日志级别,表示日志的严重程度,从低到高分别是Trace 、Debug 、Information 、Warning 、Error 、Critical 。

下面是一条Debug级别的日志:

dbug: Microsoft.AspNetCore.Mvc.ModelBinding.ParameterBinder[27]
      Done attempting to validate the bound parameter 'page' of type 'System.Int32'.

一条Information级别的日志:

info: Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker[1]
      Executing action method XXX.Controllers.YYYController.GetList (XXX) with arguments (8d35e231-c928-479e-95d4-b305a6a235eb, 1, 15, 1) - Validation state: Valid

在生产环境下,日志一般仅用于错误排查,所以用不到Information 等级别的大量日志,为此,可以设置一个最低日志级别,比如设置成Warning,将屏蔽Trace 、Debug 、Information级别的日志。最低日志级别可以给每个logging provider分别设置,如果没有具体设置,将采用默认设置。如,设置默认日志级别为Information:

"Logging": {
    "LogLevel": {
      "Default": "Information"
    }
  }

分别设置Debug、Console的日志级别:

  "Logging": {
    "Debug": {
      "LogLevel": {
        "Default": "Information"
      }
    },
    "Console": {
      "LogLevel": {
        "Default": "Debug"
      }
    },
    "LogLevel": {
      "Default": "Debug"
    }
  },

为什么针对具体的logging provider也标上"Default"?因为可以再针对日志的Log category分别设置:

  "Logging": {
    "Console": {
      "LogLevel": {
        "Microsoft.AspNetCore.Mvc.Razor.Internal": "Warning",
        "Microsoft.AspNetCore.Mvc.Razor.Razor": "Debug",
        "Microsoft.AspNetCore.Mvc.Razor": "Error",
        "Default": "Information"
      }
    },
    "LogLevel": {
      "Default": "Debug"
    }
  }

关于Log category的概念请自行查阅官方文档,不再赘述。

值得注意的时,在网站运行状态下,修改appsettings.json中的上述配置,不会造成网站重启(而修改web.config会造成网站重启),但对日志级别的控制会立即生效。所以,在网站运行不正常时,可以临时调低日志级别,以查看更多调试信息,又不会影响用户的使用。平时可以设置一个较高的日志级别,比如Error或Critical。而web.config中的stdoutLogEnabled属性要提前设置好。

输出自己的日志

可以输出自己的日志。用依赖注入的方式,注入ILogger<T>对象,然后用LogInformation()、LogWarning()等方法可以方便的输出对应级别的日志。

示例代码:

    public class HomeController : Controller
    {
        ILogger<HomeController> _logger;

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

        public IActionResult Index()
        {
            _logger.LogInformation("访问主页");
try { int i = 0; int j = 1 / i; } catch (Exception ex) { _logger.LogWarning($"发生异常了:{ex.Message},调用堆栈:{ex.StackTrace}"); }
throw new Exception("这是一个测试错误"); return View(); } }

产生的部分日志(级别设置为Information):

info: CommonCoreMvcTest.Controllers.HomeController[0]
      访问主页
warn: CommonCoreMvcTest.Controllers.HomeController[0]
      发生异常了:尝试除以零。,调用堆栈:   在 CommonCoreMvcTest.Controllers.HomeController.Index() 位置 E:\xxx\Test\CommonCoreMvcTest\Controllers\HomeController.cs:行号 28
fail: Microsoft.AspNetCore.Diagnostics.ExceptionHandlerMiddleware[1]
      An unhandled exception has occurred while executing the request.
System.Exception: 这是一个测试错误
   在 CommonCoreMvcTest.Controllers.HomeController.Index() 位置 E:\xxx\Test\CommonCoreMvcTest\Controllers\HomeController.cs:行号 36
   在 lambda_method(Closure , Object , Object[] )
   在 Microsoft.AspNetCore.Mvc.Internal.ActionMethodExecutor.SyncActionResultExecutor.Execute(IActionResultTypeMapper mapper, ObjectMethodExecutor executor, Object controller, Object[] arguments)
   在 Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker.<InvokeActionMethodAsync>d__12.MoveNext()
--- 引发异常的上一位置中堆栈跟踪的末尾 ---
……

添加web.config到源代码项目中

新建的asp.net core 2.2项目,默认没有web.config文件。得在网站发布后才能修改产生的web.config文件内容吗?没必要,可以通过“添加”、“新建项”、“Web配置文件”的方式,手动添加web.config文件到源码项目中。

使日志包含时间

asp.net core的日志不包含时间,这是个大问题,在3.0版本后,Console log provider可以配置时间格式了。经过搜索,我发现一个好用的第三方log provider:LoggingAdvanced.Console。可以用它来取代Console log provider。具体步骤如下:

1、安装nuget包LoggingAdvanced.Console

2、修改Program.cs的CreateWebHostBuilder方法,在其中的方法调用链的最后,调用ConfigureLogging方法,修改后的代码如下:

public static IWebHostBuilder CreateWebHostBuilder(string[] args) =>
            WebHost.CreateDefaultBuilder(args)
                .UseStartup<Startup>()
                .ConfigureLogging((hostingContext, loggingBuilder) =>
                 {
                     loggingBuilder.ClearProviders();//清除所有logging provider

                     loggingBuilder.AddDebug();//恢复添加Debug logging provider

                     loggingBuilder.AddEventSourceLogger();//恢复添加EventSource logging provider

                     var loggingSection = hostingContext.Configuration.GetSection("Logging");

                     loggingBuilder.AddConsoleAdvanced(loggingSection);//添加LoggingAdvanced.Console logging provider
                 });

3、修改appsettings.json的中的Logging部分,修改后如下:

"Logging": {
    "IncludeTimestamp": true,
    "IncludeLogNamespace": true,
    "TimestampPolicy": {
      "TimeZone": "Ulaanbaatar Standard Time",
      "Format": "yyyy/MM/dd HH:mm:ss.fff"
    },
    "LogLevel": {
      "Default": "Warning"
    }
  }

输出的部分日志:

[2020.03.07 22:39:36] info: HomeController: 访问主页
[2020.03.07 22:39:36] warn: HomeController: 发生异常了:尝试除以零。,调用堆栈:   在 CommonCoreMvcTest.Controllers.HomeController.Index() 位置 E:\xxx\Test\CommonCoreMvcTest\Controllers\HomeController.cs:行号 28
[2020.03.07 22:39:36] fail: ExceptionHandlerMiddleware[1]: An unhandled exception has occurred while executing the request.
System.Exception: 这是一个测试错误
   在 CommonCoreMvcTest.Controllers.HomeController.Index() 位置 E:\xxx\Test\CommonCoreMvcTest\Controllers\HomeController.cs:行号 36
   在 lambda_method(Closure , Object , Object[] )
   在 Microsoft.AspNetCore.Mvc.Internal.ActionMethodExecutor.SyncActionResultExecutor.Execute(IActionResultTypeMapper mapper, ObjectMethodExecutor executor, Object controller, Object[] arguments)
   在 Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker.<InvokeActionMethodAsync>d__12.MoveNext()
……

技巧

用浏览器查看.log文件,日志有更新,刷新一下就好了。

参考资料

1、Logging in .NET Core and ASP.NET Core

2、LoggingAdvanced.Console