天天看點
傳回

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

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

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

使用 NLog 給 Asp.Net Core 做請求監控
使用 NLog 給 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 自定義字段也是非常友善的

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

先說一說遇到的問題

（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

上一篇: Asp.Net Core 2.0 項目實戰（6）Redis配置、封裝幫助類RedisHelper及使用執行個體
下一篇: git入門三(遠端、标簽)