Logging Tips in .NET
Serilog
Serilog is the most widely used logging framework in the .NET community, so I'll dedicate a section to explain how to use it.
The example project is in Demo2.Console.
Create a console application and include the following two packages:
Serilog.Sinks.Console
Serilog.Sinks.File
Additionally, there are
Serilog.Sinks.Elasticsearch,Serilog.Sinks.RabbitMQ, etc. Serilog provides sinks for writing log events to storage in various formats. Many of the sinks listed below are developed and maintained by the broader Serilog community; https://github.com/serilog/serilog/wiki/Provided-Sinks
You can configure Serilog directly using code:
private static Serilog.ILogger GetLogger()
{
const string LogTemplate = "{SourceContext} {Scope} {Timestamp:HH:mm} [{Level}] {Message:lj} {Properties:j} {NewLine}{Exception}";
var logger = new LoggerConfiguration()
.Enrich.WithMachineName()
.Enrich.WithThreadId()
.Enrich.FromLogContext()
#if DEBUG
.MinimumLevel.Debug()
#else
.MinimumLevel.Information()
#endif
.WriteTo.Console(outputTemplate: LogTemplate)
.WriteTo.File("log.txt", rollingInterval: RollingInterval.Day, outputTemplate: LogTemplate)
.CreateLogger();
return logger;
}
If you want to load from a configuration file, add Serilog.Settings.Configuration:
private static Serilog.ILogger GetJsonLogger()
{
IConfiguration configuration = new ConfigurationBuilder()
.SetBasePath(AppContext.BaseDirectory)
.AddJsonFile(path: "serilog.json", optional: true, reloadOnChange: true)
.Build();
if (configuration == null)
{
throw new ArgumentNullException($"Unable to find the serilog.json log configuration file");
}
var logger = new LoggerConfiguration()
.ReadFrom.Configuration(configuration)
.CreateLogger();
return logger;
}
Example of the serilog.json configuration file:
{
"Serilog": {
"Using": [ "Serilog.Sinks.Console", "Serilog.Sinks.File" ],
"MinimumLevel": {
"Default": "Debug"
},
"Enrich": [ "FromLogContext", "WithMachineName", "WithThreadId" ],
"WriteTo": [
{
"Name": "Console",
"Args": {
"outputTemplate": "{SourceContext} {Scope} {Timestamp:HH:mm} [{Level}] {Message:lj} {Properties:j} {NewLine}{Exception}"
}
},
{
"Name": "File",
"Args": {
"path": "logs/log-.txt",
"rollingInterval": "Day",
"outputTemplate": "{SourceContext} {Scope} {Timestamp:HH:mm} [{Level}] {Message:lj} {Properties:j} {NewLine}{Exception}"
}
}
]
}
}
Injecting Serilog with Dependency Injection.
Include the Serilog.Extensions.Logging package.
private static Microsoft.Extensions.Logging.ILogger InjectLogger()
{
var logger = GetJsonLogger();
var ioc = new ServiceCollection();
ioc.AddLogging(builder => builder.AddSerilog(logger: logger, dispose: true));
var loggerProvider = ioc.BuildServiceProvider().GetRequiredService<ILoggerProvider>();
return loggerProvider.CreateLogger("Program");
}
Finally, configure Serilog logging in different ways and start the program to print logs.
static void Main()
{
var log1 = GetLogger();
log1.Debug("溪源More、痴者工良");
var log2 = GetJsonLogger();
log2.Debug("溪源More、痴者工良");
var log3 = InjectLogger();
log3.LogDebug("溪源More、痴者工良");
}
20:50 [Debug] 溪源More、痴者工良 {"MachineName": "WIN-KQDULADM5LA", "ThreadId": 1}
20:50 [Debug] 溪源More、痴者工良 {"MachineName": "WIN-KQDULADM5LA", "ThreadId": 1}
20:50 [Debug] 溪源More、痴者工良 {"MachineName": "WIN-KQDULADM5LA", "ThreadId": 1}
Using Logging in ASP.NET Core
The example project is in Demo2.Api.
Create a new ASP.NET Core API project and include the Serilog.AspNetCore package.
In Program, add code to inject Serilog.
var builder = WebApplication.CreateBuilder(args);
Log.Logger = new LoggerConfiguration()
.ReadFrom.Configuration(builder.Configuration)
.CreateLogger();
builder.Host.UseSerilog(Log.Logger);
// builder.Host.UseSerilog();
Copy the content of the serilog.json file from earlier into appsettings.json.
After starting the program, try accessing the API interface, and you will see logs printed as shown below:
Microsoft.AspNetCore.Hosting.Diagnostics 20:32 [Information] Request finished HTTP/1.1 GET http://localhost:5148/WeatherForecast - - - 200 - application/json;+charset=utf-8 1029.4319ms {"ElapsedMilliseconds": 1029.4319, "StatusCode": 200, "ContentType": "application/json; charset=utf-8", "ContentLength": null, "Protocol": "HTTP/1.1", "Method": "GET", "Scheme": "http", "Host": "localhost:5148", "PathBase": "", "Path": "/WeatherForecast", "QueryString": "", "EventId": {"Id": 2}, "RequestId": "0HMOONQO5ONKU:00000003", "RequestPath": "/WeatherForecast", "ConnectionId": "0HMOONQO5ONKU"}
If you want to add some property information to the request context, you can add a middleware, as shown below:
app.UseSerilogRequestLogging(options =>
{
options.EnrichDiagnosticContext = (diagnosticContext, httpContext) =>
{
diagnosticContext.Set("TraceId", httpContext.TraceIdentifier);
};
});
HTTP GET /WeatherForecast responded 200 in 181.9992 ms {"TraceId": "0HMSD1OUG2DHG:00000003" ... ...
Adding property information, such as the current user's information for the request context, allows the logs printed during this request's scope to include these context information, which is helpful for log analysis. This makes it easier to determine which log entries belong to the same context. In microservices scenarios, tools like ElasticSearch may be used to query and analyze logs. If relevant context properties are added to the logs, they can be queried during analysis, helping to diagnose issues.
If you need to log HTTP request and response information, you can use the built-in HttpLoggingMiddleware in ASP.NET Core.
First, register the request logging service.
builder.Services.AddHttpLogging(logging =>
{
logging.LoggingFields = HttpLoggingFields.All;
// To avoid printing large amounts of request and response content, only log 4kb
logging.RequestBodyLogLimit = 4096;
logging.ResponseBodyLogLimit = 4096;
});
By combining the HttpLoggingFields enumeration, you can configure the middleware to print Request, Query, HttpMethod, Header, Response and other information.
You may place the HttpLogging middleware after Swagger and Static, so that it can avoid logging requests that are not useful, retaining just the API request logs.
app.UseHttpLogging();
The logging mode in HttpLoggingMiddleware is printed at the Information level. Therefore, after the project goes live, if every request is logged, it will degrade system performance. To avoid printing ordinary logs, you can override the configuration in the configuration file.
"Microsoft.AspNetCore.HttpLogging.HttpLoggingMiddleware": "Information"
Context Properties and Scope
The example project is in Demo2.ScopeLog.
Logging scope considerations
Microsoft.Extensions.Logging.Abstractions provides the BeginScope API, which can be used to add any properties to log events within a specific area of code.
Explaining its function
The API has two forms:
IDisposable BeginScope<TState>(TState state)
IDisposable BeginScope(this ILogger logger, string messageFormat, params object[] args)
Use the following template:
{SourceContext} {Timestamp:HH:mm} [{Level}] (ThreadId:{ThreadId}) {Message}{NewLine}{Exception} {Scope}
Example of usage:
static void Main()
{
var logger = GetLogger();
using (logger.BeginScope("Checking mail"))
{
// Scope is "Checking mail"
logger.LogInformation("Opening SMTP connection");
using (logger.BeginScope("Downloading messages"))
{
// Scope is "Checking mail" -> "Downloading messages"
logger.LogError("Connection interrupted");
}
}
}
In addition to supporting the above interfaces, Serilog provides a way to inject context properties into logs through LogContext. This allows the logs to carry these context property information when logs are printed within its scope.
using (LogContext.PushProperty("Test", 1))
{
// Process request; all logged events will carry `RequestId`
Log.Information("{Test} Adding {Item} to cart {CartId}", 1,1);
}
A more complex nested example:
using (LogContext.PushProperty("A", 1))
{
log.Information("Carries property A = 1");
using (LogContext.PushProperty("A", 2))
using (LogContext.PushProperty("B", 1))
{
log.Information("Carries A = 2 and B = 1");
}
log.Information("Carries property A = 1, again");
}
When you need to set a large number of properties, the following approach can be tedious:
using (LogContext.PushProperty("Test1", 1))
using (LogContext.PushProperty("Test2", 2))
{
}
For example, in an ASP.NET Core middleware, we can add a batch:
public async Task InvokeAsync(HttpContext context, RequestDelegate next)
{
var enrichers = new List<ILogEventEnricher>();
if (!string.IsNullOrEmpty(correlationId))
{
enrichers.Add(new PropertyEnricher(_options.EnricherPropertyNames.CorrelationId, correlationId));
}
using (LogContext.Push(enrichers.ToArray()))
{
await next(context);
}
}
In a business system, you can obtain user information from the token in the middleware and then inject it into the log context so that the printed logs will carry user information.
Non-intrusive Logging
There are various methods for non-intrusive logging, such as using the ASP.NET Core middleware pipeline or using AOP frameworks.
Here you can use my open-source CZGL.AOP framework, which can be found in Nuget.
The example project is in Demo2.AopLog.
We have a type that needs to log before and after executing SayHello, recording the parameters and return values.
public class Hello
{
public virtual string SayHello(string content)
{
var str = $"Hello,{content}";
return str;
}
}
A unified interception code will be written, which will execute when the function is called.
Before will be effective before the proxy method is executed or the proxy property is called. You can use AspectContext to get or modify the parameters passed.
After is effective after the method execution or property call, allowing you to get or modify the return value.
public class LogAttribute : ActionAttribute
{
public override void Before(AspectContext context)
{
Console.WriteLine($"{context.MethodInfo.Name} function is being executed before");
foreach (var item in context.MethodValues)
Console.WriteLine(item.ToString());
}
public override object After(AspectContext context)
{
Console.WriteLine($"{context.MethodInfo.Name} function is being executed after");
Console.WriteLine(context.MethodResult.ToString());
return context.MethodResult;
}
}
Transform the Hello class, the code is as follows:
[Interceptor]
public class Hello
{
[Log]
public virtual string SayHello(string content)
{
var str = $"Hello,{content}";
return str;
}
}
Then create a proxy type:
static void Main(string[] args)
{
Hello hello = AopInterceptor.CreateProxyOfClass<Hello>();
hello.SayHello("any one");
Console.Read();
}
When the program starts, it will output:
SayHello function is being executed before
any one
SayHello function is being executed after
Hello,any one
You don't need to worry about the AOP framework causing performance issues in your program, as the CZGL.AOP framework is written using EMIT and includes caching, meaning that once a type is proxied, it does not need to be regenerated.
CZGL.AOP can be used in conjunction with the built-in dependency injection framework of .NET Core and Autofac, automatically proxying services in the CI container. This eliminates the need for manual calls to the proxy interface `AopInterceptor.CreateProxyOfClass`.
The CZGL.AOP code is open source, and you can refer to another article by the author:
[https://www.cnblogs.com/whuanle/p/13160139.html](https://www.cnblogs.com/whuanle/p/13160139.html)
文章评论