为了确定什么样的信息会被作为诊断日志记录下来,我们通过一个简单的实例演示将HostingApplication对象写入的诊断日志输出到控制台上。HostingApplication对象会将相同的诊断信息以三种不同的方式进行记录,其中包含第8章“诊断日志(中篇)”介绍的日志系统。
如下的演示程序利用WebApplicationBuilder的Logging属性得到返回的ILoggingBuilder对象,并调用它的AddSimpleConsole扩展方法为默认注册的ConsoleLoggerProvider开启了针对日志范围的支持。我们最后调用IApplicationBuilder接口的Run扩展方法注册了一个中间件,该中间件在处理请求时会利用依赖注入容器提取出用于发送日志事件的ILogger<Program>对象,并利用它写入一条Information等级的日志。如果请求路径为“/error”,那么该中间件会抛出一个InvalidOperationException类型的异常。
var builder = WebApplication.CreateBuilder(args); builder.Logging.AddSimpleConsole( options => options.IncludeScopes = true); var app = builder.Build(); app.Run(HandleAsync); app.Run(); static Task HandleAsync(HttpContext httpContext) { // 堆代码 duidaima.com var logger = httpContext.RequestServices .GetRequiredService<ILogger<Program>>(); logger.LogInformation($"Log for event Foobar"); if (httpContext.Request.Path == new PathString("/error")) { throw new InvalidOperationException("Manually throw exception."); } return Task.CompletedTask; }
在启动程序之后,我们利用浏览器采用不同的路径(“/foobar”和“/error”)向应用发送了两次请求,控制台上会输出如图1所示的七条日志。由于开启了日志范围的支持,所以输出的日志都会携带日志范围的信息,日志范围提供了很多有用的分布式跟踪信息,比如Trace ID、Span ID、Parent Span ID以及请求的ID和路径等。
请求ID(Request ID),它由当前的连接ID和一个序列号组成。从图1可以看出,两次请求的ID分别是“0HMG97FD188VR:00000002”和“0HMG97FD188VR:00000003”。由于采用的是长连接,并且两次请求共享同一个连接,所以它们具有相同的连接ID(“0HMG97FD188VR”)。同一连接的多次请求将一个自增的序列号(“00000002”和“00000003”)作为唯一标识。
public class DiagnosticCollector { [DiagnosticName("Microsoft.AspNetCore.Hosting.BeginRequest")] public void OnRequestStart( HttpContext httpContext, long timestamp) { // 堆代码 duidaima.com var request = httpContext.Request; Console.WriteLine( $"\nRequest starting {request.Protocol} {request.Method} {request.Scheme}://{request.Host}{request.PathBase}{request.Path}"); httpContext.Items["StartTimestamp"] = timestamp; } [DiagnosticName("Microsoft.AspNetCore.Hosting.EndRequest")] public void OnRequestEnd( HttpContext httpContext, long timestamp) { var startTimestamp = long.Parse( httpContext.Items["StartTimestamp"]!.ToString()); var timestampToTicks = TimeSpan.TicksPerSecond / (double)Stopwatch.Frequency; var elapsed = new TimeSpan((long)( timestampToTicks * (timestamp - startTimestamp))); Console.WriteLine( $"Request finished in {elapsed.TotalMilliseconds}ms {httpContext.Response.StatusCode}"); } [DiagnosticName("Microsoft.AspNetCore.Hosting.UnhandledException")] public void OnException( HttpContext httpContext, long timestamp, Exception exception) { OnRequestEnd(httpContext, timestamp); Console.WriteLine( $"{exception.Message}\nType:{exception.GetType()}\nStacktrace: {exception.StackTrace}"); } }
针对“开始请求”事件的OnRequestStart方法输出了当前请求的HTTP版本、HTTP方法和URL。为了能够计算整个请求处理的耗时,它将当前时间戳保存在HttpContext上下文的Items集合中。针对“结束请求”事件的OnRequestEnd方法将这个时间戳从HttpContext上下文中提取出来,结合当前时间戳计算出请求处理耗时,该耗时和响应的状态码最终会被写入控制台。
针对“未处理异常”诊断事件的OnException方法则在调用OnRequestEnd方法之后将异常的消息、类型和跟踪堆栈输出到控制台上。如下所示的演示程序中利用WebApplication的Services提供的依赖注入容器提取出注册的DiagnosticListener对象,并调用它的SubscribeWithAdapter扩展方法将DiagnosticCollector对象注册为订阅者。我们调用Run扩展方法注册了一个中间件,该中间件会在请求路径为“/error”的情况下抛出异常。
using App; using System.Diagnostics; var builder = WebApplication.CreateBuilder(args); builder.Logging.ClearProviders(); var app = builder.Build(); var listener = app.Services .GetRequiredService<DiagnosticListener>(); listener.SubscribeWithAdapter(new DiagnosticCollector()); app.Run(HandleAsync); app.Run(); static Task HandleAsync(HttpContext httpContext) { var listener = httpContext.RequestServices .GetRequiredService<DiagnosticListener>(); if (httpContext.Request.Path == new PathString("/error")) { throw new InvalidOperationException("Manually throw exception."); } return Task.CompletedTask; }待演示实例正常启动后,可以采用不同的路径(“/foobar”和“/error”)对应用程序发送两个请求,服务端控制台会以图2所示的形式输出DiagnosticCollector对象收集的诊断信息。
using System.Diagnostics.Tracing; var listener = new DiagnosticCollector(); listener.EventSourceCreated += (sender, args) => { if (args.EventSource?.Name == "Microsoft.AspNetCore.Hosting") { listener.EnableEvents( args.EventSource, EventLevel.LogAlways); } }; listener.EventWritten += (sender, args) => { Console.WriteLine(args.EventName); for (int index = 0; index < args.PayloadNames?.Count; index++) { Console.WriteLine( $"\t{args.PayloadNames[index]} = {args.Payload?[index]}"); } }; var builder = WebApplication.CreateBuilder(args); builder.Logging.ClearProviders(); var app = builder.Build(); app.Run(HandleAsync); app.Run(); static Task HandleAsync(HttpContext httpContext) { if (httpContext.Request.Path == new PathString("/error")) { throw new InvalidOperationException( "Manually throw exception."); } return Task.CompletedTask; } public class DiagnosticCollector : EventListener { }
以命令行的形式启动这个演示程序后,从图3所示的输出结果可以看到名为HostStart的事件被发出。然后我们采用目标地址“http://localhost:5000/foobar”和“http:// http://localhost:5000/error”对应用程序发送两个请求,从输出结果可以看出,应用程序针对前者的处理过程会发出RequestStart事件和RequestStop事件,针对后者的处理则会因为抛出的异常发出额外的事件UnhandledException。
输入“Ctrl+C”关闭应用后,名称为HostStop的事件被发出。对于通过EventSource发出的五个事件,只有RequestStart事件会将请求的HTTP方法(GET)和路径(“/foobar”和“/error”)作为负载内容,其他事件都不会携带任何负载内容。