记录一次Nginx转发请求给Ocelot网关响应500错误排查

Posted 2022-12-07 娃都会打酱油了

先说明下我们的Http请求流转及系统部署方式：当Http请求发起时，会先到达nginx，然后Nignx会将请求转发至Ocelot网关服务，Ocelot网关服务会再将请求转发给下游真实提供API服务的应用，我们的应用是基于Net Core 3.1，服务提供方式也是默认的Kestrel，然后所有的服务均部署在Linux环境的Docker容器中，容器的管理工具为Portainer。

产生500错误的是一个新的API接口，在这个接口之前，系统已经运行了一年多，从没产生过类似的问题，这个500还不是必定产生，多次请求时会偶发性产生，而且毫无规律。

产生问题，第一点看日志，因为我们在Ocelot网关做了统一的全局日志，所以可以先看下日志，日志如下图：

The response ended prematurely

查了下这个异常，没啥好的发现，所以只能怀疑是不是代码有Bug，因为该API依赖于其它部门提供的低代码平台SDK，底层存储用的也是Mongodb和mysql，但本地反复测试下来，无论如何都不会产生异常！那会不会是数据问题导致的呢？在项目的launchSettings.json中，将environmentVariables改为对应环境配置，直接拿测试环境数据进行测试，反复调用API，结果也是毫无问题！这就奇了怪了，抱着侥幸心理再用Postman去调用测试环境API，果然侥幸是没用的，还是必然会出现偶发性的500错误，那结论应该不是代码的问题，而是环境导致的问题。

既然推断问题应该是环境问题，那么先从配置确认，检查下来测试环境配置与本地测试配置基本一致，仅有的Docker环境变量设置也未涉及该API，所以应该大概率不是配置问题。既然从概率上讲不太可能是配置问题，那我们继续推导下面哪种情况可能会产生问题，难道是Docker问题，想了想就觉得这不太可能，Docker更多的是网络问题或者存储问题，如果是网络问题，那么就必定是通与不通两种情况，不可能会出现这种偶发性的500情况。

难道是Ocelot问题？因为我们所有的请求都是通过Ocelot进行转发的，引入Ocelot是通过OcelotMiddlewareExtensions.UseOcelot方法，打开项目源码，通过F12一路找下去，可以发现在OcelotPipelineExtensions.BuildOcelotPipeline集中了所有的中间件注册过程，按中间件注册顺序一路看下去，最终在HttpRequesterMiddleware代码中，可以看到关键代码是下面这段

        public async Task Invoke(HttpContext httpContext)
        
            var downstreamRoute = httpContext.Items.DownstreamRoute();

            var response = await _requester.GetResponse(httpContext);

            CreateLogBasedOnResponse(response);

            if (response.IsError)
            
                Logger.LogDebug("IHttpRequester returned an error, setting pipeline error");

                httpContext.Items.UpsertErrors(response.Errors);
                return;
            

            Logger.LogDebug("setting http response message");

            httpContext.Items.UpsertDownstreamResponse(new DownstreamResponse(response.Data));

            await _next.Invoke(httpContext);
        

Ctrl+F12直接查看GetResponse都做了啥

        public async Task<Response<HttpResponseMessage>> GetResponse(HttpContext httpContext)
        
            var builder = new HttpClientBuilder(_factory, _cacheHandlers, _logger);

            var downstreamRoute = httpContext.Items.DownstreamRoute();

            var downstreamRequest = httpContext.Items.DownstreamRequest();

            var httpClient = builder.Create(downstreamRoute);

            try
            
                var response = await httpClient.SendAsync(downstreamRequest.ToHttpRequestMessage(), httpContext.RequestAborted);
                return new OkResponse<HttpResponseMessage>(response);
            
            catch (Exception exception)
            
                var error = _mapper.Map(exception);
                return new ErrorResponse<HttpResponseMessage>(error);
            
            finally
            
                builder.Save();
            
        

看代码是直接通过HttpClient向下游API请求数据，看起来没啥问题，既然没问题，那我们就在Portainer中将网关服务也通过端口直接暴露出来，然后直接Postman模拟请求看看会不会有问题（其实正常应该一开始就该这么做，只是突然想去看看Ocelot都做了啥，哈哈），事实证明一切都正常，所以Ocelot也跟这500错误没有关系！

排查到这里，唯一还剩下的可疑对象就只有Nginx了，服务器上的Nginx不好排查，那么就直接在本地装个Nginx，然后将测试环境的nginx.conf中location部分配置复制到本地，在打开监控利器Fiddler，本地用Postman随便调用了几次，就得到了下图

正常返回的响应大小应该为83473，而异常部分返回的响应大小居然只有70315，对比一开始就记录到的异常信息The response ended prematurely，似乎是数据被异常截断没有完整返回！本地调试网关项目，将Nginx请求转发给本地，用Postman分别直接调用网关服务和通过Nginx转发调用，然后在全局日志中间件部分看下两边的请求参数究竟有啥不同


可以看到参数在HeaderConnection上不同，直接调用是keep-alive，而Nginx转发后是close，Connection默认是keep-alive，所以应该是Nginx转发时出了问题，再查下资料，得到Nginx设置长连接，对比下Nginx配置，果然相应的配置缺失

proxy_http_version 1.1;              # 设置http版本为1.1
proxy_set_header Connection "";      # 设置Connection为长连接（默认为no）

在Nginx配置中加上配置后，重启Nginx，果然每次请求都不会再出现500问题，问题解决。

好吧，再想个问题，为什么Connection不设置为keep-alive就会产生数据返回不全问题呢？如果Kestrel能够一次返回100kb以上的数据，那就算Connection设置为close，应该也不会产生500错误了吧，毕竟Nginx为什么要默认设置proxy_set_header Connection为close呢，虽然对Nginx不是很熟，但肯定有它的道理吧。KestrelServerOptions.Limits的MaxResponseBufferSize看着挺像的，但看其说明，如果不设置，默认是返回65536，也就是64kb，似乎和70315对不上，然后尝试在程序里设置了下，测试下来貌似也没用，哎，以后再看看如何设置响应大小吧

        public static IHostBuilder CreateHostBuilder(string[] args) =>
            Microsoft.Extensions.Hosting.Host.CreateDefaultBuilder(args)
                .ConfigureWebHostDefaults(webBuilder =>
                
                    webBuilder
                    .ConfigureKestrel(opt =>
                    
                        opt.Limits.MaxResponseBufferSize = 1024;
                    )
                    .UseStartup<Startup>();
                )
                .UseNLog();

再补充个docker swarm里设置log保留限制命令，一般情况下默认是保留5个，但可能通过脚本部署时，会将这个值设置为1，这样查看日志就不方便了

docker swarm update --task-history-limit 3