【问题标题】：Traefik breaking headers and Tomcat keeping stream alive until timeoutTraefik 打破标头和 Tomcat 保持流活动直到超时
【发布时间】：2021-04-16 07:27:29
【问题描述】：

TL;DR

我的 Spring Boot REST 端点会立即返回 HTTP 状态，但有时会等待 60 秒才能返回结果。这是由于 Feign 代理请求的标头被更改（Transfer-Encoding 被 Content-Length 替换）调查的背景和结果详述如下。

事实

A（Spring Boot + Feign + Tomcat）-> Traefik -> B（Rest 资源，Spring Boot + Tomcat）
Traefik & B 总是立即响应，A 总是立即返回 200 状态码。
根据未知标准，A 使用 KeepAlive 流，并且仅在精确 60 秒（最大空闲线程？）后返回。
B 使用 Transfer-Encoding: chunked 标头，但 Traefik 根据未知标准将其替换为 Content-Length。
暂停来自未关闭的 KeepAliveStream。我找到了几个解决方法/解决方案，但我也很想有一个解释。
- 删除Content-Length 标头可解决此问题。调试 sun.www.net.HttpClient 确认具有 Content-Length 标头会触发 KeepAlive 流的使用。
- 使用 Connection: close 标头调用 A 似乎可以解决问题（同样的原因：这会阻止使用 KeepAliveStream）。
- 用 A 中的 Jetty 替换 Tomcat 似乎可以解决问题，因为它似乎依赖于其他 HTTP 库。
- 用 OkHttp 替换 A 的 Feign 的 Apache HttpClient 即可解决问题。

剩下的问题

为什么 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 标头的计算方式与我们的客户端在收到正文时的计算方式之间存在差异。

详细的上下文

情况

我在使用充当另一个服务 (B) 代理的 Spring Boot REST 控制器 (A) 时遇到问题。端点基本上是这样的：

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

A 和 B 之间有一个 Traefik 反向代理。总而言之：A -> Traefik -> B。

在所有情况下，Feign 代理都会在 100 毫秒内做出响应，并且端点会立即返回 HTTP 状态 (200)。但是，在大多数情况下，正文不会立即返回。 A 的 Spring Boot 等待精确 60 秒（这真的不是随机的）。

body 是立即返回还是在 60 秒后返回似乎取决于resource：一些资源总是立即可用，而另一些则等待。再一次，这不是看起来是随机的。

[编辑]：调查表明，在 A 暂停的情况下，Traefik 将 B 的原始 Transfer-Encoding 标头替换为 Content-Length。基于此标头，sun.net.www.HttpClient 将决定使用 KeepAliveStream。问题是这个流不会关闭。

版本

Spring Boot：2.2.6
雄猫：9.0.33
Feign：（由 Spring Cloud 2.1.2 确定）
Traefik：2.2.11

不是什么

代理服务 (B) 速度慢不是问题。在所有情况下，myFeignProxy 都会在几毫秒内响应，并且端点会立即返回 200 HTTP 状态。

我已尝试更改 Feign 客户端超时，但没有任何影响。

我也发现暂停、body 的大小和 feign 代理的响应时间之间没有相关性。

Resource	Size (KB)	Feign time (ms)	60s pause
1	1.87	34	yes
2	3.29	35	no
3	1.55	34	yes
4	10.05	81	yes

该问题也与 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 时，我发现代理服务 (B) 开始在其 DTO 中使用 ZonedDateTime 而不是 LocalDateTime 时出现 60 秒暂停问题。唯一的变化是日期时间字段现在在响应正文中有一个偏移量，对标头没有影响。然而，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 仍然立即返回。~~

模拟-B

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}`);

【问题讨论】：

既然你在本地机器上运行时没有遇到这个问题，也许仔细看看正在使用的底层feignClient？也许为实际客户端启用更多日志记录？（Apache HTTP 客户端，OkHttp，....）。可能与网络有关...
你认为这可能与网络有关吗，@wjans？这是一个自然的假设，但我无法解释如何。我尝试在对 Feign 的调用和返回之间添加一个日志。日志总是在所有请求的数据都存在的情况下立即调用，并且在记录消息一分钟后发送正文。我认为这消除了 Feign，因为它已经完成了回答，不是吗？现在我正在研究暂停期间进行的线程转储。如果它没有产生任何结果，我会进一步研究你的建议。谢谢！
哦，所以你的意思是调用myFeignProxy.getAll(resource) 立即返回？那么我确实会尝试进行线程转储或调试？我在考虑网络，因为这是您在有问题和没有问题的情况下消除的唯一部分。还是在序列化响应时通过网络检索到某些内容？
是的，myFeignProxy.getAll() 立即返回，所有数据都在那里，反序列化（通过调试和日志记录测试）。我没有在线程转储中看到任何阻塞。我继续调试，在放弃之前遍历了链中的几个过滤器，并且在过程的后期仍然添加了 60 秒的暂停。我正在尝试完全删除 Spring Security 以查看它是否会改变任何内容。
完全不确定，但只是一个想法：当标头的内容长度超过发送的实际内容时会发生什么？我认为，在这种情况下，Traefik 会等待更多数据。

标签： java spring-boot tomcat traefik feign

【解决方案1】：

解释原因

我们终于明白了导致问题的机制。

A -> Traefik -> B

B 返回带有 ZonedDateTime 字段 ("validFrom":"2021-12-24 23:59:57+01:00") 和标头 Transfer-Encoding: chunked 的对象列表。
Traefik 将 Transfer-Encoding: chunked 替换为 Content-Length，根据请求正文计算得出。
A 接收响应，反序列化对象，然后在 UTC 时区 ("validFrom":"2021-12-24 22:59:57Z") 中重新序列化它们但，但它会重用来自 Traefik 的 Content-Length 而无需重新计算它。

因此，正文 from 比宣布的 Content-Length 短（A 发送每个 ZonedDateTime 比 Traefik 计算内容长度时少 5 个字节）。

但是，客户端已被宣布为Content-Length，正在等待丢失的字节。

可能的解决方案

我们现在想到的解决方案是告诉 Feign 及其调用控制器，它返回一个 ResponseEntity<String> 而不是 ResponseEntity<List<MyObject>>。

优点：

B 的响应按原样返回，因此不会因为内容长度不同而出现问题。
A 不会花费 CPU 时间反序列化然后立即重新序列化响应。

缺点：

A 的 OpenApi 文档不会显示返回类型（除非 Open API 注释允许指定返回模型）。这就是我今天晚些时候要测试的内容。

【讨论】：