我有一个在AWS Beanstalk(Tomcat 8.5 + Apache httpd)中运行的Java应用程序。
在某一时刻,应用程序在本地主机上调用REST端点。
有时,我在日志中看到这样的故障:
14:55:45 ... SEVERE: url[http://localhost/detail.api?id=200030599] timing=12.010 ...
That indicates that my CustomRestTemplate gave up waiting for a response, after 12 seconds.
但是,在日志中查找了几行,我看到了来自服务端点的日志条目:
{
"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)"