Detailed explanation of how to record and view logs in ASP. NET Core applications, asp. netcore

Detailed explanation of how to record and view logs in ASP. NET Core applications, asp. netcore

Logging is not only an important feature for our developed applications, but also for the ASP. NET Core framework. We know that ASP. NET Core uses a highly scalable log system consisting of three Core objects: Logger, LoggerFactory, and LoggerProvider. We can customize LoggerFactory through simple configuration and add LoggerProvider.

1. Configure LoggerFactory

In the previous section, we demonstrated an instance that displays the default registration service of ASP. NET Core. The displayed list contains the service for LoggerFactory. If the default LoggerFactory service cannot meet our needs, we can configure any LoggerFactory. For LoggerFactory settings, we can directly call the UseLoggerFactory method of WebHostBuilder to implement it.

public interface IWebHostBuilder  {    IWebHostBuilder UseLoggerFactory(ILoggerFactory loggerFactory);    IWebHostBuilder ConfigureLogging(Action<ILoggerFactory> configureLogging);    ...  }

However, the configuration for logs is more reflected in the addition of some LoggerProvider, which can be done by calling the ConfigureLogging method of WebHostBuilder. In the example demonstrated above, we used the following method to register a ConsoleLoggerProvider on LoggerFactory, so that we can directly view the recorded log information on the extended platform of the Host application.

 new WebHostBuilder()    .ConfigureLogging(factory=>factory.AddConsole())    ...

Since LoggerFactory has been registered as a service, we get this object based on dependency injection and use it to create the corresponding Logger object to write logs. If we need to write some type of logs in a defined middleware, we can inject this LoggerFactory by defining the ILoggerFactory type parameter in the Invoke method as follows.

 public class FoobarMiddleware  {    private RequestDelegate _next;       public FoobarMiddleware(RequestDelegate next)    {      _next = next;    }       public async Task Invoke(HttpContext context, ILoggerFactory loggerFactory)    {      ILogger<FoobarMiddleware> logger = loggerFactory.CreateLogger<FoobarMiddleware>();      logger.LogInformation("...");      await _next(context);    }  }

Not only do we develop applications or middleware that can use the registered LoggerFactory to create a Logger object for logging, ASP. the NET Core pipeline itself also records some logs in the same way during request processing. For example, the pipeline will write two Information-level logs at the beginning and end of each request processing. Now we will use a simple example to see what the two logs have.

public class Program  {    public static void Main()    {      new WebHostBuilder()        .ConfigureLogging(factory=>factory.AddConsole())        .UseKestrel()        .UseStartup<Startup>()                .Build()        .Run();    }  }    public class Startup  {    public void Configure(IApplicationBuilder app, ILoggerFactory loggerFactory)    {      app.Run(async context =>      {        loggerFactory.CreateLogger("App").LogInformation("Log entry for test...");        await context.Response.WriteAsync("Hello world!");      });    }  }

The code shown above is related to logs. The first is to call the ConfigureLogging method of WebHostBuilder and add a ConsoleProvider to the current LoggerFactory by calling the extension method AddConsole, in addition, the middleware registered by the Configure method of the startup class will use the injected LoggerFactory to create a Logger object during execution. We use the latter to write a log of Information level. After we run the program and use a browser to access the target address, three logs shown in are displayed on the host console. Except that the second log is written by the code we write, the other two logs are written by the ASP. NET Core framework. The first log contains not only the target address of the request, but also the Protocol (HTTP/1.1) and HTTP method (GET) used by the request ), article 3 reflects the time spent in the whole request processing process.

Because ASP. the NET Core pipeline always processes requests in an execution context created by HttpApplication. Therefore, context creation and release recovery can be regarded as the start and end of the request processing process. The logs written at the request start and end are recorded when the CreateContext and DisposeContext methods of HostingApplication are called. The reason why the whole request processing time can be calculated at the end of the process is that the created context object stores the timestamp for starting request processing, the timestamp corresponds to the StartTimestamp attribute of the Context structure.

 public class HostingApplication IHttpApplication<HostingApplication.Context>  {    public struct Context    {      public HttpContext   HttpContext { get; set; }      public IDisposable   Scope { get; set; }      public long     StartTimestamp { get; set; }    }  }

Ii. Use the current request as the log range

We know that the log system has a concept called "log range", which aims to create a context range for multiple related log records and provide a unique identifier for this range, this identifier is written as part of the log Content. When analyzing logs, we can associate a group of originally independent logs according to the log range identifier. This concept is especially important for Web applications, because in many cases, log analysis is performed on a request, this requires us to clearly identify which request the recorded log belongs, only in this way can we extract all the logs for the same request for a comprehensive analysis to reach an accurate conclusion.

From the three logs finally written to the previous instance, they do not carry the identity information of the current request. However, this is not a problem with ASP. NET Core, but we did not explicitly enable log range support when calling the extension method AddConsole of LoggerFactory to register ConsoleLoggerProvider. To enable the Logger created by the registered ConsoleLoggerProvider to support the log range, we only need to add an additional parameter (true) when calling the AddConsole method as follows.

 new WebHostBuilder()    .ConfigureLogging(factory=>factory.AddConsole(true))    .UseKestrel()    .UseStartup<Startup>()            .Build()    .Run();

We request the application again and send two requests to the target address using the browser. The six logs will be output to the console as shown in. Different from the above output results, the output log contains the Request ID, and the logs recorded in the same Request have the same Id. In addition to the Request ID, the recorded Log also carries the Request Path ).

The ID carried by the log range that uniquely identifies the current request. It can also be regarded as the unique identifier of the current HttpContext, which corresponds to the TranceIdentifier attribute of HttpContext. For DefaultHttpContext, the read and write operations for this attribute are implemented by using a feature called HttpRequestIdentifierFeature. The following Code provides the IHttpRequestIdentifierFeature interface corresponding to this object and the default implementation class HttpRequestIdentifierFeature.

Public abstract class HttpContext {// omit other members public abstract string TraceIdentifier {get; set ;}} public interface IHttpRequestIdentifierFeature {string TraceIdentifier {get; set ;}} public class HttpRequestIdentifierFeature IHttpRequestIdentifierFeature {private string _ id; private static long _ requestId = DateTime. utcNow. ticks; private static unsafe string GenerateRequestId (long id); public String TraceIdentifier {get {return _ id ?? (Id = GenerateRequestId (Interlocked. Increment (ref _ requestId);} set {this. _ id = value ;}}}

The logic for HttpRequestIdentifierFeature to generate TraceIdentifier is simple. As shown in the code snippet above, it has a static long integer field _ requestId whose initial value is the current timestamp. For a specific HttpRequestIdentifierFeature object, the default value of its TraceIdentifier attribute returns the string converted after this field _ requestId is added with 1. The specific conversion logic is defined in the GenerateRequestId method. It uses the corresponding algorithm to convert the specified integer to a string of 13.

Like the timestamp for starting request processing, the created log range is actually saved in the Context object of the HostingApplication, which corresponds to the Scope attribute of the Context structure. When HostingApplication creates this Context object, it extracts the Request ID and path from the current HttpContext, creates this log range, and assigns the value to this attribute. The whole request is actually processed in this log range. The request processing is complete, and the current log model is also recycled and released.

 public class HostingApplication IHttpApplication<HostingApplication.Context>  {    public struct Context    {      public HttpContext   HttpContext { get; set; }      public IDisposable   Scope { get; set; }      public long      StartTimestamp { get; set; }    }  }

3. Record abnormal logs

Exceptions caused by ASP. NET Core processing requests do not cause application termination. For security reasons, detailed information about thrown exceptions cannot be directly returned to the client. Therefore, in many cases, we cannot even detect exceptions in the application. Even if we detect exceptions, we do not know where the root cause is. In this case, we need to use the recorded logs for errors and error correction, because ASP. NET Core records all exceptions encountered during request processing.

For example, for the following program, it will undoubtedly throw a DivideByZeroException exception for any request processing. If we use a browser to access the site address, it will only get a 500 response, and a simple prompt that the server has an error. For the Host Program, we simply cannot perceive any exceptions.

 new WebHostBuilder()    .UseKestrel()    .Configure(app=>app.Run(async context=> {      int x = 1;      int y = 0;      await context.Response.WriteAsync((x / y).ToString());    }))    .Build()  .Run();

In this case, you can view the log to get detailed information about the exception, but before that, you must register the corresponding LoggerProvider for LoggerFactory. If we use the console application as the host, the simplest way to develop or debug is to register a ConsoleLoggerProvider as follows so that logs can be directly written to the console of the Host Program.

 new WebHostBuilder()    .ConfigureLogging(factory=>factory.AddConsole (true))    .UseKestrel()    .Configure(app=>app.Run(async context=> {      int x = 1;      int y = 0;      await context.Response.WriteAsync((x / y).ToString());    }))    .Build()    .Run();

Once such a ConsoleLoggerProvider is registered for LoggerFactory, we can directly view the error details on the host console for any unhandled exceptions on the server, is the detailed information about the DivideByZeroException thrown in the preceding example.

The above is all the content of this article. I hope it will be helpful for your learning and support for helping customers.