当服务器认为HTTP GET to localhost响应时，什么会导致HTTP GET to localhost超时？

Question

我有一个在AWS Beanstek（Tomcat 8.5 Apache httpd）中运行的Java应用程序。

在某一点上，应用程序调用本地主机上的RESTendpoint。

偶尔我在日志中看到这样的失败：

14:55:45 ... SEVERE: url[http://localhost/detail.api?id=200030599] timing=12.010 ...

这表明我的CustomRestTemplate在12秒后放弃了等待响应。

但是，查看日志中的几行，我看到了来自服务endpoint的日志条目：

{
    "server_ts": "2020-08-19T14:55:33.890Z",
    "remote_ip": "127.0.0.1",
    "local_ip": "127.0.0.1",
    "method": "GET",
    "url": "/detail.api",
    "query_string": "?id=200030599",
    "protocol": "HTTP/1.1",
    "http_status": 200,
    "referer": null,
    "user_agent": "Apache-HttpClient/4.5.2 (Java/1.8.0_252)",
    "time_elapsed": 5,
    "thread_name": "http-nio-8080-exec-20",
    "host": "localhost",
}

这是我的自定义servlet记录器，显示5毫秒的响应。这是从外部包装Servlet Filter记录的。

这个问题反复出现，但足够罕见，我无法重现。所以我需要采取一种智力方法......开发一系列假设和测试来反驳每一个假设，直到找到正确的假设。

可能的原因是什么？

到目前为止我试过什么

我编写了自定义记录器，这样我就可以捕获上面显示的时间。然后我基本上碰壁了，因为超时发生在“服务器”（localhostendpoint）发送的响应和客户端读取的响应之间的某个隐藏维度上。

我看到Apache日志（来自elasticbeanstack）也显示了本地请求：

127.0.0.1 (-) - - [19/Aug/2020:14:55:33 +0000] "GET /detail.api?id=200030599 HTTP/1.1" 200 4982 "-" "Apache-HttpClient/4.5.2 (Java/1.8.0_252)"

Answer 1

最后，我能够使用JMeter在本地测试中再现这个问题。

事实证明，“隐藏维度”隐藏在Servlet过滤器中：

@Override
public void doFilter(ServletRequest request, ServletResponse response, FilterChain chain)
        throws IOException, ServletException {
    
    long started = System.currentTimeMillis(); 

    chain.doFilter(request, response);
    
    long elapsed = System.currentTimeMillis() - started;
    
    log(request, response, elapsed);

}

调用包含一个同步数据库插入，该插入会减慢速度，并在负载下最终失败。我假设servlet引擎保持连接打开，直到这个过滤器返回。调查现在继续寻找解决方案。