Using NLog to do request monitoring for ASP. Net core

Time:2019-12-22

In order to reduce the situation that a single request hangs up and drags down the whole station, it is a good solution to make statistics for all requests. By observing which requests take a long time, we can find the corresponding interface, code and data table. Targeted optimization can improve efficiency. In asp.net web API, we can register a delegatinghandler to achieve this function. How to implement it in asp.net core?

1: Comparing the request pipeline between asp.net web API and asp.net core

 

Looking at these two diagrams, we can find that they are very similar, both of them are pipeline design. In asp.net web API, we can register a series of delegatinghandlers to process the request context httprequestmessage. In asp.net core, we can register a series of middleware to process the request context. They are very similar in function and meaning Yes, I won’t go into details about their respective pipelines here (there are many articles like this, and blog parks can be seen everywhere). They have completed similar middleware functions, but there is a little difference in code design.

Let’s take a look at the code first, create a new asp.net web API project, and add several delegatinhandlers

Then register in global


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;
    }
  }

Modify valuescontroller


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());
    }
  }

After startup, input the path / API / values. We can see the following in the output column of vs


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" };
    }
  }

After startup, input the path / API / values. We can see the following in the output column of 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

In the output, we can see that the innerhandler of delegatinghandler1 is delegatinghandler2, and so on. When the innerhandler of delegatinghandler3 processes the request, it is forwarded to the relevant controller. Here, it is very similar to the middleware in. Net core. The order of the middleware in. Net core is requestservicescontainermiddleware Binding container – > authenticationmiddleware – > routermiddleware (routing and MVC)

If we observe the expression this.requestcontext.configuration.messagehandlers in valuescontroller, we can also see that the final processing request is an httproutingdispatcher, which is assigned to the routing and controller to process. In this way, we can easily count the requests in asp.net web API. This is relatively simple. We can record more detailed information about the client and server, including IP address, HTTP status code, whether it is an authenticated user, etc., but this article is mainly based on asp.net core, so we won’t write it in detail here.

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();
      //Stop the timer and record
    }
  }
  public partial class Startup
  {
    public void Configuration(IAppBuilder app)
    {
      GlobalConfiguration.Configuration.MessageHandlers.Add(new ApplicationInsight());
    }
  }

2: Asp.net core middleware + NLog to realize request monitoring

First look at the statistical results. Start start time, time is the request consumption time (milliseconds), and authenticate is the authenticated schema. It is also very convenient to use NLog custom fields

Let’s talk about the problems

(1) NLog records how to implement more than one table. It should be that there will be a general log table (called log) first, and these statistics will not be written to the log table

(2) Using NLog custom field layoutrenderer is not similar to system.web.current in. Net framework

(3) Using usemiddleware can’t make our middleware the first Middleware

(4) To implement the method of ignoring records, there must be some interfaces that do not want to be recorded, so this should also be implemented

NLog configuration

Only part of the content is listed here. At the end of the GitHub address, the database is mysql, apiinsight represents request statistics, log is a general log, and debugher can speed up the retrieval of logs when we debug

<targets>
  <! -- logs ignored by black holes -- >
  <target xsi:type="Null"
      name="blackhole" />
  <! -- File log -- >
  <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 statistics -- >
  <target name="apiinsight" xsi:type="Database"
       dbProvider="MySql.Data.MySqlClient.MySqlConnection, MySql.Data"
       connectionString="${var:connectionString}"
       >
  </target>
  <! -- log -- >
  <target name="log" xsi:type="Database"
     dbProvider="MySql.Data.MySqlClient.MySqlConnection, MySql.Data"
     connectionString="${var:connectionString}"
       >
  </target>
 </targets>

In startup

public void Configure(IApplicationBuilder app, IHostingEnvironment env)
{
  //Other configurations are omitted

  //Global httpcontext
  app.UseGlobalHttpContext();

  //Other configurations are omitted

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

Custom fields are implemented through layoutrenderer. Because there are many custom fields, only one start time is listed here. This time is written into httpcontext.items when the first middleware we registered executes invoke method


[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 rule, it is easy to understand that log statistics only records logs under the cheers namespace

<rules>
  <! -- log to be recorded -- >
  <logger name="Cheers.*" minlevel="Trace" writeTo="apiinsight" />
  <logger name="WebApp.*" minlevel="Info" writeTo="log" />
  <logger name="*" minlevel="Trace" maxlevel="Debug" writeTo="debughelper" />

  <! -- ignored logs -- >
  <logger name="Microsoft.*" minlevel="Trace" writeTo="blackhole" final="true" />
 </rules>

Core API insight Middleware

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();
      }
    }
    //Other code omitted
  }

It is well understood that the SetValues will start counting before executing the next middleware, and the next middleware will succeed in starting statistics and writing logs (or ignoring not writing). Now it is the first middleware of asp.net core MVC. The advantage is that it is more in line with what the middleware itself does. But the problem is that httpcontext.requestservice is null, because requestservice is written in the middleware requestservicescontainermiddleware. In fact, we need httpcontext in many places, At present, Microsoft has not defined a static httpcontext for us.

Static httpcontext

Httpcontext is provided by a single example ihttpcontextaccessor. When httpcontext is created, it will be assigned to it. When the request reaches the middleware pipeline, httpcontext already exists in ihttpcontextaccessor, and it is consistent with httpcontext in the invoke parameter column table (in the same request). The problem is requestservicescon There is no container without the execution of the middleware, and many times we need to use the container, so we add the imitation source code here.


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;
    }
  }

We only need to use app. Useglobalhttpcontext() in startup; we can get httpcontext and container anywhere in the program. Someone will surely say why we don’t use constructors to get the injection we want, because some third-party frameworks or some places we can’t use containers to get services, such as NLog’s custom fields The layoutrenderer of cannot get the service we want through the constructor.

First Middleware

How to register the first middleware has not been found in the configuration method of startup, because the configuration method is always executed after the interface of istartupfilter, which also provides the possibility for us to make our middleware the first middleware. It may not be necessary or even meaningless to do so, but the implementation process is really interesting. Here we register our Middleware in the method configureservice in startup.


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

Concrete

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

    /// <summary>
    ///Register services and middleware related to API monitoring
    /// </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>();
    }
  }

Three services are registered here

IApiInsightsKeys

Defines the name of the key value pair stored in httpcontext.item


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

IRequestIsAuthenticate

/// <summary>
  ///Verify that the requesting user is authenticated
  /// </summary>
  public interface IRequestIsAuthenticate
  {
    /// <summary>
    ///Return authenticated scheme
    /// </summary>
    /// <returns></returns>
    Task<string> IsAuthenticateAsync();
    /// <summary>
    ///Return authenticated user name
    /// </summary>
    /// <returns></returns>
    Task<string> AuthenticatedUserName();
  }

In terms of authentication, different developers may use different authentication methods, which may be based on ASP. Net core authentication middleware, or other authentication methods, such as custom token, a single sign on server, or session. In fact, the authentication middleware of ASP. Net core can also help us to implement authentication based on Token authentication of restful. So it is defined, and the default implementation is based on the middleware authentication.

IStartupFilter

See that it is a very special way to register. In fact, ASP. Net core has multiple services such as istartup built-in, which are executed before the configuration of startup, so we must use this service to make our middleware the first middleware. The first register code is also easy to understand. Before the host starts, multiple istartups are registered internally, and iaapplicationbuilder will be configured in sequence at last, so we can only let the iaapplicationbuilder of the first startupfilter register our middleware, which can be realized by changing the order of services in the servicecollection. Although not necessary, you can observe the configuration method of startup and the execution order of the interface startupfilter (and ihostingstartup).


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

Ignored method


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

In the apiinsight method, isignore will be called to check whether the method is labeled with noinsightattribute. If it is, the method will be ignored. Here it is recommended to use characteristic route. There are two reasons. First, characteristic route does not need to use the iactionselector interface to find the matching method again. Second, in the restful API, combine characteristic route and httpmethodattribute label It can make the method more concise, and the same interface name can achieve different purposes through different requests


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

Program address: https://github.com/cheesebar/apiinsights

The above is the whole content of this article. I hope it will help you in your study, and I hope you can support developepaer more.