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

Question

我在 AWS Beanstalk (Tomcat 8.5 + Apache httpd) 中有一个 Java 应用程序运行。

应用在某一时刻调用本地主机上的 REST 端点。

偶尔我会在日志中看到这样的故障：

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

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

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

{
    "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 过滤器记录的。

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

可能的原因有哪些？

到目前为止我尝试了什么

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

我看到 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);

}

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

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

What can cause HTTP GET to localhost to timeout when the server thinks it responded?

apache-httpclient-4.x