ch05 使用日志来记录错误

Using Logging to Identity Errors

本章介绍 .NET 所提供的的日志功能. 日志模块必不可少, 开发中用于调试程序, 生产中可发现问题所在. ASP.NET 中已内置日志模块.

本章会解除到:

• 探究 .NET 中的日志模块
• 使用日志框架
• 使用 Serilog 保存结构化日志

技术要求 (略)

与前面几章一样.

探索 .NET 中的日志

ASP.NET Core 模板创建 WebApplicationBuilder 和 WebApplication 对象, 使用这种简化的方法来配置和运行程序, 而不需要使用 startup 类.

日志有很多级别, 可以按照不同级别进行配置产生日志. 有四个内置的 provider 可以跟踪程序运行的信息.

• Console. 提供在控制台显示日志. 在生产环境中没太大作用. 因为没法在运行的过程中时实时察控制台. 这个 provider 适用于开发环境.
• Debug. 该 provider 使用 System.Diagnotics.Debug 类来处理日志. 这个 VS 的输出窗口会展示日志. 在 Linux 上, 会将日志写入 /var/log/message 和 /var/log/syslog 中.
• EventSource. 可以在 Win 的系统事件中查看.
• EventLog. 只支持 win 系统.

最新 .NET 的新特性

有新的扩展方法来支持新的日志场景:

• AddSystemConsole
• AddJsonConsole
• AddSimpleConsole

ASP.NET 的基础设置可以参考文档.

在开始之前, 我们需要了解日志层是什么, 这是一个基本概念. 有助于我们将不同信息置于不同的日志层.

日志级别	描述含义
Trace	包含大多数细节信息. 如果在 Debug 中不足以描述问题的时候, 可以使用它. 不应在生产环境中使用. 在生产环境中启用会消耗大量的性能, 同时考虑到收集大量信息, 也不利于代码的维护.
Debug	用于调试与开发环境. 该消息不应该用于生产环境. 该日志级别对于开发者很重要, 例如应用程序状态, 数据等. 该级别的日志跟踪应用程序调试信息, 对于验证应用程序状态极为重要.
Information	跟踪应用的一般流程. 消息可能被中长时间存储. 该信息一般用于程序运行的分析, 需要可以被查询显示.
Warning	意外事件. 意外事件包括应用程序忽略的行为, 逻辑或数据的错误等. 应用程序不会崩溃, 但是它没有正确的运行.
Error	表示应用程序错误或异常. 并非应用程序错误.
Critical	显示应用程序失败. 该消息必须被操作员处理.
None	该级别不会生成消息.

要了解更为详细信息, 可以参考文档.

如果我们将日志级别设置为 Information, 那么所有日志会被记录到 Critical 级别. 而 Trace 和 Debug 会被忽略.

配置 logging

开始之前需要一些预备知识. 每一个日志对象 (ILogger<T>) 都需要一个所属的分类. 每一个日志分类有助于对日志信息进行分类. 例如在分配好分类后, 可以直接配置启用分类, 即可完成日志记录的调整.

逻辑上与基于角色控制访问一样, 配置启用角色, 那么挂载到角色下的权限就可以使用.

分类就是 T 类, 可以将与对应类相关的日志记录在对应的分类中. 只需要从依赖注入服务中注入对应的实例即可.

一旦定义好了分类, 就可以直接调用对应实例的公共方法进行日志记录了. 下面看一个示例:

首先在 Program.cs 文件中定义一个 record 类型:

internal record CategoryFiltered();

这里不局限于 record 类型, 也可以是其他类类型.

这个类型定义在 Program.cs 文件中, 且没有命名空间. 在定义 appsettings 的时候需要记住这一点. 如果带有命名空间, 那么我们需要使用全名 (完整名字, 带有命名空间的). 例如:

namespace LoggingSamples.Categories;
public class MyCategoryAlert {
  
}

那么就需要使用 LoggingSamples.Categories.MyCategoryAlert 这个名字.

如果没有指明分类, 按下面的示例, 选中的 log level 为默认级别:

"Logging": {
  "LogLevel": {
    "Default": "Information",
    "Microsoft.AspNetCore": "Warning",
    "CategoryFiltered": "Information",
    "LoggingSamples.Categories.MyCategoryAlert": "Debug"
  }
}

任何包含基础结构的日志, 例如 Microsoft logs, 都属于特殊类别, 例如 Microsoft.AspNetCore 或者 Microsoft.EntityFrameworkCore.

完整的 Microsoft log 可以在这里找到信息.

jk: 这里有些不知云云

有时需要基于跟踪的 provider 来定义必须的 log. 例如, 开发过程中, 我们需要在控制台看到所有的日志, 但是在日志文件中只需要记录错误日志.

要实现这个功能不用修改代码, 只需要配置每一个 provider 的 level. 下面示例中展示了, 在 Information 层中展示所有 Microsoft 分类中的信息:

{
  "Logging": { // Default, 所有 provider
    "LogLevel": {
      "Microsoft": "Warning"
    },
    "Console": { // Console Provider
      "LogLevel": {
        "Microsoft": "Infomation"
      }
    }
  }
}

配置已经介绍完, 下面来看怎么在 Minimal API 中使用.

下面我们注入了两个 ILogger 的实例, 一般不会这么使用, 但是为了解释其原理这么写:

app.MapGet("/first-log", 
           (ILogger<CategoryFiltered> loggerCategory, ILogger<MyCategforyAlert> loggerAlertCategory) => {
  loggerCategory.LogInfomation("I'm information {MyName}", "My Name Information");
  loggerAlertCategory.LogInformation("I'm information {MyName}", "Alert Information");
  return Results.Ok();
}).WithName("GetFirstLog");

这里使用了两个类别的日志实例, 日志使用一个模板来显示数据. 即带有占位符的是模板字符串. 如果需要控制某些日志分类不显示, 不用修改代码, 直接修改配置即可.

jk: 这里有很多背景没有解释的很清楚. 至少 Provider 没解释清楚.

简单小结一下:

• 日志需要分类, 即使用类型就可以
• 日志有很多方法你可以调用, 但是每一个方法有一个优先级
• 使用 LogLevel 配置即可控制什么分类的日志, 什么级别的方法起作用

自定义日志消息

消息是一个模板字符串, 模板使用 花括号 + 名字 来定义. 而日志中的占位符是从左往右依次由对象填充的.

可以简单理解 按照顺序编号, 而占位符中的名字仅仅是一个标识符, 没有占位的含义.

例如:

string apples = "apples";
string pears = "pears";
string bananas = "bananas";
logger.LogInformation("My fruit box has: {pears}, {bananas}, {apples}", apples, pears, bananas);

会显示出:

My fruit box has: apples, pears, bananas

基础设置日志

Infrastructure logging

这里介绍一下鲜为人知, 很少用到的主题: W3C log.

这个是用于所有 Web Server 的标准. 不单单是 IIS. 甚至是 Nginx 或其他 Linux 上的服务器也适用该标准.

该日志侧重于基础设置, 例如在那个端点调用了多少次等.

本节为会介绍如何将跟踪记录与文件中. 这个功能需要花点时间, 但支持更为复杂的场景.

我们需要一些工具来维护, 例如 OpenTelemetry

OpenTelemetry 是一个工具集, 它包含很多 API 和 SDK. 我们使用它来配置, 生成, 收集, 以及导出测量数据 (包括数据记录, 日志, 以及痕迹等). 细节可以参考 官网.

配置 W3C 日志, 使用 AddW3CLogging 方法来配置所有的可用选项.

启用则使用 UseW3CLogging 即可.

记录日志的代码不用更改.

builder.Services.AddW3CLogging(logging => {
  logging.LoggingFields = W3CLoggingFields.All;
});
...
app.UseW3CLogging();
...
app.MapGet("/first-w3c-log", (IWebHostEnvironment webHostEnvironment) => {
  return Results.Ok(new { PathToWrite = webHostEnvironment.ContentRootPath });
}).WithName("GetW3CLog");

会在对应目录下生成一个 logs 的文件夹

Source Generators

.NET6 中带有源代码生成器, 可以在编译期生成可执行代码来优化性能. 即在编译期生成可执行代码, 然后将其与运行时代码性能比较.

这个看起来有些高深

字符串插值使用 $"", 比起 string.Format 更自然易读. 但是在编写日志时不要这么使用.

虽然结果与之前推荐的方式一样, 但存在一些弊端:

• 失去了结构化日志, 无法使用格式来过滤, 从而获得消息.
• 类似的, 丢失了常量消息模板, 来定位消息.
• 数据的格式化发生在消息传入之前.
• 无论消息级别是否可用, 都会完成序列化.

不晓得是不是整理的问题, 实话没明白其意义何在, 但搞明白了一点, 就是模板消息可以保证级别无用的时候, 不会对数据进行序列化处理, 从而减少性能损失. 另外似乎可以起到一个分类过滤的作用. 但怎么分类过滤就不清楚了.

格式化日志模板似乎在编译期, 和执行期都有一些处理. 比起直接生成日志字符串更加有利(调错, 与性能).

.NET 6 中的 LoggerMessage 会自动生成日志必要的数据. 要使用该语法, 需要定义部分类或静态类, 在类中需要定义各种日志方法.

builder.Services.AddScoped<LogGenerator>();
...
public record Person {}
...
public partial class LogGenerator {
    readonly ILogger<Person> _logger;

    public LogGenerator(ILogger<Person> logger) => _logger = logger;

    [LoggerMessage(
        EventId = 100,
        EventName = "名字",
        Level = LogLevel.Debug,
        Message = "测试来用 {time}"
    )]
    public partial void LogSome(DateTime time);
}

注意, 这里还需要配合 appsettings 中的 LogLevel 来使用.

需要设置 csproj 文件, <EmitCompilerGeneratedFiles>true</EmitCompilerGeneratedFiles> 可以查看生成的代码.

jk 这个细节还是需要数理一下

使用日志框架

框架内置了一些 provider, 而不用添加其他包. 下面来介绍如何使用这些 provider, 并介绍如何自定义. 我们仅介绍 Console log provider. 其他类型的 provider 用法是类似的.

Console log

Console log provider 在开发过程中使用的是最多的. 其原因之一是它可以获得很多信息, 并收集所有的错误.

在 .NET 6 中该 provider 可以使用 AddJsonConsole provider 来添加. 其功能与 Console 一样, 但是以格式化 Json 的形式展示.

下面是案例:

builder.Logging.AddJsonConsole(opts => {
  opts.JSONWriterOptions = new JsonWriterOPtions() {
    Indented = true
  };
});

然后使用

app.MapGet("/first-log", 
           (ILogger<CategoryFiltered> loggerCategory, ILogger<MyCategoryAlert> loggerAlertCategory) => {
  loggerCategory.LogInfomation("I'm information {MyName}", "My Name Information");
  loggerCategory.LogDebug("I'm Debug {MyName}", "My Name Debug");
  loggerCategory.LogInformation("I'm Debug {Data}", new PayloadData("CategoryRoot", "Debug"));
  
  loggerAlertCategory.LogInformation("I'm information {MyName}", "Alert Information");
  loggerAlertCategory.LogDebug("I'm debug {MyName}", "Alert Debug");
  loggerAlertCategory.LogDebug("I'm debug {Data}", new PayloadData("AlertDebug", "Debug"));
  
  return Results.Ok();
}).WithName("GetFirstLog");

日志不在是一个一行的文本, 换成了一个结构化的 JSON 格式的数据. 将消息模板, 和填入的数据, 以及消息级别与 Layer 均进行了划分.

最后需要重要提点一下, 这里的日志不会对对象进行序列化, 只是显示类型的名字而已.

如果是类, 仅显示类名; 如果使用 record 类型, 还是会打印出属性值的. (与 ToString 方法有关)

这样的输出规则受限于 Provider 的实现. 所以推荐使用结构化日志工具. 例如 NLog, log4net, Serilog 等. 下面做简要介绍.

使用之前描述的两个 provider 输出前面的内容为:

• 第一个展示了格式化为 JSON 的日志, 将一些细节通过传统控制台进行输出.
• 另一个则是默认的 Console Provider 输出.

我们希望介绍如何创建适合程序的自定义 Provider 来输出日志

创建自定义 provider

微软在设计日志框架时就考虑到了扩展. 下面我们看如何自定义 provider.

那么, 为什么要自定义 provider? 一是可以不依赖于第三方库, 而是为了更好的管理性能. 总而言之就是为了更好的适配应用场景.

下面的示例中, 展示了用最少组件来创建 logging provider 所代理的好处.

provider 的其中一个功能即为配置. 我们创建一个类, 在程序启动时来展示 appsettings 的信息.

在案例中我们定义 EventId 来验证每日滚动日志文件的逻辑, 以及写入文件的路径.

public class FileLoggerConfiguration {
  public int EventId { get; set; }
  public string PathFolderName { get; set; } = "logs";
  public bool IsRollingFile { get; set; }
}

我们所编写的自定义 provider 描述了写入日志文本文件的信息. 这一点在我们实现 log 类之后会体现出来. 我们称之为 FileLogger, 它实现了 ILogger 接口.

在类的处理中, 我们所要做的就是实现 log 方法, 并在检查需要写入信息的文件.

我们将目录校验放在下一个文件中, 将所有的处理逻辑放在该方法中. 我们需要确保 log 方法在运行程序的过程中不会抛出异常. logger 不应该影响到程序的稳定性:

public class FileLogger: ILogger {
  private readonly string name;
  private readonly Func<FileLoggerConfiguration> getCurrentConfig;
  
  public FileLogger(string name, Func<FileLoggerCOnfiguration> getCurrentConfig) {
    this.name = name;
    this.getCurrentConfig = getCurrentConfig;
  }
  
  public IDisposable BeginScope<TState>(TState state) => default!;
  
  public bool IsEnabled(LogLevel logLevel) => true;
  
  public void Log<TState>(
    LogLevel logLevel, 
    EventId eventId, 
    TState state, 
    Exception? exception, 
    Func<TState, Exception?, string> formatter
  ) {
    if (!IsEnabled(logLevel)) {
      return;
    }
    var config = getCurrentConfig();
    if (config.EventId == 0 || config.EventId == eventId.id) {
      string line = $"{name} - {foramtter(state, exception)}";
      string fileName = config.IsRollingFIle ? RollingFileName : FullFileName;
      string fullPath = Path.Combine(config.PathFolderName, fileName);
      File.AppendAllLines(fillPath, new[] { line });
    }
  }
  
  private static string RollingFileName => 
    $"log-{DateTime.UtcNow:yyyy-MM-dd}.text";
  private static string FullFileName = "log.txt";
}

下面需要实现 ILoggerProvider 接口. 它会决定如何创建 logger 类的实例.

该类中会校验文件夹路径, 同时会监视 appsettings 文件的变化, 使用的是 IOptionsMonitor<T>:

public class FileLoggerProvider: ILoggerProvider {
  private readonly IDisposable onChangeToken;
  private FileLogConfiguration currentConfig;
  private readonly ConcurrentDirectory<string, FileLogger> _logger = new();
  
  public FileLoggerProvider(IOptionsMonitor<FileLoggerConfiguration> config) {
    currentConfig = config.CurrentValue;
    CheckDirectory();
    onChangeToken = config.OnChange(updateConfig => {
      currentConfig = updateCOnfig;
      CheckDirectory();
    })
  }
  
  public ILogger CreateLogger(string categoryName) {
    return _loggers
      .GetOrAdd(categoryName, name => new FileLogger(name, () => currentConfig));
  }
  
  public void Dispose() {
    _loggers.Clear();
    onChangeToken.Dispose();
  }
  
  private void CheckDirectory() {
    if (!Directory.Exists(currentConfig.PathFolderName)) {
      Directory.CreateDirectory(currentConfig.PathFolderName);
    }
  }
}

最后在程序启动时使用它, 也可以将其定义成扩展方法来使用.

AddFile 方法会注册 ILoggerProvider, 并会启用该配置. 虽然简单, 但包含了核心的用法.

public static class FileLoggerExtensions {
  public static ILoggerBuilder AddFile(this ILoggerBuilder builder) {
    builder.AddConfiguration();
    builder.Services.TryAddEnumerable(
      ServiceDescriptor.Singleton<ILoggerProvider, FileLoggerProvider>()
    );
    LoggerProviderOptions
      .RegisterProviderOptions<FileLoggerConfiguration, FileLoggerProvider>(
        builder.Services
      );
    return builder;
  }
  
  public static ILoggerBuilder AddFile(
    this ILoggingBuilder builder, 
    Action<FileLoggerConfiguration> configure) 
  {
    builder.AddFile();
    builder.Services.Configure(configure);
    return builder;
  }
}

使用方法为:

builder.Logging.AddFile(configuration => {
  configuration.PathFolderName = Path.Combine(builder.Environment.ContentRootPath, "logs");
  configuration.IsRollingFile = true;
});

其日志显示结果为:

这里没有异常信息, 如果需要记录异常信息, 需要重写 ILogger 的 formatter 来实现对象的序列化.

这里介绍了如何自定义 Provider 来创建结构化日志, 并发送到服务或存储中. 下一步介绍如何使用 Azure 的 Application Insights, 它对日志记录与应用程序监控非常友好.

Application Insights (略)

通过 Serilog 来存储结构化日志

基本略, 知道这个工具包即可. 书是基于 Azure 来介绍的, 在没有使用的经验下, 暂不考虑.

结构化日志对理解错误非常重要.

我们推荐使用 Serilog.

Serilog 是一个综合框架, 其中已经预制了很多模块, 用于记录日志, 以及后期查询.

Serilog 是一个日志框架, 它允许你在多个数据源中跟踪信息. 在 Serilog 中数据源被称为 Sink. 它允许你在日志中写入结构化的数据, 并对数据进行序列化.

下面看看如何使用, 这里作者使用两个源, 一个 Console, 一个是 Application Insight. 不巧, 第二个暂时不用.

<PackageReference Include="Microsoft.ApplicationInsights.AspNetCore" Version="2.20.0" />
<PackageReference Include="Serilog.AspNetCore" Version="4.1.0" />
<PackageReference Include="Serilog.Settings.Configuration" Version="3.3.0" />
<PackageReference Include="Serilog.Sinks.ApplicationInsights" Version="3.1.0" />

• 第一个包是 ApplicationInsights 需要的 SDK.
• 第二个包是 Serilog 包, 用于在程序中注册与使用 Serilog.
• 第三个包是用于在配置文件中对 Serilog 进行配置的依赖库, 这样不用每次配置都修改代码, 重新编译.
• 最后一个包用于添加 ApplicationInsights sink.

猜测需要的核心库为: Serilog.AspNetCore 以及 Serilog.Settings.Configuration.

• 在 appsettings 文件中, 创建 Serilog 节点.
• 使用 Using 节点来注册各种 sink.
• 同时还注册了其他数据 (怎么用, 其实不清楚)

"Serilog": {
  "Using": [ "Serilog.Sinks.Console", "Serilog.Sinks.ApplicationInsights" ],
  "MinimumLevel": "Verbose",
  "WriteTo": [
    {"Name": "Console"},
    {
      "Name": "ApplicationInsights", 
      "Args": {
        "restrictedToMinimumLevel": "Infomation",
        "telemetryConverter": "Serilog.Sinks.ApplicationInsights.Sinks.ApplicationInsights.TelemetryConverter.TraceTelemetryConverter,Serilog.Sinks.ApplicationInsights"
      }
    }
  ],
  "Enrich": ["FromLogContext"],
  "Properties": {
    "Application": "MinimalApi.Packt"
  }
}

现在只需要在 ASP.NET 管道中注册 Serilog 即可:

using Microsoft.ApplicationInsights.Extensibility;
using Serilog;
var builder = WebApplication.CreateBuilder(args);

builder.Logging.AddSerilog();
builder.Services.AddApplicationInsightsTelemetry();

var app = builder.Build();
Log.Logger = new LoggerConfiguration()
  .WriteTo
  .ApplicationInsights(app
                       .Services
                       .GetRequiredService<TelemetryConfiguration>(),
                       TelemetryConverter.Traces)
  .CreateLogger();

然后作者对代码进行了解释. 略.

使用时, 使用 @ 来提供占位符:

app.MapGet("/serilog", (ILogger<CategoryFiltered> loggerCategory) => {
  logCategory.LogInformation("I'm {@Person}", new Person(...));
  return Results.Ok();
}).WithName("GetFirstLog");

小结 (略)