每个请求的日志级别

引言

前段时间，我读了 ThoughtWorks 的技术雷达。其中提到了一种名为“每个请求的日志级别”的技术。我一直在思考如何实现类似的解决方案。现在，我准备向大家展示一种可能的实现。

问题描述

那么我们谈论的是什么呢？假设你有一个 Web 服务。在某个时刻，它开始在生产环境中出现故障。但它只在某些请求上失败。例如，它只对一个用户失败。或者只对一个特定的端点失败。当然，我们必须找到原因。在这种情况下，日志记录应该会有所帮助。

我们可以将足够的日志指令插入到代码中，以找出不同的故障原因。日志指令通常将消息与某个日志级别（`Debug`、`Info`、`Warning` 等）关联起来。此外，记录器也有自己的日志级别。因此，所有级别高于记录器级别的消息都将写入日志接收器（文件、数据库等）。如果消息级别低于记录器级别，则该消息将被丢弃。

当应用程序运行良好时，我们希望尽可能少地记录日志消息，以保持日志接收器的大小较小。同时，如果应用程序出现故障，我们希望尽可能多地记录日志消息，以便能够找到问题的原因。这里的困难在于，通常我们为应用程序中的所有记录器设置一个级别。如果一切正常，我们保持此级别较高（例如 `Warning`）。如果我们需要调查故障，我们将此级别设置较低（例如 `Debug`）。

每个应用程序的日志级别

当我们把应用程序的日志级别设置得很低时，日志接收器中会突然出现大量的消息。这些消息将来自许多请求，并且会被打乱，因为许多请求可以同时处理。这导致了几个潜在的困难

• 如何将有问题的请求消息与没有问题的请求消息区分开来？
• 没有问题的请求仍然花费时间将消息写入日志接收器，尽管这些消息不会被使用。
• 没有问题的请求的消息仍然占用日志接收器中的空间，尽管这些消息不会被使用。

嗯，所有这些困难都不是非常严重。为了将“好”请求的消息与“坏”请求的消息区分开来，我们可以使用关联 ID。所有现代日志保留系统都支持按其字段过滤消息。

性能通常也不是大问题。日志系统支持异步写入，因此大量日志记录的影响不应很严重。

现在存储空间相对便宜，所以这也不是一个大问题。特别是如果我们能删除旧记录的话。

然而，我们能做得更好吗？我们能否根据某些条件为每个请求设置单独的日志级别？我想在这里探讨这个问题。

每个请求的日志级别

请允许我阐述我将要实现的解决方案的要求。应该有一种方法可以为每个请求独立设置日志级别。必须有一种灵活的方法来定义为请求选择日志级别的条件。并且应该能够在运行时更改这些条件而无需重新启动应用程序。

舞台已经准备就绪。让我们开始吧。

我将使用 .NET Core 编写一个简单的 Web API 应用程序。它将只有一个控制器

[Route("api/[controller]")]
[ApiController]
public class ValuesController : ControllerBase
{
    ...

    // GET api/values
    [HttpGet]
    public ActionResult<IEnumerable<string>> Get()
    {
        Logger.Info("Executing Get all");

        return new[] { "value1", "value2" };
    }

    // GET api/values/5
    [HttpGet("{id}")]
    public ActionResult<string> Get(int id)
    {
        Logger.Info($"Executing Get {id}");

        return "value";
    }
}

我们稍后将讨论 `Logger` 属性的实现。对于此实现，我将使用 log4net 库进行日志记录。这个库有一个有趣的特性。我说的是 级别继承。简单来说，如果我在日志配置中声明名为 `X` 的记录器应该具有 `Info` 日志级别，这意味着所有名称以 `X.` 开头的记录器（例如 `X.Y`、`X.Z`、`X.A.B`）都将继承相同的日志级别。

于是最初的想法来了。对于每个请求，我都会以某种方式计算所需的日志级别。然后我会在 `log4net` 配置中创建一个新命名的记录器。该记录器将具有所需的日志级别。之后，在此请求期间创建的所有记录器对象都必须以该记录器的名称作为前缀。这里唯一的问题是 `log4net` 从不删除记录器。一旦它们被创建，它们就会在应用程序运行时一直存在。这就是为什么我将预先创建具有特定名称的记录器，用于每个日志级别

<?xml version="1.0" encoding="utf-8" ?>
<log4net>
  <appender name="Console" type="log4net.Appender.ConsoleAppender">
    <layout type="log4net.Layout.PatternLayout">
      <!-- Pattern to output the caller's file name and line number -->
      <conversionPattern value="%5level [%thread] (%file:%line) - %message%newline" />
    </layout>
  </appender>

  <appender name="RollingFile" type="log4net.Appender.RollingFileAppender">
    <file value="RequestLoggingLog.log" />
    <appendToFile value="true" />
    <maximumFileSize value="100KB" />
    <maxSizeRollBackups value="2" />

    <layout type="log4net.Layout.PatternLayout">
      <conversionPattern value="%level %thread %logger - %message%newline" />
    </layout>
  </appender>

  <root>
    <level value="WARN" />
    <appender-ref ref="Console" />
    <appender-ref ref="RollingFile" />
  </root>

  <logger name="EdlinSoftware.Log.Error">
    <level value="ERROR" />
  </logger>

  <logger name="EdlinSoftware.Log.Warning">
    <level value="WARN" />
  </logger>

  <logger name="EdlinSoftware.Log.Info">
    <level value="INFO" />
  </logger>

  <logger name="EdlinSoftware.Log.Debug">
    <level value="DEBUG" />
  </logger>
</log4net>

现在我有一些预定义的记录器，名称为 `EdlinSoftware.Log.XXXX`。这些名称将作为实际级别的名称前缀。为了避免请求之间的冲突，我将当前请求的前缀保存在一个 `AsyncLocal` 对象中。我将在新的 OWIN 中间件中设置此对象的值

app.Use(async (context, next) =>
{
    try
    {
        LogSupport.LogNamePrefix.Value = await LogSupport.GetLogNamePrefix(context);

        await next();
    }
    finally
    {
        LogSupport.LogNamePrefix.Value = null;
    }
});

当设置此值后，就可以轻松创建带有所需名称前缀的日志记录器

public static class LogSupport
{
    public static readonly AsyncLocal<string> LogNamePrefix = new AsyncLocal<string>();

    public static ILog GetLogger(string name)
    {
        return GetLoggerWithPrefixedName(name);
    }

    public static ILog GetLogger(Type type)
    {
        return GetLoggerWithPrefixedName(type.FullName);
    }

    private static ILog GetLoggerWithPrefixedName(string name)
    {
        if (!string.IsNullOrWhiteSpace(LogNamePrefix.Value))
        { name = $"{LogNamePrefix.Value}.{name}"; }

        return LogManager.GetLogger(typeof(LogSupport).Assembly, name);
    }

    ....

}

现在很清楚如何在控制器中获取日志记录器实例

[Route("api/[controller]")]
[ApiController]
public class ValuesController : ControllerBase
{
    private ILog _logger;

    private ILog Logger
    {
        get => _logger ?? (_logger = LogSupport.GetLogger(typeof(ValuesController)));
    }

    ....
}

剩下的唯一事情是如何设置规则来定义应该为请求分配哪个日志级别。这个机制应该足够灵活。这里的主要思想是使用 C# 脚本。我将创建一个文件 `LogLevelRules.json`，在其中定义一组规则-日志级别对

[
  {
    "logLevel": "Debug",
    "ruleCode": "context.Request.Path.Value == \"/api/values/1\""
  },
  {
    "logLevel": "Debug",
    "ruleCode": "context.Request.Path.Value == \"/api/values/3\""
  }
]

这里 `logLevel` 是所需的日志级别，`ruleCode` 是一个 C# 代码，它为给定的请求返回一个布尔值。应用程序将逐一运行这些规则的代码。第一个返回 `true` 的规则将设置相应的日志级别。如果所有规则都返回 `false`，则将使用默认日志级别。

要从规则的 `string` 表示创建委托，可以使用 `CSharpScript` 类

public class Globals
{
    public HttpContext context;
}

internal class LogLevelRulesCompiler
{
    public IReadOnlyList<LogLevelRule> 
           Compile(IReadOnlyList<LogLevelRuleDescription> levelRuleDescriptions)
    {
        var result = new List<LogLevelRule>();

        foreach (var levelRuleDescription in levelRuleDescriptions ?? new LogLevelRuleDescription[0])
        {
            var script = CSharpScript.Create<bool>
                         (levelRuleDescription.RuleCode, globalsType: typeof(Globals));
            ScriptRunner<bool> runner = script.CreateDelegate();

            result.Add(new LogLevelRule(levelRuleDescription.LogLevel, runner));
        }

        return result;
    }
}

internal sealed class LogLevelRule
{
    public string LogLevel { get; }

    public ScriptRunner<bool> Rule { get; }

    public LogLevelRule(string logLevel, ScriptRunner<bool> rule)
    {
        LogLevel = logLevel ?? throw new ArgumentNullException(nameof(logLevel));
        Rule = rule ?? throw new ArgumentNullException(nameof(rule));
    }
}

在这里，`Compile` 方法获取从 `LogLevelRules.json` 文件读取的对象列表。它为每个规则创建一个 `runner` 委托并存储起来供以后使用。

此委托列表可以存储

LogSupport.LogLevelSetters = new LogLevelRulesCompiler().Compile(
    new LogLevelRulesFileReader().ReadFile("LogLevelRules.json")
);

并稍后使用

public static class LogSupport
{
    internal static IReadOnlyList<LogLevelRule> LogLevelSetters = new LogLevelRule[0];

    ...

    public static async Task<string> GetLogNamePrefix(HttpContext context)
    {
        var globals = new Globals
        {
            context = context
        };

        string result = null;

        foreach (var logLevelSetter in LogLevelSetters)
        {
            if (await logLevelSetter.Rule(globals))
            {
                result = $"EdlinSoftware.Log.{logLevelSetter.LogLevel}";
                break;
            }
        }

        return result;
    }
}

因此，在应用程序启动时，我们读取 `LogLevelRules.json` 文件，使用 `CSharpScript` 类将其内容转换为委托列表，并将其存储到 `LogSupport.LogLevelSetters` 字段中。在每个请求中，我们运行此列表中的委托以获取请求的日志级别。

剩下的唯一事情就是监视 `LogLevelRules.json` 文件的修改。当我们想为某种请求设置日志级别时，我们会在这个文件中添加另一个检查器。为了让应用程序在不重启的情况下应用这些更改，我们必须监视文件

var watcher = new FileSystemWatcher
{
    Path = Directory.GetCurrentDirectory(),
    Filter = "*.json",
    NotifyFilter = NotifyFilters.LastWrite
};
watcher.Changed += (sender, eventArgs) =>
{
    // Wait for the application that modifies the file to release it..
    Thread.Sleep(1000);

    LogSupport.LogLevelSetters = new LogLevelRulesCompiler().Compile(
        new LogLevelRulesFileReader().ReadFile("LogLevelRules.json")
    );
};
watcher.EnableRaisingEvents = true;

为简洁起见，我在处理 `LogSupport.LogLevelSetters` 字段时没有使用线程同步代码。但在实际应用程序中，你确实应该应用它。

您可以在 GitHub 上找到该应用程序的完整代码。

缺点

此代码解决了为每个请求定义日志级别的问题。但它也有一些缺点。让我们讨论一下它们。

1. 这种方法改变了记录器的名称。因此，在日志文件中，而不是 `MyClassLogger`，人们会看到类似 `Edlinsoft.Log.Debug.MyClassLogger` 的内容。人们可以接受它，但它不是很方便。也许可以通过调整日志布局来克服这个问题。
2. 现在不可能将记录器实例设置为静态，因为它们应该为每个请求单独创建。对我来说，这里最严重的问题是所有团队成员都应该始终记住这样做。人们可能会不小心定义一个带有记录器的静态字段并得到奇怪的结果。为了克服这种情况，我们可以为记录器创建一个包装类，并使用它而不是直接使用 `log4net` 类。这样的包装类可以为每个操作始终创建 `log4net` 记录器的新实例。在这种情况下，使用包装类的静态实例将不是问题。
3. 所描述的方法创建了许多日志记录器实例。它会污染内存并占用 CPU 周期。根据应用程序的不同，这可能是一个问题，也可能不是。
4. 当我们修改带有规则的 JSON 文件时，规则代码可能包含错误。很容易设置 `try-catch` 块以确保这些错误不会破坏我们的主程序。但我们仍然需要意识到出了问题。可能存在两种类型的错误
   • 将规则代码编译成委托时的编译时错误。
   • 这些委托执行期间的运行时错误。

无论如何，我们必须意识到这些错误，否则，我们将无法获得日志消息，甚至不知道发生了什么。

结论

总的来说，我应该说我觉得这不是一个应该取代现代日志记录方法的出色解决方案。一个能够过滤日志记录的好工具，即使在使用每个应用程序的日志级别的情况下，也能提供帮助。无论如何，我希望对问题的分析能给你一些思考。

您可以在我的博客上阅读我的其他文章。