У меня есть приложение Java, работающее в AWS Beanstalk (Tomcat 8.5 + Apache httpd).
В какой-то момент приложение вызывает конечную точку 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",
}
Это мой собственный регистратор сервлетов, показывающий ответ 5 миллисекунд. Это регистрируется из внешнего фильтра сервлетов.
Эта проблема повторяется, но достаточно редко, поэтому я не могу ее воспроизвести. Так что мне нужно применить интеллектуальный подход... разработать серию гипотез и проверить каждую из них, пока не будет найдена правильная.
Каковы возможные причины?
Что я уже пробовал
Я написал собственные регистраторы, чтобы зафиксировать показанные выше тайминги. Затем я в основном натыкаюсь на кирпичную стену, поскольку тайм-аут происходит в каком-то скрытом измерении между ответом, отправляемым сервером (конечная точка локального хоста), и ответом, прочитанным клиентом.
Я вижу, что журнал 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)"