第19课：日志作用域：解决不同请求之间的日志干扰

学习分享 丨作者 / 郑 子 铭 丨公众号 / DotNet NB / CloudNative NB

开始之前先看一下上一节的代码

// 配置的框架
var configBuilder = new ConfigurationBuilder();
configBuilder.AddCommandLine(args);
configBuilder.AddJsonFile("appsettings.json", optional: false, reloadOnChange: true);

var config = configBuilder.Build();
IServiceCollection serviceCollection = new ServiceCollection();
serviceCollection.AddSingleton<IConfiguration>(p => config);

// 日志的框架
serviceCollection.AddLogging(builder =>
{
    builder.AddConfiguration(config.GetSection("Logging"));// 注册 Logging 配置的 Section
    builder.AddConsole();// 先使用一个 Console 的日志输出提供程序
    builder.AddDebug();
});

我们可以观察到配置的框架和日志的框架，它们的设计模式是很相似的

区别就是：

配置的框架是从不同的数据源读取数据并且供给我们结构化的数据可以读取

日志框架是用统一的记录方式，让我们可以把日志记录到不同的地方去，输出到不同的地方去

接下来演示一下关于日志的作用域的部分

日志作用域几个常用场景：

1、一个事务包含多条操作时：比如说在一个事务里面去操作的时候，会需要记录多条日志，需要把多条日志串联在一起，而不是记录成一行

2、复杂流程的日志关联时：比如说工作流流程里面去进入这个日志

3、调用链追踪与请求处理过程对应时：如果在调用链追踪过程中记录了多条日志，希望把日志串联在一起的时候，作用域就发挥了作用

主程序

namespace LoggingScopeDemo
{
    class Program
    {
        static void Main(string[] args)
        {
            var configBuilder = new ConfigurationBuilder();
            configBuilder.AddCommandLine(args);
            configBuilder.AddJsonFile("appsettings.json", optional: false, reloadOnChange: true);
            var config = configBuilder.Build();
            IServiceCollection serviceCollection = new ServiceCollection();
            serviceCollection.AddSingleton(p => config); //用工厂模式将配置对象注册到容器管理
            serviceCollection.AddLogging(builder =>
            {
                builder.AddConfiguration(config.GetSection("Logging"));
                builder.AddConsole();
                builder.AddDebug();
            });

            IServiceProvider service = serviceCollection.BuildServiceProvider();

            var logger = service.GetService<ILogger<Program>>();

            // 相当于记录了一条上下文串联的日志
            using (logger.BeginScope("ScopeId:{scopeId}", Guid.NewGuid()))
            {
                logger.LogInformation("这是Info");
                logger.LogError("这是Error");
                logger.LogTrace("这是Trace");
            }
        }
    }
}

新增配置文件 appsettings.json，右键属性，如果较新则复制

{
  "Logging": {
    "LogLevel": {
      "Default": "Debug",
      "Microsoft": "Warning",
      "Microsoft.Hosting.Lifetime": "Information"
    },
    "Console": {
      "IncludeScopes": false,
      "LogLevel": {
        "Default": "Information",
        "LoggingScopeDemo.Program": "Trace",
        "alogger": "Trace"
      }
    }
  }
}

启动程序，输出如下：

info: LoggingScopeDemo.Program[0]
      这是Info
fail: LoggingScopeDemo.Program[0]
      这是Error
trce: LoggingScopeDemo.Program[0]
      这是Trace

和之前一样的输出，接着修改配置文件

"IncludeScopes": true,

启动程序，输出如下：

info: LoggingScopeDemo.Program[0]
      => ScopeId:b8ef7682-6c6d-4f74-83c8-b9fd4613c623
      这是Info
fail: LoggingScopeDemo.Program[0]
      => ScopeId:b8ef7682-6c6d-4f74-83c8-b9fd4613c623
      这是Error
trce: LoggingScopeDemo.Program[0]
      => ScopeId:b8ef7682-6c6d-4f74-83c8-b9fd4613c623
      这是Trace

可以看到，日志里面有 scope，并且三条日志都包含了相同的 ScopeId，这个是由我们决定 Scope 的内容是什么，一般推荐使用一个唯一标识，比如 HTTP 请求的 id，或者是 session 的 id，或者是事务的 id

接着修改为循环

// 只要输入不是 Esc 就循环执行
while (Console.ReadKey().Key != ConsoleKey.Escape)
{
    // 相当于记录了一条上下文串联的日志
    using (logger.BeginScope("ScopeId:{scopeId}", Guid.NewGuid()))
    {
        logger.LogInformation("这是Info");
        logger.LogError("这是Error");
        logger.LogTrace("这是Trace");
    }
    Console.WriteLine("============分割线=============");
}
Console.ReadKey();

启动程序，输出如下：

info: LoggingScopeDemo.Program[0]
      => ScopeId:cc25dd86-d3fe-41e8-b607-61912c65bde7
      这是Info
============分割线=============
fail: LoggingScopeDemo.Program[0]
      => ScopeId:cc25dd86-d3fe-41e8-b607-61912c65bde7
      这是Error
trce: LoggingScopeDemo.Program[0]
      => ScopeId:cc25dd86-d3fe-41e8-b607-61912c65bde7
      这是Trace

这里可以看到分割线有点错乱，这是因为 Console 的提供程序实际上内部是用异步的方式在记录，那也就是这里遇到并发的问题

调整一下代码，让主线程休息一下

System.Threading.Thread.Sleep(100);
Console.WriteLine("============分割线=============");

这样子启动之后顺序就正确了

在程序启动的情况下，修改 Debug 目录下的配置文件

"IncludeScopes": false,

修改保存后在控制台输入回车，可以看到配置生效了，意味着可以使用配置热更新能力来动态修改配置的输出，调整配置输出的级别

比如将

"LoggingScopeDemo.Program": "Trace",

修改为

"LoggingScopeDemo.Program": "Error",

修改保存后在控制台输入回车，只会输出 Error 级别

GitHub源码链接：

https://github.com/MINGSON666/Personal-Learning-Library/tree/main/DotNetCoreDevelopmentActualCombat/LoggingScopeDemo

这是在控制台里面的效果，接下来看一下在一个 ASP.NET Core Web 应用下面的日志是什么样子

这是一个默认的工程，仅仅在应用程序里面加了两行代码

[HttpGet]
public async Task<IEnumerable<WeatherForecast>> Get()
{
    _logger.LogInformation("开始Get了");

    _logger.LogInformation("Get睡醒了");

    var rng = new Random();
    return Enumerable.Range(1, 5).Select(index => new WeatherForecast
    {
        Date = DateTime.Now.AddDays(index),
        TemperatureC = rng.Next(-20, 55),
        Summary = Summaries[rng.Next(Summaries.Length)]
    })
    .ToArray();

}

日志级别

"Console": {
      "IncludeScopes": true
    }

启动程序，输出如下：

info: LoggingDemo.Controllers.WeatherForecastController[0]
      => RequestPath:/weatherforecast RequestId:0HLU2MTQ99HO2:00000001, SpanId:|7bb9cb12-4a0fe499cae27707., TraceId:7bb9cb12-4a0fe499cae27707, ParentId: => LoggingDemo.Controllers.WeatherForecastController.Get (LoggingDemo)
      开始Get了
info: LoggingDemo.Controllers.WeatherForecastController[0]
      => RequestPath:/weatherforecast RequestId:0HLU2MTQ99HO2:00000001, SpanId:|7bb9cb12-4a0fe499cae27707., TraceId:7bb9cb12-4a0fe499cae27707, ParentId: => LoggingDemo.Controllers.WeatherForecastController.Get (LoggingDemo)
      Get睡醒了

可以看到，记录的 开始Get了 以及 Get睡醒了，都包含了 RequestPath，RequestId，SpanId，TraceId 这些信息，这些信息是当前请求的上下文

也就意味着可以在记录日志的时候，用请求上下文把日志串联起来，多个请求的日志可以区分开来，无论记录了多条还是单条

也就意味着可以在事务处理的过程中，复杂的流程的过程中，或者调用链的处理过程中，当然还有其他的场景任意的需要将多条日志串联起来的场景，都可以用作用域来实现这个能力

GitHub源码链接：https://github.com/MingsonZheng/DotNetCoreDevelopmentActualCombat/tree/main/LoggingDemo