TL;DR

Моя конечная точка Spring Boot REST немедленно возвращает статус HTTP, но иногда ждет 60 секунд, прежде чем вернуть результат. Это вызвано изменением заголовков запроса Feign-proxy (Transfer-Encoding заменено на Content-Length). Контекст и результаты расследования подробно описаны ниже.

Факты

• A (Spring Boot + Feign + Tomcat) -> Traefik -> B (остальные ресурсы, Spring Boot + Tomcat)
• Traefik и B всегда отвечают немедленно, A всегда немедленно возвращает код состояния 200.
• На основании неизвестных критериев A использует поток проверки активности и возвращается только через ровно 60 секунд (максимальное число бездействующих потоков?).
• B использует заголовок Transfer-Encoding: chunked, но Traefik заменяет его на Content-Length в зависимости от неизвестных критериев.
• The pause comes from a KeepAliveStream not being closed. I found several workarounds/solutions, but I'd love to have an explanation also.
  • Removing the Content-Length header solves the issue. Debugging sun.www.net.HttpClient confirms that having a Content-Length header triggers the use of a KeepAlive stream.
  • Вызов A с заголовком Connection: close, по-видимому, решает проблему (по той же причине: это предотвращает использование KeepAliveStream).
  • Замена Tomcat на Jetty в A, по-видимому, решает проблему, поскольку, похоже, он полагается на другие HTTP-библиотеки.
  • Замена Apache HttpClient Feign от A на OkHttp решает проблему.

Оставшиеся вопросы

• Почему Feign/Tomcat/HttpClient не закрывается, как только все тело доступно (что сразу)?
• Бонусный вопрос: почему/когда/на основании чего Traefik изменяет заголовки и каковы правила?

Тайна потерянных байтов

Одним из наших последних тестов было использование -v с curl, и мы увидели это, когда A делал паузу:

$ curl -i -v http://localhost:8100/a/proxied-endpoint
#...
< Content-Length: 1843
<
{ [1793 bytes data]

Итак, служба зависает и ждет 50 недостающих байт. Однако при прерывании он возвращает весь ответ. Я думаю о проблеме с кодировкой, но не понимаю, где это могло произойти.

Замена длины содержимого на 1793 (или меньше) приводит к немедленному возврату конечной точки.

Существует несоответствие между тем, как вычисляется заголовок Content-Length, и тем, как наш клиент вычисляет его при получении тела.

Подробный контекст

Ситуация

У меня возникла проблема с контроллером REST Spring Boot (A), который действует как прокси для другой службы (B). Конечная точка в основном выглядит так:

@GetMapping("/{resource}")
public ResponseEntity<List<Something>> getAll(@PathVariable resource) {
    return myFeignProxy.getAll(resource);
}

Между A и B есть обратный прокси-сервер Traefik. В итоге: A -> Traefik -> B.

Во всех случаях прокси Feign отвечает менее чем за 100 мс, а конечная точка немедленно возвращает статус HTTP (200). Однако в большинстве случаев тело не возвращается сразу. Spring Boot A ожидает ровно 60 секунд (на самом деле это не случайно).

Будет ли тело возвращено немедленно или через 60 с, по-видимому, зависит от resource: некоторые ресурсы всегда доступны сразу, другие ждут своего часа. Опять же, это не кажется случайным.

[Изменить]: расследование показало, что в тех случаях, когда A делает паузу, Traefik заменяет исходный заголовок Transfer-Encoding B на Content-Length. Основываясь на этом заголовке, sun.net.www.HttpClient решит использовать KeepAliveStream. Проблема в том, что этот поток не закрывается.

Версии

Spring Boot: 2.2.6
Tomcat: 9.0.33
Feign: (определено Spring Cloud 2.1.2)
Traefik: 2.2.11

Что это не

Медленная служба прокси (B) не является проблемой. Во всех случаях myFeignProxy отвечает через несколько мс, и конечная точка немедленно возвращает HTTP-статус 200.

Я попытался изменить время ожидания клиента Feign без каких-либо последствий.

Также не вижу корреляции между паузой, размером тела и временем отклика фиктивного прокси.

Проблема также не связана с Spring Security, поскольку ее полное удаление (конфигурация и зависимости) не меняет симптомов.

Обновленные расследования

Технический слой, вызывающий паузу

Пауза, кажется, исходит от Tomcat. Замена стартера Tomcat на стартер Jetty (в A) устраняет проблему (все запросы отвечают немедленно). Это, как говорится, не объясняет проблему.

Анализ журнала трассировки

Оказывается, для конечной точки, где появляется пауза, во время звонков есть одна дополнительная строка в журналах. Примеры см. ниже. Параметры для HttpURLConnection также кажутся другими, хотя я не понимаю, почему.

Делать без паузы

DEBUG [nio-8100-exec-9] s.n.www.protocol.http.HttpURLConnection  : sun.net.www.MessageHeader@784b4a945 pairs: {GET /xxx HTTP/1.1: null}{Accept: application/json}{User-Agent: Java/11.0.7}{Host: xxx}{Connection: keep-alive}
DEBUG [nio-8100-exec-9] s.n.www.protocol.http.HttpURLConnection  : sun.net.www.MessageHeader@2a3818a612 pairs: {null: HTTP/1.1 200 OK}{Cache-Control: no-cache, no-store, max-age=0, must-revalidate}{Content-Type: application/json}{Date: Tue, 20 Apr 2021 07:47:47 GMT}{Expires: 0}{Pragma: no-cache}{Strict-Transport-Security: max-age=31536000 ; includeSubDomains}{Vary: accept-encoding}{X-Content-Type-Options: nosniff}{X-Frame-Options: DENY}{X-Xss-Protection: 1; mode=block}{Transfer-Encoding: chunked}

Регистр с паузой

DEBUG [nio-8100-exec-6] s.n.www.protocol.http.HttpURLConnection  : sun.net.www.MessageHeader@7bff99e75 pairs: {GET /xxx HTTP/1.1: null}{Accept: application/json}{User-Agent: Java/11.0.7}{Host: xxx}{Connection: keep-alive}
TRACE [nio-8100-exec-6] s.n.www.protocol.http.HttpURLConnection  : KeepAlive stream used: https://xxx/xxx
DEBUG [nio-8100-exec-6] s.n.www.protocol.http.HttpURLConnection  : sun.net.www.MessageHeader@5aed6c9312 pairs: {null: HTTP/1.1 200 OK}{Cache-Control: no-cache, no-store, max-age=0, must-revalidate}{Content-Type: application/json}{Date: Tue, 20 Apr 2021 07:57:42 GMT}{Expires: 0}{Pragma: no-cache}{Strict-Transport-Security: max-age=31536000 ; includeSubDomains}{Vary: accept-encoding}{X-Content-Type-Options: nosniff}{X-Frame-Options: DENY}{X-Xss-Protection: 1; mode=block}{Content-Length: 803}

При окончательном ответе после паузы (отсутствует при немедленном ответе)

DEBUG [nio-8100-exec-7] o.apache.tomcat.util.threads.LimitLatch  : Counting down[http-nio-8100-exec-7] latch=1
DEBUG [nio-8100-exec-7] org.apache.tomcat.util.net.NioEndpoint   : Calling [org.apache.tomcat.util.net.NioEndpoint@63668501].closeSocket([org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper@cfdc708:org.apache.tomcat.util.net.NioChannel@6e7c15b6:java.nio.channels.SocketChannel[connected local=/0:0:0:0:0:0:0:1:8100 remote=/0:0:0:0:0:0:0:1:52501]])

Дополнительный журнал (используемый поток KeepAlive) находится в sun.net.www.http.HttpClient. Кажется, я понимаю, что решение об использовании этого KeepAlive зависит от заголовков проксируемого ответа.

Анализ заголовков и вмешательство Traefik

Traefik меняет заголовки между A и B.

B всегда возвращает свой ответ с Transfer-Encoding: chunked. Traefik иногда заменяет его на Content-Length и правильный размер полезной нагрузки.

В нашем экземпляре Traefik ничего не настроено в отношении заголовков. Правила, используемые для выбора между Transfer-Encoding и Content-Length, кажутся сложными для понимания:

• Кажется, это зависит от вызываемой конечной точки или ее полезной нагрузки.
• Это также, кажется, зависит от чего-то от вызывающей стороны, так как я не всегда получаю один и тот же заголовок в зависимости от того, звоню ли я из A или из curl.

Это объясняет, почему проблема не воспроизводится, когда оба приложения находятся на локальном компьютере, поскольку между ними нет Traefik.

Что касается правил, которые применяет Traefik, похоже, что версия HTTP играет роль.

$ curl -s -o /dev/null -D - --http1.1 https://traefik/b/endpoint
HTTP/1.1 200 OK
# ...
Transfer-Encoding: chunked

$ curl -s -o /dev/null -D - --http2 https://traefik/b/endpoint
HTTP/2 200
# ...
content-length: 2875

Traefik всегда возвращает одни и те же заголовки для данной конечной точки, поэтому мы можем думать, что заголовки также зависят от адреса или, что более вероятно, от полезной нагрузки (данная конечная точка всегда возвращает одну и ту же полезную нагрузку для этой службы).

Первая версия B, которая не работает

Выполняя git bisect, я обнаружил, что проблема с 60-секундной паузой возникает, когда проксируемая служба (B) начинает использовать ZonedDateTime вместо LocalDateTime в своем DTO. Единственное изменение заключается в том, что поля даты и времени теперь имеют смещение в теле ответа, это не влияет на заголовки. Тем не менее, клиент Feign отлично работает для LocalDateTimes и приостанавливается для ZonedDateTimes.

Принудительное закрытие соединения

Передача заголовка Connection: close приводит к исчезновению паузы в A. Тело ответа возвращается немедленно.

В этом случае HttpClient не использует KeepAliveStream.

Попытка воспроизвести с помощью макета B

Я написал быстрый фиктивный сервис B. Он возвращает заголовок Content-Type и содержимое. Что интересно, так это:

• Если mock-B возвращает заголовок Content-Length, то A имеет 60-секундную паузу.
• Если mock-B не возвращает заголовок Content-Length, то немедленно возвращается A.

Это согласуется с предыдущими тестами, указывающими на то, что заголовок Content-Length играет роль, но я до сих пор не могу понять, какую именно, поскольку он присутствует в некоторых вхождениях Traefik, которые A по-прежнему возвращаются немедленно.

const port = 8080;

const http = require('http');
const path = require('path');
const fs = require('fs');

const countBytesInString = str => encodeURI(str).split(/%..|./).length - 1

const requestListener = (req, res) => {
    console.log(`\n>> Mock call to endpoint ${req.url}`);

    fs.readFile(path.join(__dirname, `endpoints${req.url}.json`), 'utf8' , (err, data) => {
        if (err) {
            console.error(err)
            return;
        }

        const contentLength = countBytesInString(data);
        console.log(`Content-Length: ${contentLength}`);

        res.setHeader('Content-Type', 'application/json');
        res.setHeader('content-length', contentLength);
        res.writeHead(200);
        res.end(data);
    })
};

const server = http.createServer(requestListener);
server.listen(port);
console.log(`Mock server listening on port ${port}`);