ASP.NET Core管道详解[3]: Pipeline = IServer + IHttpApplication

ASP.NET Core的请求处理管道由一个服务器和一组中间件构成,但对于面向传输层的服务器来说,它其实没有中间件的概念。当服务器接收到请求之后,会将该请求分发给一个处理器进行处理,对服务器而言,这个处理器就是一个HTTP应用,此应用通过IHttpApplication<TContext>接口来表示。由于服务器是通过IServer接口表示的,所以可以将ASP.NET Core框架的核心视为由IServer和IHttpApplication<TContext>对象组成的管道。[本文节选自《ASP.NET Core 3框架揭秘》第13章, 更多关于ASP.NET Core的文章请点这里]

2

目录
一、服务器(IServer)
二、承载应用( HostingApplication)
三、应用生命周期和请求日志
     ILogger日志
     DiagnosticSource诊断日志
     EventSource事件日志

一、服务器(IServer)

由于服务器是整个请求处理管道的“龙头”,所以启动和关闭应用的最终目的是启动和关闭服务器。ASP.NET Core框架中的服务器通过IServer接口来表示,该接口具有如下所示的3个成员,其中由服务器提供的特性就保存在其Features属性表示的IFeatureCollection集合中。IServer接口的StartAsync<TContext>方法与StopAsync方法分别用来启动和关闭服务器。

public interface IServer : IDisposable
{
    IFeatureCollection Features { get; }

    Task StartAsync<TContext>(IHttpApplication<TContext> application, CancellationToken cancellationToken);
    Task StopAsync(CancellationToken cancellationToken);
}

服务器在开始监听请求之前总是绑定一个或者多个监听地址,这个地址是应用程序从外部指定的。具体来说,应用程序指定的监听地址会封装成一个特性,并且在服务器启动之前被添加到它的特性集合中。这个承载了监听地址列表的特性通过如下所示的IServerAddressesFeature接口来表示,该接口除了有一个表示地址列表的Addresses属性,还有一个布尔类型的PreferHostingUrls属性,该属性表示如果监听地址同时设置到承载系统配置和服务器上,是否优先考虑使用前者。

public interface IServerAddressesFeature
{
    ICollection<string> Addresses { get; }
    bool PreferHostingUrls { get; set; }
}

正如前面所说,服务器将用来处理由它接收请求的处理器会被视为一个通过IHttpApplication<TContext>接口表示的应用,所以可以将ASP.NET Core的请求处理管道视为IServer对象和IHttpApplication<TContext>对象的组合。当调用IServer对象的StartAsync<TContext>方法启动服务器时,我们需要提供这个用来处理请求的IHttpApplication<TContext>对象。IHttpApplication<TContext>采用基于上下文的请求处理方式,泛型参数TContext代表的就是上下文的类型。在IHttpApplication<TContext>处理请求之前,它需要先创建一个上下文对象,该上下文会在请求处理结束之后被释放。上下文的创建、释放和自身对请求的处理实现在该接口3个对应的方法(CreateContext、DisposeContext和ProcessRequestAsync)中。

public interface IHttpApplication<TContext>
{
    TContext CreateContext(IFeatureCollection contextFeatures);
    void DisposeContext(TContext context, Exception exception); 
    Task ProcessRequestAsync(TContext context);
}

二、承载应用( HostingApplication)

ASP.NET Core框架利用如下所示的HostingApplication类型作为IHttpApplication<TContext>接口的默认实现,它使用一个内嵌的Context类型来表示处理请求的上下文。一个Context对象是对一个HttpContext对象的封装,同时承载了一些与诊断相关的信息。

public class HostingApplication : IHttpApplication<HostingApplication.Context>
{
    ...
    public struct Context
    {
        public HttpContext HttpContext { get; set; }

        public IDisposable Scope { get; set; }
        public long StartTimestamp { get; set; }
        public bool EventLogEnabled { get; set; }
        public Activity Activity { get; set; }
    }
}

HostingApplication对象会在开始和完成请求处理,以及在请求过程中出现异常时发出一些诊断日志事件。具体来说,HostingApplication对象会采用3种不同的诊断日志形式,包括基于DiagnosticSource和EventSource的诊断日志以及基于 .NET Core日志系统的日志。Context除HttpContext外的其他属性都与诊断日志有关。具体来说,Context的Scope是为ILogger创建的针对当前请求的日志范围(第9章有对日志范围的详细介绍),此日志范围会携带唯一标识每个请求的ID,如果注册ILoggerProvider提供的ILogger支持日志范围,它可以将这个请求ID记录下来,那么我们就可以利用这个ID将针对同一请求的多条日志消息组织起来做针对性分析。

HostingApplication对象会在请求结束之后记录当前请求处理的耗时,所以它在开始处理请求时就会记录当前的时间戳,Context的StartTimestamp属性表示开始处理请求的时间戳。它的EventLogEnabled属性表示针对EventSource的事件日志是否开启,而Activity属性则与针对DiagnosticSource的诊断日志有关,Activity代表基于当前请求处理的活动。

虽然ASP.NET Core应用的请求处理完全由HostingApplication对象负责,但是该类型的实现逻辑其实是很简单的,因为它将具体的请求处理分发给一个RequestDelegate对象,该对象表示的正是所有注册中间件组成的委托链。在创建HostingApplication对象时除了需要提供RequestDelegate对象,还需要提供用于创建HttpContext上下文的IHttpContextFactory对象,以及与诊断日志有关的ILogger对象和DiagnosticListener对象,它们被用来创建上面提到过的HostingApplicationDiagnostics对象。

public class HostingApplication : IHttpApplication<HostingApplication.Context>
{
    private readonly RequestDelegate _application;
    private HostingApplicationDiagnostics _diagnostics;
    private readonly IHttpContextFactory _httpContextFactory;

    public HostingApplication(RequestDelegate application, ILogger logger,DiagnosticListener diagnosticSource, IHttpContextFactory httpContextFactory)
    {
        _application = application;
        _diagnostics = new HostingApplicationDiagnostics(logger, diagnosticSource);
        _httpContextFactory = httpContextFactory;
    }

    public Context CreateContext(IFeatureCollection contextFeatures)
    {
        var context = new Context();
        var httpContext = _httpContextFactory.Create(contextFeatures);
        _diagnostics.BeginRequest(httpContext, ref context);
        context.HttpContext = httpContext;
        return context;
    }

    public Task ProcessRequestAsync(Context context) => _application(context.HttpContext);

    public void DisposeContext(Context context, Exception exception)
    {
        var httpContext = context.HttpContext;
        _diagnostics.RequestEnd(httpContext, exception, context);
        _httpContextFactory.Dispose(httpContext);
        _diagnostics.ContextDisposed(context);
    }
}

如上面的代码片段所示,当CreateContext方法被调用时,HostingApplication对象会利用IHttpContextFactory工厂创建出当前HttpContext上下文,并进一步将它封装成一个Context对象。在返回这个Context对象之前,它会调用HostingApplicationDiagnostics对象的BeginRequest方法记录相应的诊断日志。用来真正处理当前请求的ProcessRequestAsync方法比较简单,只需要调用代表中间件委托链的RequestDelegate对象即可。

对于用来释放上下文的DisposeContext方法来说,它会利用IHttpContextFactory对象的Dispose方法来释放创建的HttpContext对象。换句话说,HttpContext上下文的生命周期是由HostingApplication对象控制的。完成针对HttpContext上下文的释放之后,HostingApplication对象会利用HostingApplicationDiagnostics对象记录相应的诊断日志。Context的Scope属性表示的日志范围就是在调用HostingApplicationDiagnostics对象的ContextDisposed方法时释放的。如果将HostingApplication对象引入ASP.NET Core的请求处理管道,那么完整的管道就体现为下图所示的结构。

3

三、应用生命周期和请求日志

很多人可能对ASP.NET Core框架自身记录的诊断日志并不关心,其实很多时候这些日志对纠错排错和性能监控提供了很有用的信息。例如,假设需要创建一个APM(Application Performance Management)来监控ASP.NET Core处理请求的性能及出现的异常,那么我们完全可以将HostingApplication对象记录的日志作为收集的原始数据。实际上,目前很多APM(如Elastic APM和SkyWalking APM等)针对ASP.NET Core应用的客户端都是利用这种方式收集请求调用链信息的。

ILogger日志

为了确定什么样的信息会被作为诊断日志记录下来,下面介绍一个简单的实例,将HostingApplication对象写入的诊断日志输出到控制台上。前面提及,HostingApplication对象会将相同的诊断信息以3种不同的方式进行记录,其中包含日志系统,所以我们可以通过注册对应ILoggerProvider对象的方式将日志内容写入对应的输出渠道。

整个演示实例如下面的代码片段所示:首先通过调用IWebHostBuilder接口的ConfigureLogging方法注册一个ConsoleLoggerProvider对象,并开启针对日志范围的支持。我们调用IApplicationBuilder接口的Run扩展方法注册了一个中间件,该中间件在处理请求时会利用表示当前请求上下文的HttpContext对象得到与之绑定的IServiceProvider对象,并进一步从中提取出用于发送日志事件的ILogger<Program>对象,我们利用它写入一条Information等级的日志。如果请求路径为“/error”,那么该中间件会抛出一个InvalidOperationException类型的异常。

public class Program
{
    public static void Main()
    {
        Host.CreateDefaultBuilder()
            .ConfigureLogging(builder => builder.AddConsole(options => options.IncludeScopes = true))
            .ConfigureWebHostDefaults(builder => builder
                .Configure(app => app.Run(context =>
                {
                    var logger = context.RequestServices.GetRequiredService<ILogger<Program>>();
                    logger.LogInformation($"Log for event Foobar");
                    if (context.Request.Path == new PathString("/error"))
                    {
                        throw new InvalidOperationException("Manually throw exception.");
                    }
                    return Task.CompletedTask;
                })))
            .Build()
            .Run();
    }
}

在启动程序之后,我们利用浏览器采用不同的路径(“/foobar”和“/error”)向应用发送了两次请求,演示程序的控制台上呈现的输出结果如下图所示。由于我们开启了日志范围的支持,所以被ConsoleLogger记录下来的日志都会携带日志范围的信息。日志范围的唯一标识被称为请求ID(Request ID),它由当前的连接ID和一个序列号组成。从图13-4可以看出,两次请求的ID分别是“0HLO4ON65ALGG:00000001”和“0HLO4ON65ALGG:00000002”。由于采用的是长连接,并且两次请求共享同一个连接,所以它们具有相同的连接ID(“0HLO4ON65ALGG”)。同一连接的多次请求将一个自增的序列号(“00000001”和“00000002”)作为唯一标识。

4

除了用于唯一表示每个请求的请求ID,日志范围承载的信息还包括请求指向的路径,这也可以从图13-4所示的输出接口看出来。另外,上述请求ID实际上对应HttpContext类型的TraceIdentifier属性。如果需要进行跨应用的调用链跟踪,所有相关日志就可以通过共享TraceIdentifier属性构建整个调用链。

public abstract class HttpContext
{ 
    public abstract string  TraceIdentifier { get; set; } 
    ...
}

对于两次采用不同路径的请求,控制台共捕获了7条日志,其中类别为App.Program的日志是应用程序自行写入的,HostingApplication写入日志的类别为“Microsoft.AspNetCore.Hosting.Diagnostics”。对于第一次请求的3条日志消息,第一条是在HostingApplication开始处理请求时写入的,我们利用这条日志获知请求的HTTP版本(HTTP/1.1)、HTTP方法(GET)和请求URL。对于包含主体内容的请求,请求主体内容的媒体类型(Content-Type)和大小(Content-Length)也会一并记录下来。当HostingApplication对象处理完请求后会写入第三条日志,日志承载的信息包括请求处理耗时(67.877 6毫秒)和响应状态码(200)。如果响应具有主体内容,对应的媒体类型同样会被记录下来。

对于第二次请求,由于我们人为抛出了一个异常,所以异常的信息被写入日志。但是如果足够仔细,就会发现这条等级为Error的日志并不是由HostingApplication对象写入的,而是作为服务器的KestrelServer写入的,因为该日志采用的类别为“Microsoft.AspNetCore.Server.Kestrel”。换句话说,HostingApplication对象利用ILogger记录的日志中并不包含应用的异常信息。

DiagnosticSource诊断日志

HostingApplication采用的3种日志形式还包括基于DiagnosticSource对象的诊断日志,所以我们可以通过注册诊断监听器来收集诊断信息。如果通过这种方式获取诊断信息,就需要预先知道诊断日志事件的名称和内容荷载的数据结构。通过查看HostingApplication类型的源代码,我们会发现它针对“开始请求”、“结束请求”和“未处理异常”这3类诊断日志事件对应的名称,具体如下。

  • 开始请求:Microsoft.AspNetCore.Hosting.BeginRequest。
  • 结束请求:Microsoft.AspNetCore.Hosting.EndRequest。
  • 未处理异常:Microsoft.AspNetCore.Hosting.UnhandledException。

至于针对诊断日志消息的内容荷载(Payload)的结构,上述3类诊断事件具有两个相同的成员,分别是表示当前请求上下文的HttpContext和通过一个Int64整数表示的当前时间戳,对应的数据成员的名称分别为httpContext和timestamp。对于未处理异常诊断事件,它承载的内容荷载还包括一个额外的成员,那就是表示抛出异常的Exception对象,对应的成员名称为exception。

既然我们已经知道事件的名称和诊断承载数据的成员,所以可以定义如下所示的DiagnosticCollector类型作为诊断监听器(需要针对NuGet包“Microsoft.Extensions.DiagnosticAdapter”的引用)。针对上述3类诊断事件,我们在DiagnosticCollector类型中定义了3个对应的方法,各个方法通过标注的DiagnosticNameAttribute特性设置了对应的诊断事件。我们根据诊断数据承载的结构定义了匹配的参数,所以DiagnosticSource对象写入诊断日志提供的诊断数据将自动绑定到对应的参数上。

public class DiagnosticCollector
{
    [DiagnosticName("Microsoft.AspNetCore.Hosting.BeginRequest")]
    public void OnRequestStart(HttpContext httpContext, long timestamp)
    {
        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方法之后将异常的消息、类型和跟踪堆栈输出到控制台上。

如下面的代码片段所示,在注册的Startup类型中,我们在Configure方法注入DiagnosticListener服务,并调用它的SubscribeWithAdapter扩展方法将上述DiagnosticCollector对象注册为诊断日志的订阅者。与此同时,我们调用IApplicationBuilder接口的Run扩展方法注册了一个中间件,该中间件会在请求路径为“/error”的情况下抛出一个异常。

public class Program
{
    public static void Main()
    {
        Host.CreateDefaultBuilder()
            .ConfigureLogging(builder => builder.ClearProviders())
            .ConfigureWebHostDefaults(builder => builder.UseStartup<Startup>())
            .Build()
            .Run();
    }
}

public class Startup
{
    public void Configure(IApplicationBuilder app, DiagnosticListener listener)
    {
        listener.SubscribeWithAdapter(new DiagnosticCollector());
        app.Run(context =>
        {
            if (context.Request.Path == new PathString("/error"))
            {
                throw new InvalidOperationException("Manually throw exception.");
            }
            return Task.CompletedTask;
        });
    }
}

待演示实例正常启动后,可以采用不同的路径(“/foobar”和“/error”)对应用程序发送两个请求,服务端控制台会以图13-5所示的形式输出DiagnosticCollector对象收集的诊断信息。如果我们试图创建一个针对ASP.NET Core的APM框架来监控请求处理的性能和出现的异常,可以采用这样的方案来收集原始的诊断信息。

5

EventSource事件日志

除了上述两种日志形式,HostingApplication对象针对每个请求的处理过程中还会利用EventSource对象发出相应的日志事件。除此之外,在启动和关闭应用程序(实际上就是启动和关闭IWebHost对象)时,同一个EventSource对象还会被使用。这个EventSource类型采用的名称为Microsoft.AspNetCore.Hosting,上述5个日志事件对应的名称如下。

  • 启动应用程序:HostStart。
  • 开始处理请求:RequestStart。
  • 请求处理结束:RequestStop。
  • 未处理异常:UnhandledException。
  • 关闭应用程序:HostStop。

我们可以通过如下所示的实例来演示如何利用创建的EventListener对象来监听上述5个日志事件。如下面的代码片段所示,我们定义了派生于抽象类EventListener的DiagnosticCollector。在启动应用前,我们创建了这个DiagnosticCollector对象,并通过注册其EventSourceCreated事件开启了针对目标名称为Microsoft.AspNetCore.Hosting的EventSource的监听。在注册的EventWritten事件中,我们将监听到的事件名称的负载内容输出到控制台上。

public class Program
{
    private sealed class DiagnosticCollector : EventListener {}
    static void Main()
    {
        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]}");
            }
        };

        Host.CreateDefaultBuilder()
            .ConfigureLogging(builder => builder.ClearProviders())
            .ConfigureWebHostDefaults(builder => builder
                .Configure(app => app.Run(context =>
                {
                    if (context.Request.Path == new PathString("/error"))
                    {
                        throw new InvalidOperationException("Manually throw exception.");
                    }
                    return Task.CompletedTask;
                })))
            .Build()
            .Run();
    }
}

以命令行的形式启动这个演示程序后,从下图所示的输出结果可以看到名为HostStart的事件被发出。然后采用目标地址“//localhost:5000/foobar”和“// //localhost:5000/error”对应用程序发送两个请求,从输出结果可以看出,应用程序针对前者的处理过程会发出RequestStart事件和RequestStop事件,针对后者的处理则会因为抛出的异常发出额外的事件UnhandledException。输入“Ctrl+C”关闭应用后,名称为HostStop的事件被发出。对于通过EventSource发出的5个事件,只有RequestStart事件会将请求的HTTP方法(GET)和路径(“/foobar”和“/error”)作为负载内容,其他事件都不会携带任何负载内容。

6

请求处理管道[1]: 模拟管道实现
请求处理管道[2]: HttpContext本质论
请求处理管道[3]: Pipeline = IServer +  IHttpApplication<TContext
请求处理管道[4]: 中间件委托链
请求处理管道[5]: 应用承载[上篇
请求处理管道[6]: 应用承载[下篇]