服务器认为响应时，是什么导致HTTP GET到localhost超时？

问题描述

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

应用程序有时会在localhost上调用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)"

解决方法

最后，我能够使用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引擎保持连接打开，直到此过滤器返回。调查正在进行中，现在就找到修复程序。