.NET Worker Service 添加 Serilog 日志记录

前面我们了解了 .NET Worker Service 的入门知识[1] 和 如何优雅退出 Worker Service [2]，今天我们接着介绍一下如何为 Worker Service 添加 Serilog 日志记录。

在实际的生产环境中，应用程序中记录日志是非常宝贵的。在许多情况下，开发人员无法直接访问生产环境来调试问题。高质量的日志记录为解决线上问题提供了线索和依据。

日志记录是将应用程序操作和状态记录到辅助接口的过程。

.NET 日志记录框架

.NET 中有很多默认的日志记录提供程序[3]，它们可以将日志输出到控制台、Debug、EventSource 和 EventLog 等，例如在上一篇的示例中，默认的实现是将日志记录输出到了控制台窗口。

但是 .NET 中没有可以帮我们将日志信息输出到文件和数据库的内置提供程序，而这却是我们在生产环境中十分常见的应用场景。为了实现这一功能，我们需要为 .NET 实现自定义的日志记录提供程序[4]，这需要大量时间，因为需要考虑很多事情，比如读写性能、存储空间、配置等等。

幸运的是，一些优秀的第三方程序包可以为我们提供帮助，.NET 中三种最流行的日志框架分别是：log4net、NLog、Serilog，我们只需从 NuGet 包存储库中获取它们，然后简单地配置一下便可以愉快地使用它们了。

log4net

log4net[5] 是一个始于 2001 年的领先的日志记录框架，最初是 Java 框架 log4j 的端口。多年来，Apache Logging Services 项目持续进行开发，没有其他框架能像 log4net 一样久经考验。log4net 是所有现代 .NET 日志记录框架的鼻祖，在日志框架中，日志级别（log levels）、记录器(logger)和输出模块(appenders/targets/sinks)等概念几乎都是通用的[6]。相信所有多年使用 .NET 编程的朋友对 log4net 都相当熟悉。

log4net 好用、稳定且灵活，但是它的配置相对来说比较复杂一些，而且很难实现结构化的日志记录。

NLog

NLog[7] 也是一个相当老的项目，最早的版本发布于 2006 年，不过目前仍在积极开发中。NLog 从 v4.5 版本开始新增了对结构化日志记录的支持。

与 log4net 相比，NLog 的配置更加容易，并且基于代码的配置也比较简洁。NLog 中的默认设置比 log4net 中的默认设置会更合理一些。需要注意的一点是，当使用这两个框架，您可能会遇到同一个问题，那就是配置有问题（比如忘记复制配置文件）时，不会得到任何提示，也不会输出日志信息。假如您将应用部署上线以后遇到这个情况，这将是致命的，因为许多问题的检查都是依赖于日志记录的。当然，这么设计的初衷是避免让应用程序因日志问题而导致崩溃。

Serilog

Serilog[8] 日志记录框架发布于 2013 年，相对来说是一个较新的框架。与其他日志框架不同的是，Serilog 在设计时考虑了强大的结构化事件数据，提供了开箱即用的结构化日志实现。所以 Serilog 对结构化日志的支持非常好，而且配置简洁。Serilog 中的日志可以发送到许多终端，Serilog 称这些终端为“输出模块库(sinks)”。您可以在 https://github.com/serilog/serilog/wiki/Provided-Sinks 页面查看非常全面的列表。

Serilog 中还有一个功能强大的概念是Enricher，可以通过各种方式来丰富日志事件的属性，从而向日志添加新的信息。NuGet 中提供了一些预建的 Enricher，您也可以通过实现 ILogEventEnricher 构建自己的 Enricher。

结构化日志记录

或许您已注意到了，前面我多次提到结构化日志记录，那么什么是结构化日志记录，为什么我要强调结构化日志记录呢？

通常情况下，您会发现日志信息基本上包含两部分内容：消息模板和值，而 .NET 通常只接受诸如 string.Format(...) 这样的的输入字符串。比如：

var position = new { Latitude = 25, Longitude = 134 };
var elapsedMs = 34;

log.Information("Processed Position, Latitude:{0}, Longitude: {1} in Elapsed:{2} ms.", position.Latitude, position.Longitude, elapsedMs);

这条日志只是简单地被转换为文本输出到日志文件中：

[INF] Processed Position, Latitude:25, Longitude: 134 in Elapsed:34 ms.

这看起来很好，但它可以更好！

当我们遇到问题的时候，我们需要根据一些已知的信息来检索日志记录。比如，假设我们已知 Latitude 为 25，Longitude 为 134，我们要查找这条日志的话，该怎么做呢？由于上面输出的日志信息是简单的文本，有经验的您可能立马会想到使用正则表达式或者简单的字符串匹配，但这样不仅不够直观，实现起来也比较麻烦。有没有更好的方法呢？

如果我们在存储日志的时候，将其中包含值的部分作为特征提取出来，形成由键和值组成的有结构的 JSON 对象，作为每条日志记录的属性(properties)：

{"Position": {"Latitude": 25, "Longitude": 134}, "Elapsed": 34}

然后，在我们检索的时候只需要查找日志记录的 properties 就可以了，它是结构化的，检索起来既方便又直观。

Serilog 帮我们实现了这一点，您只需改动一行代码就可以了：

log.Information("Processed {@Position} in {Elapsed:000} ms.", position, elapsedMs);

Position 前面的 @ 是解构操作符，它告诉 Serilog 需要将传入的对象序列化，而不是调用 ToString() 转换它。

Elapsed 之后的 :000 是一个标准的 .NET 格式字符串，它决定该属性的呈现方式。

为 Worker Service 添加 Serilog 日志

现在，您已经大概了解了 Serilog，以及为什么我会选用它的原因。下面我用一个实例来介绍一下它的用法。

需要用到的开发工具：

本示例基于上一篇文章中的 Worker Service 源码[9]修改，如果您安装有 git，可以用下面的命令获取它：

git clone git@github.com:ITTranslate/WorkerServiceGracefullyShutdown.git

然后，使用 Visual Studio Code 打开此项目，运行一下，以确保一切正常：

dotnet build
dotnet run

您在 Serilog 官方文档中可以看到很多例子，不过大部分示例都是使用编码的方式配置 Serilog，或者以 xml 的方式配置在老旧项目的 AppSettings 文件中。

在本文的示例中，我将以 JSON 的方式把 Serilog 的配置放置在现在流行的 appsettings.json 配置文件中。我们只需要修改 Program.cs 和 appsettings.json，不需要修改 Worker.cs。

安装依赖程序包

首先，安装我们所需的程序包：

dotnet add package Serilog
dotnet add package Serilog.Settings.Configuration
dotnet add package Serilog.Extensions.Hosting
dotnet add package Serilog.Sinks.Console
dotnet add package Serilog.Sinks.RollingFile

修改 Program

然后，修改 Program 中的 Main 方法，从 appsettings.json 读取配置并根据配置构建 Serilog 日志记录器的实例：

public static void Main(string[] args)
{
    var configuration = new ConfigurationBuilder()
        .SetBasePath(Directory.GetCurrentDirectory())
        .AddJsonFile("appsettings.json")
        .AddJsonFile($"appsettings.{Environment.GetEnvironmentVariable("DOTNET_ENVIRONMENT") ?? "Production"}.json", true)
        .Build();

    // 全局共享的日志记录器
    Log.Logger = new LoggerConfiguration()
        .ReadFrom.Configuration(configuration)
        .Enrich.FromLogContext()
        .CreateLogger();

    try
    {
        var separator = new string('-', 30);

        Log.Information($"{separator} Starting host {separator} ");

        CreateHostBuilder(args).Build().Run();

        Log.Information($"{separator} Exit host {separator} ");
    }
    catch (Exception ex)
    {
        Log.Fatal(ex, "Host terminated unexpectedly");
    }
    finally
    {
        Log.CloseAndFlush(); // 释放资源
    }
}

修改 Program 中的 CreateHostBuilder 方法，将 Serilog 设置为日志提供程序：

public static IHostBuilder CreateHostBuilder(string[] args) =>
    Host.CreateDefaultBuilder(args)
        .ConfigureServices((hostContext, services) =>
        {
            services.AddHostedService<Worker>();
        })
        .UseSerilog(); //将 Serilog 设置为日志提供程序

修改配置文件 appsettings.json

修改应用程序配置文件 appsettings.json，添加 Serilog 节点(Section)。

Serilog 所需的配置节点名称默认为 Serilog；当然，您也可以改变它，但要在读取的时候指定节点名。

{
  "Serilog": {
    "Using": [
      "Serilog.Sinks.Console",
      "Serilog.Sinks.RollingFile"
    ],
    "MinimalLevel": {
      "Default": "Information",
      "Override": {
        "System": "Warning",
        "Microsoft": "Information"
      }
    },
    "WriteTo": [
      {
        "Name": "Console"
      },
      {
        "Name": "RollingFile",
        "Args": {
          "pathFormat": "Logs\\{Hour}.log",
        }
      }
    ]
  }
}

看一下我们都配置了什么：

您可以在 Serilog.Settings.Configuration 包[10] 的文档中找到这些配置的说明。

Using 节点

Using 节点包含了所需的程序集列表，用于自动发现 WriteTo 和 Enrich 等节点中配置的方法所属的程序集。

对于 .NET Core 项目，构建工具会生成 .deps.json 文件，并且 Serilog.Settings.Configuration 包使用 Microsoft.Extensions.DependencyModel 实现了一个约定，从而可以从名称任意位置带有Serilog 的依赖程序包中找出正确的包，并从中提取配置的方法。因此，上面示例中的 Using 节点是可以省略的。

MinimalLevel 节点

MinimumLevel 对象配置输出日志的最低级别。添加 MinimalLevel.Override 项，可以覆盖某些特定命名空间的最小级别。

WriteTo 节点

使用 WriteTo 对象配置输出模块(sinks)，可以同时配置并激活多个输出模块。本示例中我们配置了 Console 和 RollingFile，前者将日志输出到控制台，后者将日志输出到滚动文件中。

将日志输出到文件，您还可以使用 Serilog.Sinks.File 程序包，它也支持滚动文件。

Args 用于配置 Sink 的选项。本例中 pathFormat 配置了日志文件的存放位置，该项的值中 {Hour} 是滚动日志文件的 文件名格式说明符。该输出模块支持三种不同的文件名格式说明符（区分大小写）：

  • {Date}：每天创建一个文件。文件名使用 yyyyMMdd 格式。
  • {Hour}：每小时创建一个文件。文件名使用 yyyyMMddHH 格式。
  • {HalfHour}：每半小时创建一个文件。文件名使用 yyyyMMddHHmm 格式。

完成以上这些配置后，我们运行应用程序：

dotnet build
dotnet run

您会发现在应用程序根目录下多了一个 Logs 文件夹，可以将日志信息正常输出到文件了。同时，控制台也有输出日志。两者的输出格式略有不同，控制台中的输出更简洁一些。

添加 Enricher 和格式化输出

前文我提到过 Serilog 中还有一个功能强大的概念是Enricher，这里我就以预建的 Enricher 来举例说明一下它的使用。

添加以下依赖程序包：

dotnet add package Serilog.Enrichers.Thread
dotnet add package Serilog.Enrichers.Environment
dotnet add package Serilog.Enrichers.Process

这三个 Enricher 分别提供了不同的信息以丰富日志事件的属性。

  • Serilog.Enrichers.Environment 提供 WithMachineName() 和 WithEnvironmentUserName()
  • Serilog.Enrichers.Process 提供 WithProcessId()
  • Serilog.Enrichers.Thread 提供 WithThreadId()

修改 appsettings.json，向 Serilog 配置对象添加 Enrich 配置节点，以丰富日志事件的信息：

"Enrich": [
  "WithMachineName",
  "WithProcessId",
  "WithProcessName",
  "WithThreadId"
]

修改 appsettings.json，向 WriteTo 下的 RollingFile 对象节点的 Args 添加一个 outputTemplate 选项，以自定义输出消息模板：

{
  "Name": "RollingFile",
  "Args": {
    "pathFormat": "Logs\\{HalfHour}.log",
    "outputTemplate": "{Timestamp:o} [{Level:u3}] ({MachineName}/{ProcessId}/{ProcessName}/{ThreadId}) {Message}{NewLine}{Exception}"
  }
}

修改好配置后，重新运行应用程序：

dotnet build
dotnet run

再查看一下日志文件，您会发现日志已经按我们自定义的格式输出了，并且多了一些我们使用 Enricher 获得的信息：(计算机名/进程ID/进程名称/线程ID)。

2021-05-27T18:15:40.2992230+08:00 [INF] (DESKTOP-6LTYU3O/54376/MyService/1) Worker running at: 05/27/2021 18:15:40 +08:00

将日志保存到数据库

前文我提到过日志文件的属性(properties)，为什么直到现在还没有看到过它呢？

这是因为，当 Serilog 将日志事件写入文件或控制台时，消息模板和属性将仅会呈现为易于阅读的友好文本。而当我们将日志事件发送到基于云的日志服务器、数据库和消息队列等输出模块(sinks)时，就可以保存为结构化的数据了。

为了简便起见，我以 SQLite 数据库为例来介绍一下。

添加 SQLite 依赖程序包：

dotnet add package Serilog.Sinks.SQLite

修改 appsettings.json，在 Serilog 配置中的 WriteTo 节点下添加以下配置节点，以向 SQLite 输出日志：

{
  "Name": "SQLite",
  "Args": {
    "sqliteDbPath": "Logs\\log.db",
    "tableName": "Logs",
    "maxDatabaseSize": 1,
    "rollOver": true
  }
}

解释一下 Args 各个选项的作用：

  • sqliteDbPath： SQLite 数据库的路径。
  • tableName： 用于存储日志的 SQLite 表的名称。
  • maxDatabaseSize： 数据库的最大文件大小，可以以 MB 为单位增加。默认为 10MB，最大为 20GB。为了方便测试，我在这里将其设置为 1MB。
  • rollOver： 如果文件大小超过最大数据库文件大小，则创建滚动备份，默认为 true。

此时，再次运行应用程序：

dotnet build
dotnet run

您将会在应用程序目录下的 Logs 文件夹中看到一个 SQLite 数据库文件 log.db。使用 DBeaver 打开检查一下：

Serilog SQLite table

可以看到，SQLite 输出模块自动为我们创建了数据库和表，日志记录成功了。

我们配置了数据库文件大于 1MB 时自动滚动备份，可以多输出一些日志测试一下，看它是否有自动滚动备份。我的测试结果如下图：

Serilog SQLite dbs

再看一下 Serilog 捕获的日志事件的属性(properties)：

Serilog SQLite table properties

Serilog 使用消息模板、以及命名和位置参数扩展 .NET 的格式化字符串，不过 Serilog 捕获与每个命名参数相关联的值，而不是直接将事件格式化为文本。我们添加几行代码，测试一下 Serilog 捕获日志事件的情况：

var position = new { Latitude = 25, Longitude = 134 };
var elapsedMs = 34;
Log.Information("Processed {@Position} in {Elapsed:000} ms.", position, elapsedMs);

上面的示例在日志事件中记录了两个属性：Position 和 Elapsed，Position 前面的 @ 操作符告诉 Serilog 要序列化传入的对象。最终我们在数据库中存储的结构化的 Properties 如下所示：

{"Position":{"Latitude":25,"Longitude":134},"Elapsed":34,"MachineName":"DESKTOP-6LVG1OL","ProcessId":54332,"ProcessName":"MyService","ThreadId":1}

Serilog SQLite structured data

Serilog 对结构化事件数据深入且丰富的支持，开创了原本使用传统日志记录器所没有的巨大的诊断可能性。

总结

在本文中，我介绍了 .NET 中常用的结构化事件日志框架 Serilog，以及使用它的原因和好处；并通过一个 .NET Worker Service 实例，说明如何将日志保存到滚动文件和数据库中。

Serilog 是一个稳定的、配置简洁的、功能强大的、可扩展的、支持结构化日志事件的 .NET 日志记录提供程序，值得我们在应用中广泛使用。

您可以从 GitHub 下载本文中的源码[11]。


相关阅读：

作者 ： 技术译民
出品 ： 技术译站

  1. https://mp.weixin.qq.com/s/ujGkb5oaXq3lqX_g_eQ3_g .NET Worker Service 入门介绍 ↩︎

  2. https://mp.weixin.qq.com/s/voxAxh9rQQogE3_Yc1-eCQ 如何优雅退出 Worker Service ↩︎

  3. https://docs.microsoft.com/zh-cn/dotnet/core/extensions/logging-providers ↩︎

  4. https://docs.microsoft.com/zh-cn/dotnet/core/extensions/custom-logging-provider ↩︎

  5. https://logging.apache.org/log4net/ ↩︎

  6. https://stackify.com/nlog-vs-log4net-vs-serilog/ ↩︎

  7. https://nlog-project.org/ ↩︎

  8. https://serilog.net/ ↩︎

  9. https://github.com/ITTranslate/WorkerServiceGracefullyShutdown ↩︎

  10. https://github.com/serilog/serilog-settings-configuration ↩︎

  11. https://github.com/ITTranslate/WorkerServiceWithSerilog 源码下载 ↩︎

posted @ 2021-05-31 14:27  技术译民  阅读(4691)  评论(6)  编辑  收藏  举报