令人困惑的 503s 和 Istio到底是哪里引起的?

关注上方 云原生CTO 更多云原生干货等你来探索

• 专注于 云原生技术分享
• 提供优质 云原生开发 视频技术培训
• 面试技巧，及技术疑难问题 解答

云原生技术分享不仅仅局限于containerd、CoreDNS、Envoy、etcd、Fluentd、Harbor、Helm、Jaeger、Kubernetes、Open Policy Agent、Prometheus、Rook、TiKV、TUF、Vitess、Argo、Buildpacks、CloudEvents、CNI、Contour、Cortex、CRI-O、Falco、Flux、gRPC、KubeEdge、Linkerd、NATS、Notary、OpenTracing、Operator Framework、SPIFFE、SPIRE 和 Thanos等

令人困惑的 503s 和 Istio到底是哪里引起的？

Istio 是一个众所周知的开源服务网格。我们，在DKube，已经使用它一段时间了。最近，我们的用户报告说在 Istio 周围看到上游连接错误和 503。我会带你解决这个有趣的问题。

1. 问题

一段时间以来，我们的用户报告说在我们的 UI 中偶尔会看到如下错误。

上游连接错误或在Header之前断开/重置。重置原因：连接终止

如果我们刷新浏览器页面，这个问题就会消失。但是，要重现此错误非常困难。

我们知道这是 来自 Istio，因为我们的 UI 不处理这样的页面。有趣的是，我们主要在从我们的 Open ID Connect (OIDC) 提供程序回调到运行 Nodejs 服务器的 UI 服务器期间会看到这一点。

1.2 Istio Mixer

我开始筛选 Istio 日志。有一个包含 2 个容器的 Istio策略pod—proxy和Istio Mixer。proxy容器定期抛出日志，如

2020–09–04 14:36:59.085][29][warning][filter] [src/istio/mixerclient/report_batch.cc:106] Mixer Report failed with: UNAVAILABLE:upstream connect error or disconnect/reset before headers. reset reason: connection failure

此日志表明Mixer无法正确处理请求。但是，Mixer的日志另有建议。Istio 有一个名为 policyCheckFailOpen 的配置参数，这意味着

在无法到达Mixer策略服务的情况下允许所有流量。默认值为false，这意味着当客户端无法连接到Mixer时，流量被拒绝。

由于proxy容器抛出了与我追逐的相同的错误，我认为将此参数设置为 true 可能会解决此问题，但我错了！

1.3 Istio ingress控制器

我再次开始追捕罪魁祸首。我为 Istio 启用了详细日志记录。这将输出一连串的日志，所以要预先警告。

您可以按如下方式启用详细日志记录。

kubectl port-forward -n<namespace> <istio proxy pod> 15000 &

curl -X POST localhost:15000/logging?level=debug

我开始在使用 docker.io/istio/proxyv2:1.1.6容器镜像的ingress gateway pod 中看到以下调试日志。

[2020–09–04 14:25:43.870][42][debug][pool] [external/envoy/source/common/http/conn_pool_base.cc:20] queueing request due to no available connections
 [2020–09–04 14:25:43.966][42][debug][pool] [external/envoy/source/common/http/http1/conn_pool.cc:332] [C27322] connect timeout 
 [2020–09–04 14:25:43.966][42][debug][connection] [external/envoy/source/common/network/connection_impl.cc:101] [C27322] closing data_to_write=0 type=1 
 [2020–09–04 14:25:43.966][42][debug][connection] [external/envoy/source/common/network/connection_impl.cc:183] [C27322] closing socket: 1 
 [2020–09–04 14:25:43.966][42][debug][client] [external/envoy/source/common/http/codec_client.cc:82] [C27322] disconnect. resetting 0 pending requests 
 [2020–09–04 14:25:43.966][42][debug][pool] [external/envoy/source/common/http/http1/conn_pool.cc:129] [C27322] client disconnected, failure reason: 
 [2020–09–04 14:25:43.966][42][debug][pool] [external/envoy/source/common/http/http1/conn_pool.cc:164] [C27322] purge pending, failure reason: 
 [2020–09–04 14:25:43.966][42][debug][router] [external/envoy/source/common/router/router.cc:644] [C0][S16904449693883860917] upstream reset: reset reason connection failure 
 [2020–09–04 14:25:43.966][42][debug][http] [external/envoy/source/common/http/async_client_impl.cc:94] async http request response headers (end_stream=false): ‘:status’, ‘503’ ‘content-length’, ‘91’ ‘content-type’, ‘text/plain’

还有另一个日志。

[2020–09–14T07:00:25.505Z] “GET /callback?code=xxx&state=xxx HTTP/2” **503 UC** “-” 0 95 1 — “10.233.64.1” “Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/85.0.4183.83 Safari/537.36” “2926fb89–58d9–99ef-a5f6–65cd348d3c53” “192.168.200.23:32222” “10.233.64.210:3000” outbound|3000||dkube-ui.dkube.svc.cluster.local — 10.233.64.200:443 10.233.64.1:39082 -

UC 代表上游连接。这是否暗示与 UI 服务器的某种连接超时？服务，UI 服务器，看起来不错。那为什么是503s呢？我错过了什么？

1.4. 数据传输协议

我决定对 UI 服务器的容器接口进行 tcpdump。为了进行 tcpdump，您需要知道容器的接口名称。在此之前，您需要知道接口的链接 ID。为此，请执行到容器并输入以下内容

kubectl exec -it <pod name> -n<namespace> — cat /sys/class/net/eth0/iflink

通常，eth0是事实上的容器接口名称。相应地更改它。无论如何，上面的命令将输出类似 70 的内容。要获取 veth 接口名称，请运行以下命令

ip a | grep ^70

或

ip link | grep ^70

这会给你，

70: **veth930b1c36**@if3: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1410 qdisc noqueue master cni0 state UP mode DEFAULT group default

突出显示的部分是您的界面。现在开始使用 tcpdump：

sudo tcpdump -eni veth930b1c36 -w dump.pcap

1.5 Ksniff (K8s tcpdump)

如果您不想经历上述麻烦，可以使用ksniff。它是一个 kubectl插件，它利用 tcpdump 在 Kubernetes 集群中的任何 pod上启动远程捕获。我通过Krew安装了这个。现在开始使用 tcpdump：

kubectl sniff <pod name> -p -n<namespace> -f 'tcp[tcpflags] & (tcp-syn|tcp-fin|tcp-rst|tcp-push) != 0' -o dump.pcap

https://github.com/eldadru/ksniff, '-f' 是可选的，使用它是因为我只对 TCP数据包的一个子集感兴趣。检查捕获的数据包

dump.pcap 将包含您捕获的数据包，可以将其导入 Wireshark以获得更好的可读性和理解性。现在是有趣的部分。

07:00:25.507495 ethertype IPv4 (0x0800), length 1477: 10.233.64.200.55116 > 10.233.64.210.3000: Flags [P.], seq 1118:2529, ack 2921202, win 6771, options [nop,nop,TS val 2437011412 ecr 1473459814], length 1411
 
07:00:25.507530 ethertype IPv4 (0x0800), length 54: 10.233.64.210.3000 > 10.233.64.200.55116: Flags [R], seq 1780822149, win 0, length 0

10.233.64.200 属于 Istio ingress，10.233.64.210 属于 UI 服务器。从转储中可以看出，入口正在通过已建立的 TCP 连接推送数据。但是，UI 服务器以重置标志进行响应。重置可能是由 UI 服务器发送的，因为数据包到达之前建立的 TCP 连接，但本地服务器已经关闭了它的套接字。

正是因为这个重置标志，Istio 正确地说，“上游重置：重置原因连接终止”。

1.6 UI服务器为什么要发送RESET包？

• Ingress 控制器在 T 秒向 UI 服务器发送第一个 SYN 数据包。

• UI 服务器在 T+5 发送 FIN 数据包，因为过去 5 秒内没有人使用它。这是套接字被破坏的时间，可以通过 此处指定的 5 秒保持连接超时来解释。

• 一段时间后，OIDC 提供商在 T+19.8 发出回调。此请求到达 istio 代理，然后被发送到 UI服务器。

• 由于套接字已经关闭，因此 UI 服务器在 T+19.8 发送了一个重置数据包。

因此，一旦套接字被破坏，就必须建立新的连接。这就是为什么浏览器页面刷新使我们能够通过。

本质上，UI 服务器因为 http keepalive 超时而关闭了套接字。对于 Nodejs 服务器，http keepalive 超时是指服务器在完成写入最后一个响应后，在套接字将被销毁之前等待额外传入数据所需的非活动毫秒数。如果服务器在保持活动超时触发之前收到新数据，它将重置此不活动超时。

2 解决方案

理想情况下，Istio 不应写入已关闭的套接字。这可能是 Istio内部竞争条件的结果。我们或许也应该转向更高版本的 Istio。

2.1 解决方案1

一种解决方案可能是增加 UI 服务器的 HTTP keepalive 超时，以便它不会很快发送 RESET 数据包。例如：1 分钟

2.2 解决方案2

另一种解决方案是在 503状态代码上启用 HTTP重试。请注意，您无法根据 Istio 的 HTTP 请求类型（POST、GET、PUT等）进行配置。这可能对非幂等请求处理程序不利。

这两种解决方案可以结合使用，以提供更强大的 503防护。

由于各种原因，我们继续采用第二种解决方案。这是通过在虚拟服务上设置重试来完成的，这是 Istio的流量路由策略。

 retries:
 attempts: 3
 perTryTimeout: 5s
 retryOn: gateway-error,connect-failure,refused-stream

Istio proxy缓存每个请求。在下图中，我们可以看到 HTTP重试（第 4 行）正在运行。获得 TCP 重置（第三行）后，初始 GET调用（第二行）失败。Istio gateway重试失败的请求（参见第二个 GET调用，第 6 行）并成功。

我看到许多报告的问题与 Istio 的上游连接错误和 503 相关。因此，我希望有人会发现这有帮助。

5.3 文档

参考资料 ^[1]

参考资料