ASP.NET Core - 日志记录系统(一)

一、日志记录

日志记录是什么?简单而言,就是通过一些方式记录应用程序运行中的某一时刻的状态,保留应用程序当时的信息。这对于我们进行应用程序的分析、审计以及维护有很大的作用。

作为程序员,我们恐怕谁也不敢保证我们开发的软件应用一定不存在BUG,一定不会出现故障,而当故障出现的时候,日志就是我们排查故障的首要依据,排查故障的第一步一定是查看故障发生时的日志信息。

当然,日志也不仅仅只是在排查故障的时候有用,这类称为错误日志,比较常谈的还有安全日志、审计日志等等,它根据应用场景、企业团队对其认知和需要有不同的应用。日志记录在软件工程中更是一种思想,而不止是一种开发技术实现,它被认为是产品团队对其产品需求没有特别要求的非功能性使用场景,在软件框架、开发实现中基本是一种必备的横切功能点,现在的各种开发语言、框架中基本都具备日志记录的实现。

二、ASP.Net Core 的日志记录

.NET Core 框架中内置了日志记录系统,支持通过统一的 API 进入日志的记录,并且支持通过配置各种日志提供程序以各种不同的方式保存日志信息,不仅有多种内置的日志提供程序,也兼容各种按照标准规范实现的第三方框架。以下演示代码基于 .NET 7 。

2.1. 日志记录系统的接入

当我们通过 VS 应用模板创建一个 ASP.NET Core 的应用时,默认将日志记录系统添加到应用中,内部实际上时在创建 HostApplicationBuilder 的过程中,通过 AddLogging() 注册了日志相关的服务,并配置了 ConsoleDebugEventSourceEventLog(仅Windows)共四种日志记录提供程序。

var builder = WebApplication.CreateBuilder(args);

除此之外,我们也可以引入 Microsoft.Extensions.Hosting 包,自行通过通用主机创建应用,以下代码中也默认添加了日志记录系统:

var host = Host.CreateDefaultBuilder().Build();

通过查看源码,可以看到:

image

image

image

image

这两种方式最终都是通过 HostingHostBuilderExtensions 中的 AddDefaultServices() 方法向容器中注入日志相关的服务,并根据不同平台配置了不同的日志提供程序。

除了默认的几种提供程序,我们也可以通过以下两种方式根据自己的实际需要,添加其他的日志提供程序,如比较常用的文件记录提供程序将日志输出到文本文件中,或者清除默认的提供程序进行自定义。在.NET 6、.NET 7 中,微软推进用第二种方式替代第一种方式。

builder.Host.ConfigureLogging(logging =>
{
    // 清除已经注入的日志提供程序
    logging.ClearProviders();
    logging.AddConsole();
});

// 清除已经注入的日志提供程序
builder.Logging.ClearProviders();
builder.Logging.AddConsole();
builder.Logging.AddJsonConsole();

关于日志记录提供程序,下面再进行详细的介绍。

2.2 记录日志

将日志记录系统集成到应用之后,使用方式就非常简单了。.NET Core 日志记录系统提供统一的 API 进行日志的记录,无论底层使用的是什么日志提供程序,无论最终是将日志记录在哪里。

我们可以通过依赖注入,在需要记录日志的类中从容器中解析出 ILogger<TCategoryName> 这样一个日志记录器实例。日志记录器在创建的时候需要指定日志类别,它会与该记录器的记录的每一条日志关联,方便我们在众多的日志信息中查找特定的日志。ILogger<TCategoryName> 中的泛型会作为该记录器的日志类别,按照 .NET 体系下不成文的约定,一般情况下使用注入记录器的类作为泛型类型,最终在日志信息中会以该类的全类名作为日志类别。

[ApiController]
[Route("[controller]/[action]")]
public class WeatherForecastController : ControllerBase
{
	private readonly ILogger<WeatherForecastController> _logger;

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

我们也可以显式指定日志类别,日志类别实质就是一个字符串,这时我们可以注入 ILoggerFactory 实例,之后通过 ILoggerFactory.CreateLogger 方法自行创建记录器。

[ApiController]
[Route("[controller]/[action]")]
public class WeatherForecastController : ControllerBase
{
	private ILogger _logger;

	public WeatherForecastController(ILoggerFactory loggerFactory)
	{
		_logger = loggerFactory.CreateLogger("MyLogger");
	}
 }

之后,就是使用记录器在我们需要的位置记录日志信息,记录器提供了丰富的 API 方便我们记录各种日志:

[ApiController]
[Route("[controller]/[action]")]
public class WeatherForecastController : ControllerBase
{
	private readonly ILogger<WeatherForecastController> _logger;

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

	[HttpGet]
	public Task Get()
	{
		// 各种日志API对应各种日志级别
		// 断点
		_logger.LogTrace("这是一个断点日志");
		//调试
		_logger.LogDebug("this is a debug.");
		//信息
		_logger.LogInformation("this is an info.");
		//警告
		_logger.LogWarning("this is a warning.");
		//错误
		_logger.LogError("this is an error.");
		//当机
		_logger.LogCritical("this is Critical");
		// 多个重载方法,支持字符串占位符
		_logger.LogInformation("this is an info {date} {level}.", DateTime.Now, 1);
		// 支持传入异常,记录异常信息
		_logger.LogError(new Exception(), "this is an error.");
	   // 指定日志ID,方便同类异常的筛选, 常用的日志id可以定义为常量
		_logger.LogError(1001, new Exception(), "this is an error with eventId.");
 // 自行指定日志级别
 _logger.Log(LogLevel.Information, "loging an info.");

		return Task.CompletedTask;
	}
}

当调用该接口的时候,可以看到控制台中输出了我们记录的日志内容:

image

这里没有输出 TraceDebug 日志,是因为默认配置中输出的最低日志级别是 Information,要使 TraceDebug 这两类日志可以正常输出,需要我们进行配置。

image

image

2.3 基本配置

2.3.1 日志级别

上面的代码中讲到,记录日志时我们可以指定当前日志信息的级别,日志级别表示日志的严重程度,.NET Core 框架日志系统中日志级别如下,一共分为7个等级,从轻到重为(最后的None较为特殊):

日志级别 描述
Trace 0 追踪级别,包含最详细的信息。这些信息可能包含敏感数据,默认情况下是禁用的,并且绝不能出现在生产环境中。
Debug 1 调试级别,用于开发人员开发和调试。信息量一般比较大,在生产环境中一定要慎用。
Information 2 信息级别,该级别平时使用较多。
Warning 3 警告级别,一些意外的事件,但这些事件并不对导致程序出错。
Error 4 错误级别,一些无法处理的错误或异常,这些事件会导致当前操作或请求失败,但不会导致整个应用出错。
Critical 5 致命错误级别,这些错误会导致整个应用出错。例如内存不足等。
None 6 指示不记录任何日志

2.3.2 全局输出配置

我们可以在记录日志的时候指定日志的级别,但是并不是我们记录的任何一个级别的日志都会输出保存,还得配合日志记录系统的配置,就像上面的例子中,最开始 DebugTrace 级别的日志是不输出的。

日志记录配置通常通过配置文件进行设置,在 appsettings.json 文件有关于日志配置的相关节点 Logging,在我们通过 ASP.NET Core 应用模板创建项目时,就会自动生成:

{
  "Logging": {
    "LogLevel": {
      "Default": "Information",
      "Microsoft.AspNetCore": "Warning"
    }
  }
}

在配置文件中,我们可以通过 LogLevel 节点对日志记录系统全局输出的日志最低级别进行设置,日志记录系统最终会输出大于等于我们设置的级别的日志信息,而其他信息则不会输出。

可以看到,在 LogLevel 节点下还有一些字段,通过这些字段我们还可以进行更具体的配置。其中“Default”字段顾名思义就是默认配置,如上面配置中设置了日志系统默认输出的最低级别日志为 Information,没有进行过特殊配置的日志记录器全部按照这一个配置进行输出。

我们还可以针对某一特定的日志记录器进行专门的设置,通过日志记录器创建时传入的名称进行筛选,支持模糊匹配(字符串 StartWith 判断),如上面配置中的 “Microsoft.AspNetCore”,这个字段一看就是命名空间书写方式,也就是说全类名以该字段开始的日志记录器记录的日志按照这个配置设置的最低日志记录进行记录。如果还有更加具体的配置,如“Microsoft.AspNetCore.Mvc”,一个日志记录器名称同时匹配 “Microsoft.AspNetCore”“Microsoft.AspNetCore.Mvc”,则以 “Microsoft.AspNetCore.Mvc” 的配置为准,因为 “Microsoft.AspNetCore.Mvc” 更具体。

这也是为什么约定使用 ILogger<TCategoryName> 接口注入日志记录器的原因,这种方式下我们可以通过有规律的命名空间快速设置筛选最终需要输出保存的日志信息。当然,如果自定义的日志记录器名称字符串比较有规律,那也没有问题。

2.3.3 针对特定日志提供程序的配置

在日常的应用开发中,往往我们都会使用不止一种方式记录日志,通常会同时集成多个日志记录提供程序,LogLevel 节点是针对所有日志记录提供程序的统一配置,它适用于所有没有进行单独配置的日志记录提供程序(Windows EventLog 除外。EventLog 必须显式地进行配置,否则会使用其默认的 LogLevel.Warning)。当然,我们也可以针对不同的日志提供程序进行单独的配置。如:

{
  "Logging": {
    "LogLevel": {
      "Default": "Information",
      "Microsoft": "Warning",
      "Microsoft.Hosting.Lifetime": "Information"
    },
    "Console": {
      "LogLevel": {
        "Default": "Error"
       }
    },
    "Debug": {
      "LogLevel": {
        "Microsoft": "None"
       }
    },
    "EventSource": {
      "LogLevel": {
        "Default": "Trace",
        "Microsoft": "Trace",
        "Microsoft.Hosting.Lifetime": "Trace"
      }
    }
  }
}

就像 appsettings.{Environment}.jsonappsettings.json 之间的关系一样,Logging.{Provider}.LogLevel 中的配置将会覆盖 Logging.LogLevel 中的配置。例如 Logging.Console.LogLevel.Default 将会覆盖 Logging.LogLevel.DefaultConsole 日志记录器将默认记录 Error 及其以上级别的日志。

刚才提到了,Windows EventLog 比较特殊,它不会继承 Logging.LogLevel 的配置。EventLog 默认日志级别为 LogLevel.Warning,如果想要修改,则必须显式进行指定。

以上讲到的日志配置方式,都是通过 appsettings.json 设置的,实际上 .NET Core 框架下配置来源不仅仅是 appsettings.json 文件,只不过它是最常用的,这一块的内容在之前的配置系统的文章中已经详细讲过了。我们也可以通过其他的配置来源进行日志相关的配置,例如命令行、环境变量等。

2.3.6 显式设置

除了通过配置进行日志记录系统的设置之外,我们还可以在代码中通过 AddFilter 方法显式地设置日志系统的相关行为配置,该方法有多个重载,如:

var builder = WebApplication.CreateBuilder(args);

// 相当于 Logging:LogLevel:Default:Information
builder.Logging.AddFilter(logging => logging >= LogLevel.Information);
// 相当于 Logging:LogLevel:Microsoft:Warning
builder.Logging.AddFilter("Microsoft", LogLevel.Warning);
// 相当于 Logging:Console:LogLevel:Microsoft:Information
builder.Logging.AddFilter<ConsoleLoggerProvider>("Microsoft", LogLevel.Information);
// 也可以更加灵活地通过筛选器设置日志记录规则
builder.Logging.AddFilter((provider, category, logLevel) =>
{
    if (provider.Contains("ConsoleLoggerProvider")
        && category.Contains("Controller")
        && logLevel >= LogLevel.Information)
    {
        return true;
    }
    else if (provider.Contains("ConsoleLoggerProvider")
        && category.Contains("Microsoft")
        && logLevel >= LogLevel.Information)
    {
        return true;
    }
    else
    {
        return false;
    }
});
// 设置全局的日志输出最小级别,日志记录系统默认最低级别是 Information
builder.Logging.SetMinimumLevel(LogLevel.Debug);

这种方式相对于配置会比较固化,不利于动态调整,一般来说,日志记录的相关配置还是配置文件中设置,所以这里就简单地讲一下,大家知道有这种方式就行了。

2.3.4 配置筛选原理

当创建 ILogger<TCategoryName> 的对象实例时,ILoggerFactory 根据不同的日志记录提供程序,将会:

  1. 查找匹配该日志记录提供程序的配置。如果找不到,则使用通用配置。
  2. 然后匹配拥有最长前缀的配置类别。如果找不到,则使用Default配置。
  3. 如果匹配到了多条配置,则采用最后一条。
  4. 如果没有匹配到任何配置,则使用 MinimumLevel,这是个配置项,默认是LogLevel.Information。

如上面讲到的,我们可以使用 SetMinimumLevel 方法设置 MinimumLevel

对于到的 .NET Core 中的源码是这一段:
image

在创建 ILoggerFactory 实例、创建 ILogger 实例和配置刷新的时候,都会对每一个提供程序的配置规则根据优先级进行筛选,只有最小级别不为 None,才会创建最终的日志记录书写器,否则甚至不会有书写器。

而在具体的规则过滤逻辑中,可以看到微软的注释:

日志规则过滤 LoggerRuleSelector
internal static class LoggerRuleSelector
{
	public static void Select(LoggerFilterOptions options, Type providerType, string category, out LogLevel? minLevel, out Func<string?, string?, LogLevel, bool>? filter)
	{
		filter = null;
		minLevel = options.MinLevel;

		// Filter rule selection:
		// 1. Select rules for current logger type, if there is none, select ones without logger type specified
		// 2. Select rules with longest matching categories
		// 3. If there nothing matched by category take all rules without category
		// 3. If there is only one rule use it's level and filter
		// 4. If there are multiple rules use last
		// 5. If there are no applicable rules use global minimal level

		string? providerAlias = ProviderAliasUtilities.GetAlias(providerType);
		LoggerFilterRule? current = null;
		foreach (LoggerFilterRule rule in options.RulesInternal)
		{
			if (IsBetter(rule, current, providerType.FullName, category)
				|| (!string.IsNullOrEmpty(providerAlias) && IsBetter(rule, current, providerAlias, category)))
			{
				current = rule;
			}
		}

		if (current != null)
		{
			filter = current.Filter;
			minLevel = current.LogLevel;
		}
	}

	private static bool IsBetter(LoggerFilterRule rule, LoggerFilterRule? current, string? logger, string category)
	{
		// Skip rules with inapplicable type or category
		// 别名或者全类名与当前日志提供程序对不上的则跳过
		if (rule.ProviderName != null && rule.ProviderName != logger)
		{
			return false;
		}
		// 对日志类别进行判断,这里会同时判断通用的配置和针对特定日志提供程序的配置
		// 也就是说某个类别,如果通用的LogLevel中配置了,如果特定的日志特工程序中没有重新配置覆盖,则会使用通用配置
		// 支持通配符 * ,但 * 只能有一个
		string? categoryName = rule.CategoryName;
		if (categoryName != null)
		{
			const char WildcardChar = '*';

			int wildcardIndex = categoryName.IndexOf(WildcardChar);
			if (wildcardIndex != -1 &&
				categoryName.IndexOf(WildcardChar, wildcardIndex + 1) != -1)
			{
				throw new InvalidOperationException(SR.MoreThanOneWildcard);
			}

			ReadOnlySpan<char> prefix, suffix;
			if (wildcardIndex == -1)
			{
				prefix = categoryName.AsSpan();
				suffix = default;
			}
			else
			{
				prefix = categoryName.AsSpan(0, wildcardIndex);
				suffix = categoryName.AsSpan(wildcardIndex + 1);
			}

			if (!category.AsSpan().StartsWith(prefix, StringComparison.OrdinalIgnoreCase) ||
				!category.AsSpan().EndsWith(suffix, StringComparison.OrdinalIgnoreCase))
			{
				return false;
			}
		}
		// 如果相同的类别,则以特定提供程序的配置优先
		if (current?.ProviderName != null)
		{
			if (rule.ProviderName == null)
			{
				return false;
			}
		}
		else
		{
			// We want to skip category check when going from no provider to having provider
			if (rule.ProviderName != null)
			{
				return true;
			}
		}
		// 特定的类别优先于默认的 Default 类别
		if (current?.CategoryName != null)
		{
			if (rule.CategoryName == null)
			{
				return false;
			}
			// 类别名称更详细的优先
			if (current.CategoryName.Length > rule.CategoryName.Length)
			{
				return false;
			}
		}

		return true;
	}
}

LoggerFilterOptions 中的规则是怎么来的呢?在通过主机构建应用的时候会通过配置文件加载相关的配置,并将配置转化为规则

image

image

最终,配置文件中的每一个日志类别的配置都会结合日志提供程序转化为一项规则,默认的 LogLevel 中的配置转换成的规则中 ProviderNamenull,默认的 Default 类别对于的规则 CategoryNamenull

日志规则配置 LoggerFilterConfigureOptions
internal sealed class LoggerFilterConfigureOptions : IConfigureOptions<LoggerFilterOptions>
{
	private const string LogLevelKey = "LogLevel";
	private const string DefaultCategory = "Default";
	private readonly IConfiguration _configuration;

	public LoggerFilterConfigureOptions(IConfiguration configuration)
	{
		_configuration = configuration;
	}

	public void Configure(LoggerFilterOptions options)
	{
		LoadDefaultConfigValues(options);
	}

	private void LoadDefaultConfigValues(LoggerFilterOptions options)
	{
		if (_configuration == null)
		{
			return;
		}

		options.CaptureScopes = GetCaptureScopesValue(options);

		foreach (IConfigurationSection configurationSection in _configuration.GetChildren())
		{
			if (configurationSection.Key.Equals(LogLevelKey, StringComparison.OrdinalIgnoreCase))
			{
				// Load global category defaults
				LoadRules(options, configurationSection, null);
			}
			else
			{
				IConfigurationSection logLevelSection = configurationSection.GetSection(LogLevelKey);
				if (logLevelSection != null)
				{
					// Load logger specific rules
					string logger = configurationSection.Key;
					LoadRules(options, logLevelSection, logger);
				}
			}
		}

		[UnconditionalSuppressMessage("ReflectionAnalysis", "IL2026:RequiresUnreferencedCode",
			Justification = "IConfiguration.GetValue is safe when T is a bool.")]
		bool GetCaptureScopesValue(LoggerFilterOptions options) => _configuration.GetValue(nameof(options.CaptureScopes), options.CaptureScopes);
	}

	private static void LoadRules(LoggerFilterOptions options, IConfigurationSection configurationSection, string? logger)
	{
		foreach (System.Collections.Generic.KeyValuePair<string, string?> section in configurationSection.AsEnumerable(true))
		{
			if (TryGetSwitch(section.Value, out LogLevel level))
			{
				string? category = section.Key;
				if (category.Equals(DefaultCategory, StringComparison.OrdinalIgnoreCase))
				{
					category = null;
				}
				var newRule = new LoggerFilterRule(logger, category, level, null);
				options.Rules.Add(newRule);
			}
		}
	}

	private static bool TryGetSwitch(string? value, out LogLevel level)
	{
		if (string.IsNullOrEmpty(value))
		{
			level = LogLevel.None;
			return false;
		}
		else if (Enum.TryParse(value, true, out level))
		{
			return true;
		}
		else
		{
			throw new InvalidOperationException(SR.Format(SR.ValueNotSupported, value));
		}
	}
}

而这些是对配置中的规则的处理,最终得到的是 miniLevel,每次写日志的时候会先将当前日志信息的级别和配置的最低级别进行比较,如果我们还有在代码中通过 AddFilter 扩展方法增加的额外的规则的化,会在配置规则过滤完成之后再过滤(也就是说,Filter 中是不会有低于配置的级别的日志的),如果都不通过,则不会转到最终的记录器。

image

image

2.3.5 日志作用域

有些时候,我们可能希望某一些日志集中在一起显示,或者在进行一些强关联的逻辑操作时,希望记录的日志中保留有关联信息,这时候就可以使用日志作用域。日志作用域依赖于特定的日志记录提供程序的支持,并不是所有的提供程序都支持,内置的提供程序中 Console、AzureAppServicesFile 和 AzureAppServicesBlob 提供了相应的支持。可以通过以下的方式启用日志作用域:

(1) 通过日志记录器的 BeginScope 创建作用域,并使用 using 块包装。

[ApiController]
[Route("[controller]/[action]")]
public class WeatherForecastController : ControllerBase
{
	private readonly ILogger<WeatherForecastController> _logger;

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

	[HttpGet]
	public Task Get()
	{
		// 创建一个日志域,以下日志会被当作一个整体
		using (_logger.BeginScope("this is a log scope"))
		{
			// 除了使用特定级别的API,也可以使用Log方法,动态指定级别
			_logger.Log(LogLevel.Information, "logging a scope info.");
			_logger.Log(LogLevel.Warning, "logging a scope warning.");
		}

		return Task.CompletedTask;
	}
}

(2) 在配置中针对日志提供程序添加 "IncludeScopes: true" 配置

{
  "Logging": {
    "LogLevel": {
      "Default": "Trace",
      "Microsoft.AspNetCore": "Warning"
    },
    "Console": {
      "IncludeScopes": true,
      "LogLevel": {
        "Default": "Information",
        "Microsoft.AspNetCore": "Warning"
      }
    }
  }
}

image

从最终的输出中可以看到,同一个作用域中记录的日志都带上了创建作用域时设置的标记。同时也可以看到,记录的日志中多了 SpanId、TraceId、ParentId 这些内容,这是日志记录系统隐式创建范围对象,这些信息源自于每一次的Http 请求,方便对一次 Http 请求中各个步骤的跟踪。对于这些信息的配置,可以通过 ActivityTrackingOptions 设置。

var builder = WebApplication.CreateBuilder(args);
builder.Logging.Configure(option =>
{
    option.ActivityTrackingOptions = ActivityTrackingOptions.SpanId | ActivityTrackingOptions.TraceId;
});

image

以下是一些注意点:

  • 若要在 Startup.Configure 方法中记录日志,直接在参数上注入 ILogger<Startup> 即可。
  • 不支持在 Startup.ConfigureServices 方法中使用 ILogger,因为此时 DI 容器还未配置完成。
  • 没有异步的日志记录方法。日志记录动作执行应该很快,不值的牺牲性能使用异步方法。如果日志记录动作比较耗时,如记录到 MSSQL 中,那么请不要直接写入 MSSQL。你应该考虑先将日志写入到快速存储介质,如内存队列,然后通过后台工作线程将其从内存转储到 MSSQL 中。
  • 无法使用日志记录 API 在应用运行时更改日志记录配置。不过,一些配置提供程序(如文件配置提供程序)可重新加载配置,这可以立即更新日志记录配置。


参考文章:

.NET Core 和 ASP.NET Core 中的日志记录 | Microsoft Learn
理解ASP.NET Core - 日志(Logging) - xiaoxiaotank - 博客园 (cnblogs.com)



ASP.NET Core 系列:

目录:ASP.NET Core 系列总结
上一篇:ASP.NET Core - 缓存之分布式缓存
下一篇:[ASP.NET Core - 日志记录系统(二)]

posted @ 2023-07-19 22:39  啊晚  阅读(3183)  评论(2编辑  收藏  举报