.NetCore WebApi通过中间件实现参数的日志打印

线上环境为了防止上下游扯皮，是有必要把接口的输入输出打印到日志中的，这样出了问题能够快速定位问题，没出问题也能直接把日志糊在对面脸上抓紧时间下班。

之前在.Net FrameWork的实现其实挺简单的，就是Global.aspx里的生命周期函数里写上就可以了，但是转到core之后，想当然的使用Filter来实现，遇到了不少问题，比如使用ActionFilter时，触发过滤器的时候，RequestBody实际上已经被Action读过一次了，也就是说Body已经被加载到Action的参数中了，而Request.Body对象实际上是个Stream，默认情况下只能读取一次，这时候去读Body实际上只是个空字符串了，虽然有解决方案，但是需要使用参数名才能获取到Action的Body参数，不太符合需求。

后来发现应该使用中间件来干这个事情，但是实现过程中还是遇到了点坑，首先就是用StreamReader读取RequestBody的时候，不能使用using，因为StreamReader被Dispose的时候，Body也被干了，等到接口内部读取Body的时候就会报错。

其次就是必须声明Body是可重复读取的，这个比较简单：Request.EnableBuffering();就可以了。

下面废话不多说，直接上完整代码：

    public class LogMiddleware:IMiddleware
    {
        static long GetNowTimestamp()
        {
            return (DateTime.Now.ToUniversalTime().Ticks - 621355968000000000) / 10000;
        }

        public async Task InvokeAsync(HttpContext context, RequestDelegate next)
        {
            var originalBody = context.Request.Body;

            try
            {
                var requestID = Guid.NewGuid().ToString();

                var Request = context.Request;
                Request.Headers.Add("WikiRequestId", requestID);
                Request.Headers.Add("WikiRequestTime", GetNowTimestamp().ToString());
                StringBuilder parmsb = new StringBuilder();

                #region url参数
                var urlcontent = string.Empty;
                if (Request.Query.Keys != null && Request.Query.Keys.Count > 0)
                {
                    foreach (var key in Request.Query.Keys)
                    {
                        parmsb.Append($"{key}={Request.Query[key]},");
                    }

                    urlcontent = parmsb.ToString().TrimEnd(',');
                }
                #endregion
                #region Header
                StringBuilder headersb = new StringBuilder();
                var headercontent = string.Empty;
                if (Request.Headers.Keys != null && Request.Headers.Keys.Count > 0)
                {
                    foreach (var key in Request.Headers.Keys)
                    {
                        parmsb.Append($"{key}={Request.Headers[key]},");
                    }
                    headercontent = parmsb.ToString().TrimEnd(',');
                }
                #endregion
                #region body参数
                var bodycontent = string.Empty;
                Request.EnableBuffering();
                var sr = new StreamReader(Request.Body);
                string requestBody = await sr.ReadToEndAsync();
                if (requestBody != string.Empty)
                {
                    bodycontent = requestBody;
                }
                Request.Body.Position = 0;
                #endregion

                LoggerHelper.Instance().LogInfo($"请求开始时间{DateTime.Now.ToString("yyyy-MM-dd HH:mm:ss:fff")}{Environment.NewLine}RequestId：{requestID}{Environment.NewLine}请求路径：{Request.Path}{Environment.NewLine}Url参数:{urlcontent}{Environment.NewLine}Body参数:{bodycontent}头部：{headercontent}");
            }
            catch (Exception ex)
            {
                LoggerHelper.Instance().LogInfo($"OnActionExecuting失败：{ex?.Message}_{ex.StackTrace?.ToString()}");
            }

            await next(context);

            try
            {
                var Request = context.Request;
                //获取请求时间差值
                var WikiRequestTime = Request.Headers["WikiRequestTime"].ToString();
                var totalrequestTime = GetNowTimestamp() - Convert.ToInt64(WikiRequestTime);
                if (totalrequestTime < 500)
                {
                    LoggerHelper.Instance().LogInfo($"请求结束：{DateTime.Now.ToString("yyyy-MM-dd HH:mm:ss:fff")}{Environment.NewLine}RequestId：{Request.Headers["WikiRequestId"]}");
                }
                else
                {
                    ThreadPool.GetMinThreads(out int workerThreads, out int completionPortThreads);
                    ThreadPool.GetAvailableThreads(out var available, out _);
                    ThreadPool.GetMaxThreads(out var max, out _);
                    var busythreads = max - available;
                    var outputstring = $"请求结束：{DateTime.Now.ToString("yyyy-MM-dd HH:mm:ss:fff")}{Environment.NewLine}RequestId：{Request.Headers["WikiRequestId"].ToString()}" +
                        $"{Environment.NewLine}DefaultMinThreads: {completionPortThreads}{Environment.NewLine}MaxThread:{max}{Environment.NewLine}AvailableThread:{available}" +
                        $"{Environment.NewLine}BusyThreads:{busythreads}{Environment.NewLine}Total:{totalrequestTime}";
                    LoggerHelper.Instance().LogWarn(outputstring);
                }
            }
            catch (Exception ex)
            {
                LoggerHelper.Instance().LogInfo($"OnActionExecuted失败：{ex?.Message}_{ex.StackTrace?.ToString()}");
            }
        }
    }

这里需要注意的就是await next(context); 这个实际上就是调用下一个中间件，直到调用到一个没有next的中间件，方法自然返回，就开始结束这次请求的流程了，而.NetCore访问Action本质上也是中间件的一环，所以简单来说，await next(context);上面的代码就是request请求进来，await next(context);下面就是response出去了。

最后就是注册这个中间件了：

        public void Configure(IApplicationBuilder app, IWebHostEnvironment env)
        {
            if (env.IsDevelopment())
            {
                app.UseDeveloperExceptionPage();
            }
            app.UseSwagger();
            app.UseSwaggerUI(c =>
            {
                c.SwaggerEndpoint("/swagger/v1/swagger.json", "Wikibit.WebAPI.New v1");
                //c.DefaultModelsExpandDepth(-1); //设置为 - 1 可不显示models
                //c.DocExpansion(Swashbuckle.AspNetCore.SwaggerUI.DocExpansion.None); //设置为none可折叠所有方法
            });
            app.UseHttpsRedirection();

            app.UseRouting();

            app.UseAuthorization();

            app.Use((context, next) =>
            {
                context.Request.EnableBuffering();
                return next();
            });

            app.UseMiddleware<LogMiddleware>();

            app.UseEndpoints(endpoints =>
            {
                endpoints.MapControllers();
            });
        }

app.UseMiddleware();就是注册中间件，而app.Use((context,next)=> next());则是匿名中间件。