使用 NLog 給 Asp.Net Core 做請求監控

為了減少由於單個請求掛掉而拖垮整站的情況發生，給所有請求做統計是一個不錯的解決方法，通過觀察哪些請求的耗時比較長，我們就可以找到對應的介面、代碼、數據表，做有針對性的優化可以提高效率。在 asp.net web api 中我們可以通過註冊一個 DelegatingHandler 來實現該功能。那在 asp.net core 中該如何實現呢？

一：比較 asp.net web api 和 asp.net core 的請求管道

觀察這兩張圖，可以發現他們非常的相似，都是管道式的設計，在 asp.net web api 中，我們可以註冊一系列的 DelegatingHandler 來處理請求上下文 HttpRequestMessage，在 asp.net core 中，我們可以註冊一系列中間件來處理請求上下文，他們兩者從功能和意義上是非常相似的，我這裡這裡不會詳細介紹各自的管道是如何的（這樣的文章非常多，博客園隨處可見），他們都完成了類似中間件的功能，只是在代碼設計上有一點區別。

我們先看一段代碼，新建一個 asp.net web api 項目，添加幾個 DelegatinHandler

    public class DelegatingHandler1 : DelegatingHandler
    {
        protected override async Task<HttpResponseMessage> SendAsync(HttpRequestMessage request, CancellationToken cancellationToken)
        {
            Trace.WriteLine("DelegatingHandler1 HashCode: " + this.GetHashCode());
            Trace.WriteLine("DelegatingHandler1 base InnerHandler HashCode: " + base.InnerHandler.GetHashCode());
            Trace.WriteLine("DelegatingHandler1 start");
            var response = await base.SendAsync(request, cancellationToken);
            Trace.WriteLine("DelegatingHandler1 end");
            return response;
        }
    }
    public class DelegatingHandler2 : DelegatingHandler
    {
        protected override async Task<HttpResponseMessage> SendAsync(HttpRequestMessage request, CancellationToken cancellationToken)
        {
            Trace.WriteLine("DelegatingHandler2 HashCode: " + this.GetHashCode());
            Trace.WriteLine("DelegatingHandler2 base InnerHandler HashCode: " + base.InnerHandler.GetHashCode());
            Trace.WriteLine("DelegatingHandler2 start");
            var response = await base.SendAsync(request, cancellationToken);
            Trace.WriteLine("DelegatingHandler2 end");
            return response;
        }
    }
    public class DelegatingHandler3 : DelegatingHandler
    {
        protected override async Task<HttpResponseMessage> SendAsync(HttpRequestMessage request, CancellationToken cancellationToken)
        {
            Trace.WriteLine("DelegatingHandler3 HashCode: " + this.GetHashCode());
            Trace.WriteLine("DelegatingHandler3 base InnerHandler HashCode: " + base.InnerHandler.GetHashCode());
            Trace.WriteLine("DelegatingHandler3 start");
            var response = await base.SendAsync(request, cancellationToken);
            Trace.WriteLine("DelegatingHandler3 end");
            return response;
        }
    }

然後在 Global 中註冊

    public class WebApiApplication : System.Web.HttpApplication
    {
        protected void Application_Start()
        {
            AreaRegistration.RegisterAllAreas();
            GlobalConfiguration.Configure(WebApiConfig.Register);
            FilterConfig.RegisterGlobalFilters(GlobalFilters.Filters);
            RouteConfig.RegisterRoutes(RouteTable.Routes);
            BundleConfig.RegisterBundles(BundleTable.Bundles);

            GlobalConfiguration.Configuration.MessageHandlers.Add(new DelegatingHandler1());
            GlobalConfiguration.Configuration.MessageHandlers.Add(new DelegatingHandler2());
            GlobalConfiguration.Configuration.MessageHandlers.Add(new DelegatingHandler3());
        }
    }

修改一下 ValuesController

    public class ValuesController : ApiController
    {
        // GET api/values
        public IEnumerable<string> Get()
        {
            Trace.WriteLine("/api/values");
            var handlers = this.RequestContext.Configuration.MessageHandlers;
            return new string[] { "value1", "value2" };
        }
    }

啟動後輸入路徑 /api/values，我們可以在VS 的輸出欄看到下麵這些內容

DelegatingHandler1 HashCode: 58154627
DelegatingHandler1 base InnerHandler HashCode: 35529478
DelegatingHandler1 start
DelegatingHandler2 HashCode: 35529478
DelegatingHandler2 base InnerHandler HashCode: 47422476
DelegatingHandler2 start
DelegatingHandler3 HashCode: 47422476
DelegatingHandler3 base InnerHandler HashCode: 65273341
DelegatingHandler3 start
/api/values
DelegatingHandler3 end
DelegatingHandler2 end
DelegatingHandler1 end

輸出中我們可以看到 DelegatingHandler1 的 InnerHandler 是 DelegatingHandler2，以此類推，在 DelegatingHandler3 的 InnerHandler 處理請求的時候就轉發到了相關控制器，這裡和 .net core 中的中間件非常相似，在.net core 中間件順序是 RequestServicesContainerMiddleware（給請求上下文綁定容器）-> AuthenticationMiddleware（認證）-> RouterMiddleware （路由以及MVC）

如果我們在 ValuesController 中觀察表達式 this.RequestContext.Configuration.MessageHandlers 還可以看到最終處理請求的是一個 HttpRoutingDispatcher，最也是是分配到路由以及控制器來處理的，按照如此方式我們可以很容易在 asp.net web api 中對請求統計。這裡是比較簡陋的，對此我們可以記錄客戶端和伺服器更詳細的信息，包括 IP 地址，http狀態碼，是否是認證用戶等等，但是這篇主要是以 asp.net core 為主的，所以這裡就不詳細寫下去了。

    public class ApplicationInsight : DelegatingHandler
    {
        protected override async Task<HttpResponseMessage> SendAsync(HttpRequestMessage request, CancellationToken cancellationToken)
        {
            var stopWatch = new Stopwatch();
            stopWatch.Start();

            var response = await base.SendAsync(request, cancellationToken);

            stopWatch.Stop();
            //停止計時器，並記錄
        }
    }
    public partial class Startup
    {
        public void Configuration(IAppBuilder app)
        {
            GlobalConfiguration.Configuration.MessageHandlers.Add(new ApplicationInsight());
        }
    }

 二：asp.net core 中間件 + NLog 實現請求監控

 先看統計結果，start 開始時間，time 是請求消耗時間（毫秒），authenicate 是認證通過的 schema，使用 NLog 自定義欄位也是非常方便的

先說一說遇到的問題

（1）NLog 記錄一張以上的表如何實現，應為首先會有一個一般性的日誌表（稱他為 log），並且這些統計不對寫到 log 表

（2）使用 NLog 自定義欄位 LayoutRenderer 沒有類似 .net framework 中的 System.Web.Current

（3）使用 UseMiddleware 無法在讓我們的中間件成為第一個中間件

（4）實現忽略記錄的方法，肯定有一些介面是不希望記錄的，所以這個也要實現

 NLog 配置

這裡只列出了部分內容，github 地址在最後，資料庫是 mysql ，apiinsight 表示請求統計，log 是一般性的日誌，debughelper 可以加快我們調試時日誌的檢索速度

<targets>
    <!--黑洞 忽略的日誌-->
    <target xsi:type="Null"
            name="blackhole" />
    <!--文件日誌-->
    <target xsi:type="File"
        name="debughelper"
        fileName="${var:root}\Logs\debug_helper.log"
        layout="${longdate}|${event-properties:item=EventId.Id}|${logger}|${uppercase:${level}}|${message} ${exception}" />
    <!--apiinsight api 統計-->
    <target name="apiinsight" xsi:type="Database"
             dbProvider="MySql.Data.MySqlClient.MySqlConnection, MySql.Data"
             connectionString="${var:connectionString}"
             >
    </target>
    <!--日誌-->
    <target name="log" xsi:type="Database"
         dbProvider="MySql.Data.MySqlClient.MySqlConnection, MySql.Data"
         connectionString="${var:connectionString}"
             >
    </target>
  </targets>

在 Startup 中

public void Configure(IApplicationBuilder app, IHostingEnvironment env)
{
    //省略了其他配置

    //全局的 HttpContext
    app.UseGlobalHttpContext();

    //省略了其他配置

    LogManager.Configuration = new XmlLoggingConfiguration(Path.Combine(env.ContentRootPath, "nlog.config"));
    LogManager.Configuration.Variables["root"] = env.ContentRootPath;
    LogManager.Configuration.Variables["connectionString"] = Configuration.GetConnectionString("DefaultConnection");
}

 自定義欄位都是通過 LayoutRenderer 實現，由於自定義欄位有很多，這裡只列出了一個開始時間是如何查詢的，這個時間是在我們註冊的第一個中間件執行 Invoke 方法的時候寫進 HttpContext.Items 的

    [LayoutRenderer("apiinsight-start")]
    public class StartApiInsightRenderer : LayoutRenderer
    {
        protected override void Append(StringBuilder builder, LogEventInfo logEvent)
        {
            var httpContext = HttpContextProvider.Current;
            if (httpContext == null)
            {
                return;
            }
            var _apiInsightsKeys = httpContext.RequestServices.GetService<IApiInsightsKeys>();

            if (httpContext != null)
            {
                if (httpContext.Items.TryGetValue(_apiInsightsKeys.StartTimeName, out var start) == true)
                {
                    builder.Append(start.ToString());
                }
            }
        }
    }

 NLog 規則，很容易理解日誌統計只記錄 Cheers 命名空間下的日誌

  <rules>
    <!--需要記錄的日誌-->
    <logger name="Cheers.*" minlevel="Trace" writeTo="apiinsight" />
    <logger name="WebApp.*" minlevel="Info" writeTo="log" />
    <logger name="*" minlevel="Trace" maxlevel="Debug" writeTo="debughelper" />

    <!--忽略的日誌-->
    <logger name="Microsoft.*" minlevel="Trace" writeTo="blackhole" final="true" />
  </rules>

 核心 ApiInsightMiddleware 中間件

    public class ApiInsightMiddleware
    {
        private readonly RequestDelegate _next;
        private readonly IServiceProvider _serverProvider;
        private readonly IApiInsightsKeys _apiInsightsKeys;
        private readonly ILogger<ApiInsightMiddleware> _logger;
        private HttpContext _httpContext;

        public ApiInsightMiddleware(RequestDelegate next, IServiceProvider serviceProvider, ILogger<ApiInsightMiddleware> logger)
        {
            _next = next;
            _serverProvider = serviceProvider;
            _apiInsightsKeys = _serverProvider.GetService<IApiInsightsKeys>();
            _logger = logger;
        }

        public async Task Invoke(HttpContext httpContext)
        {
            _httpContext = httpContext;
            var flag = SetValues();

            await _next(httpContext);

            if (flag == true)
            {
                ApiInsight();
            }
        }
        //省略了其他的代碼
    }

很好理解，在執行下一個中間件之前調用 SetValues 開始計時，下一個中間件執行成功開始統計並寫入日誌（或者忽略不寫）。現在他是 asp.net core mvc 的第一個中間件了，好處就是更符合這個中間件本身的所做的事情了，但是帶來的問題就是 httpContext.RequestService 是 null ，因為 RequestService 是在 RequestServicesContainerMiddleware 這個中間件寫進去的，在者其實很多地方我們都需要 HttpContext ，並且目前微軟還沒有給我們定義一個靜態的 HttpContext。

靜態的 HttpContext

HttpContext 是通過單例 IHttpContextAccessor 提供的，當 HttpContext 創建的時候就會賦值給他，當請求到達中間件這個管道的時候，HttpContext 就已經存在於 IHttpContextAccessor 了，並且和 Invoke 參數列表中的 HttpContext 是一致的（同一個請求中），問題在於 RequestServicesContainerMiddleware 這個中間件沒有執行就沒有容器，並且很多時候我們都要用到容器，所以就模仿源碼在這裡都加進去了。

    public static class HttpContextProvider
    {
        private static IHttpContextAccessor _accessor;
        private static IServiceScopeFactory _serviceScopeFactory;

        public static Microsoft.AspNetCore.Http.HttpContext Current
        {
            get
            {
                var context = _accessor?.HttpContext;

                if (context != null)
                {
                    var replacementFeature = new RequestServicesFeature(_serviceScopeFactory);
                    context.Features.Set<IServiceProvidersFeature>(replacementFeature);

                    return context;
                }

                return null;
            }
        }

        internal static void ConfigureAccessor(IHttpContextAccessor accessor, IServiceScopeFactory serviceScopeFactory)
        {
            _accessor = accessor;
            _serviceScopeFactory = serviceScopeFactory;
        }
    }
    public static class HttpContextExtenstion
    {
        public static void AddHttpContextAccessor(this IServiceCollection services)
        {
            services.AddSingleton<IHttpContextAccessor, HttpContextAccessor>();
        }

        public static IApplicationBuilder UseGlobalHttpContext(this IApplicationBuilder app)
        {
            var httpContextAccessor = app.ApplicationServices.GetRequiredService<IHttpContextAccessor>();
            var serviceScopeFactory = app.ApplicationServices.GetRequiredService<IServiceScopeFactory>();
            HttpContextProvider.ConfigureAccessor(httpContextAccessor, serviceScopeFactory);
            return app;
        }
    }

我們只需要在 Startup 中使用 app.UseGlobalHttpContext(); 就可以在程式的任何地方得到 HttpContext 和容器了，肯定會有人說為什麼不通過構造函數來獲取我們想要的註入呢，因為有些第三方框架或這某些地方我們不能使用容器獲取服務，比如這裡 NLog 的自定義欄位使用的 LayoutRenderer 就無法通過構造器得到我們想要的服務。

第一個中間件

在 Startup 的 Configure 方法中目前還沒發現如何註冊第一個中間件，因為 Configure 方法始終是在 IStartupFilter 這個介面之後執行的，這也提供了我們讓自己的中間件成為第一個中間件的可能。可能這樣做並不是特別有必要，甚至是沒有意義的，但是實現的過程確實很有意思的。這裡在 Startup 中的 方法 ConfigureService 註冊我們的中間件。

    public void ConfigureServices(IServiceCollection services)
    {
        services.AddApiInsights();
        services.AddMvc();
    }

具體的

    public static class ApiInsightsServiceCollectionExtensions
    {
        static readonly string stopWatchName = "__stopwatch__";
        static readonly string startTimeName = "__start__";

        /// <summary>
        ///     註冊和 API 監控相關的服務，中間件
        /// </summary>
        /// <param name="services"></param>
        public static void AddApiInsights(this IServiceCollection services)
        {
            services.AddSingleton<IApiInsightsKeys>(
                    new ApiInsightsKeys(stopWatchName, startTimeName)
                );
            services.FirstRegister<IStartupFilter, RequestApiInsightBeginStartupFilter>(ServiceCollectionServiceExtensions.AddTransient<IStartupFilter, RequestApiInsightBeginStartupFilter>);
            services.AddSingleton<IRequestIsAuthenticate, DefaultRequestIsAuthenticate>();
        }
    }

這裡註冊了三個服務

IApiInsightsKeys

定義了存儲在 HttpContext.Item 中的鍵值對的名稱

   public interface IApiInsightsKeys
    {
        string StopWatchName { get; }
        string StartTimeName { get; }
    }

IRequestIsAuthenticate

    /// <summary>
    ///     驗證請求用戶是否已經認證
    /// </summary>
    public interface IRequestIsAuthenticate
    {
        /// <summary>
        ///     返回已經認證的 scheme
        /// </summary>
        /// <returns></returns>
        Task<string> IsAuthenticateAsync();
        /// <summary>
        ///     返回已經認證的 用戶名
        /// </summary>
        /// <returns></returns>
        Task<string> AuthenticatedUserName();
    }

就驗證而言可能不同的開發者使用的是不一樣的驗證方式，可能是基於 Asp.Net Core Authentication 中間件的認證方式，也可能是其他的比如自定義的 token，或者有一個單點登錄的伺服器，又或者是 session，其實 Asp.Net Core 的 Authentication 中間件也可以幫我們實現基於 restful 的token 認證。所以就把它定義出來了，並且預設的實現就是基於 Authentication 這個中間件的。

IStartupFilter

看到他是一個非常特殊的方式來註冊的，自定義的 FirstRegister 這個方法，實際上 Asp.Net Core 內置有多個 IStartup 這樣的服務，並且都是在 Startup 的 Configure 之前執行的，所以這裡一定要用這個服務來讓我們的中間件成為第一個中間件。FirstRegister 代碼也很容易理解，由於在宿主啟動之前，內部註冊了多個 IStartup，並且最後會按先後順序配置 IApplicationBuilder，所以我們只能讓第一個 StartupFilter 的 IApplicationBuilder 就註冊我們的中間件，通過改動 ServiceCollection 中服務的順序可以實現。雖然不是很有必要，但是可以從中觀察的 Startup 的 Configure方法 以及 介面StartupFilter （還有 IHostingStartup ）的執行順序。

    public class RequestApiInsightBeginStartupFilter : IStartupFilter
    {
        public Action<IApplicationBuilder> Configure(Action<IApplicationBuilder> next)
        {
            return builder =>
            {
                builder.UseMiddleware<RequestApiInsightBeginMiddleware>();
                next(builder);
            };
        }
    }

忽略的方法

    [AttributeUsage(AttributeTargets.Method, AllowMultiple = false, Inherited = true)]
    public class NoInsightAttribute : Attribute
    {
    }

在 ApiInsight 方法中會調用 IsIgnore 檢測該方法是否打了標簽 NoInsightAttribute，如果是那就忽略該方法，這裡建議使用特性路由，原因有兩點，第一特性路由不需要使用 IActionSelector 介面重新查找匹配的方法，第二，在 restful api 中，結合特性路由和 HttpMethodAttribute 標簽可以使方法更簡潔，相同的介面名稱通過不同的請求方式達到不同的目的

    private bool IsIgnore()
    {
        var actionDescriptor = GetSelectedActionDescriptor() as ControllerActionDescriptor;
        if (actionDescriptor == null)
        {
            return false;
        }
        else
        {
            var noInsight = actionDescriptor.MethodInfo.GetCustomAttribute<NoInsightAttribute>();
            return noInsight != null;
        }
    }

程式地址:https://github.com/cheesebar/ApiInsights