记录一次Nginx使用第三方模块fair导致的线上故障排错

一、问题

今天发现有一台服务器的内存飙升，然后有预警，立即排查，发现该服务内存使用达到了 2G ,询问开发，当天是否有活动，被告知没有，登陆 Pinpoint 发现该服务是有两台机器，并且所有的访问都是到那台内存飙升的机器上面。这就很清楚了，是所有请求到一台服务器，导致的，我们查看那台没有收到任何请求的服务器上，发现服务是启动了，端口也在监听的。

启动日志：

2019-11-05 16:07:09.024 [main] INFO  o.a.coyote.http11.Http11NioProtocol - Initializing ProtocolHandler ["http-nio-18096"]

2019-11-05 16:07:09.061 [main] INFO  o.a.coyote.http11.Http11NioProtocol - Starting ProtocolHandler ["http-nio-18096"]

2019-11-05 16:07:09.062 [main] INFO  o.a.tomcat.util.net.NioSelectorPool - Using a shared selector for servlet write/read

2019-11-05 16:07:09.122 [main] INFO  o.s.b.c.e.t.TomcatEmbeddedServletContainer - Tomcat started on port(s): 18096 (http)

二、故障排查

2.1 第一次排查（服务没有正常启动）

启动日志里面也没有任何异常的报错。我就以为服务是已经启动了，可能是 Nginx 的问题，登陆到 Nginx 服务器进行查看，是配置了 fair 插件的，想着是不是 fair 判断那台服务器内存不够就不把请求转发过去了，我们就把 fair 这个插件去除了。然后 Nginx reload 了一下(16.26这个时间)。不到一分钟，我 Pinpoint 发现有访问到这个服务器上了，心想难道真的是这个问题导致的，不可能啊，然后我回到我控制台(幸好我有个 tail -f ),然后发现下面的，日志。到底是 fair 导致的还是启动没有成功导致的。后面查阅昨天发版日志，发现昨天发版后，下面后面那三行日志就一直没打印，也就是一直没启动成功，但是正常的服务的那个服务器是有后面三行日志的。

当时启动打印的

2019-11-05 16:07:09.024 [main] INFO  o.a.coyote.http11.Http11NioProtocol - Initializing ProtocolHandler ["http-nio-18096"]

2019-11-05 16:07:09.061 [main] INFO  o.a.coyote.http11.Http11NioProtocol - Starting ProtocolHandler ["http-nio-18096"]

2019-11-05 16:07:09.062 [main] INFO  o.a.tomcat.util.net.NioSelectorPool - Using a shared selector for servlet write/read

2019-11-05 16:07:09.122 [main] INFO  o.s.b.c.e.t.TomcatEmbeddedServletContainer - Tomcat started on port(s): 18096 (http)

后面打印的

2019-11-05 16:26:53.435 [http-nio-18096-exec-5] INFO  o.a.c.c.C.[Tomcat].[localhost].[/] - Initializing Spring FrameworkServlet 'dispatcherServlet'

2019-11-05 16:26:53.435 [http-nio-18096-exec-5] INFO  o.s.web.servlet.DispatcherServlet - FrameworkServlet 'dispatcherServlet': initialization started

2019-11-05 16:26:53.473 [http-nio-18096-exec-5] INFO  o.s.web.servlet.DispatcherServlet - FrameworkServlet 'dispatcherServlet': initialization completed in 38 ms

第一次排查结论

基于上面的情况，我们认为问题就是服务没有初始化成功，应该是由于服务器内存不足导致的。也可能是和 Tomcat 启动慢的原因是一致的。

2.2 第二次排查

再次排障后发现这个问题取决于 Nginx 与应用两者。

场景

我们有另一个服务也部署在两个服务器上，一个服务器上启动后正常提供服务，另外一台服务一直没有接收到请求，也没有处理任何东西，日志如下：

当我们启动 spring boot 框架的服务后。日志出现了

2019-11-05 16:07:09.024 [main] INFO  o.a.coyote.http11.Http11NioProtocol - Initializing ProtocolHandler ["http-nio-18096"]

2019-11-05 16:07:09.061 [main] INFO  o.a.coyote.http11.Http11NioProtocol - Starting ProtocolHandler ["http-nio-18096"]

2019-11-05 16:07:09.062 [main] INFO  o.a.tomcat.util.net.NioSelectorPool - Using a shared selector for servlet write/read

2019-11-05 16:07:09.122 [main] INFO  o.s.b.c.e.t.TomcatEmbeddedServletContainer - Tomcat started on port(s): 18096 (http)

一直停留在这个界面。

然后我们通过模拟请求，也就是在服务器上通过 curl ip+port，立马就打印出来日志。

2019-11-05 16:26:53.435 [http-nio-18096-exec-5] INFO  o.a.c.c.C.[Tomcat].[localhost].[/] - Initializing Spring FrameworkServlet 'dispatcherServlet'

2019-11-05 16:26:53.435 [http-nio-18096-exec-5] INFO  o.s.web.servlet.DispatcherServlet - FrameworkServlet 'dispatcherServlet': initialization started

2019-11-05 16:26:53.473 [http-nio-18096-exec-5] INFO  o.s.web.servlet.DispatcherServlet - FrameworkServlet 'dispatcherServlet': initialization completed in 38 ms

第二次排查结论

第一就是出现在 Nginx 上，我们 Nginx 上使用了 fair 模块(github链接)。 fair 模块采用的不是负载均衡默认的轮询的均衡算法，而是可以根据页面大小、加载时间长短智能的进行负载均衡。

推测是fair 将其中一台服务器直接屏蔽掉了(也就是我们没有收到请求的机器)，然后就把所有的请求发送到另外一台机器了。

怪异之处

屏蔽掉的服务器内存和CPU 都是正常状态(内存还有剩余)，为什么会屏蔽掉它，fair模块算法是有什么问题？

-- 去监控下请求返回的时常，对比下另外一台。（对比后无异常，返回都在 1s 内）

为什么启动后接受了请求才会打印类似初始化的日志。

2019-11-05 16:26:53.435 [http-nio-18096-exec-5] INFO  o.a.c.c.C.[Tomcat].[localhost].[/] - Initializing Spring FrameworkServlet 'dispatcherServlet'

2019-11-05 16:26:53.435 [http-nio-18096-exec-5] INFO  o.s.web.servlet.DispatcherServlet - FrameworkServlet 'dispatcherServlet': initialization started

2019-11-05 16:26:53.473 [http-nio-18096-exec-5] INFO  o.s.web.servlet.DispatcherServlet - FrameworkServlet 'dispatcherServlet': initialization completed in 38 ms

询问开发后：得到答复:

2019-11-05 16:07:09.024 [main] INFO  o.a.coyote.http11.Http11NioProtocol - Initializing ProtocolHandler ["http-nio-18096"]

2019-11-05 16:07:09.061 [main] INFO  o.a.coyote.http11.Http11NioProtocol - Starting ProtocolHandler ["http-nio-18096"]

2019-11-05 16:07:09.062 [main] INFO  o.a.tomcat.util.net.NioSelectorPool - Using a shared selector for servlet write/read

2019-11-05 16:07:09.122 [main] INFO  o.s.b.c.e.t.TomcatEmbeddedServletContainer - Tomcat started on port(s): 18096 (http)

上面的日志，就是表明已经启动了，web 容器 Tomcat 已经 ok了。可以正常提供服务。

那么下面那个日志是怎么回事？

2019-11-05 16:26:53.435 [http-nio-18096-exec-5] INFO  o.a.c.c.C.[Tomcat].[localhost].[/] - Initializing Spring FrameworkServlet 'dispatcherServlet'

2019-11-05 16:26:53.435 [http-nio-18096-exec-5] INFO  o.s.web.servlet.DispatcherServlet - FrameworkServlet 'dispatcherServlet': initialization started

2019-11-05 16:26:53.473 [http-nio-18096-exec-5] INFO  o.s.web.servlet.DispatcherServlet - FrameworkServlet 'dispatcherServlet': initialization completed in 38 ms

原因是（开发告知）：这个是DispatcherServlet初始化，当第一个请求过来后，它才初始化。

三、总结

上述的故障最后的问题定位于： Nginx 的 fair插件导致的问题，与服务本身没有任何关系，但是 fair插件的具体的问题没有去细究。

巴特西