kubernetes 在响应写入阶段,列表请求超时未被尊重,

9lowa7mx  于 5个月前  发布在  Kubernetes
关注(0)|答案(9)|浏览(65)

发生了什么?

可能发出的列表请求超过了由request-timeout apiserver标志设置的持续时间。当apiserver序列化响应并将其写回客户端时,request-timeout标志似乎没有被强制执行(而在其他请求阶段,如从存储中列出时则会强制执行)。具体来说,CPU或网络资源不足的慢速客户端可能会因接收响应缓慢而引入任意高的列表延迟。这些请求将在整个执行期间占用APF座位(1+分钟),这可能会使使用相同FlowSchema的其他客户端饥饿。

你期望发生什么?

我们期望列表请求受到request-timeout标志指定的持续时间的约束。

我们如何尽可能最小精确地重现它?

  1. 创建50k个密钥。
  2. 在此命名空间中列出所有密钥,并通过利用limit-rate标志强制HTTP客户端接收响应的速度变慢。
curl --cert ./client.pem --key ./client-key.pem --cacert ./ca.pem $server/api/v1/namespaces/default/secrets --limit-rate 200k | wc -c
  1. APIServer日志显示请求花费了5+分钟完成:
I0714 19:37:10.706663 11 trace.go:205] Trace[449374747]: "List" url:/api/v1/namespaces/default/secrets,user-agent:curl/8.0.1,audit-id:a09c55c2-0f84-4d6e-8fe6-fcde2e226b31,client:205.251.233.233,accept:*/*,protocol:HTTP/2.0 (14-Jul-2023 19:31:34.658) (total time: 336048ms):
Trace[449374747]: ---"Listing from storage done" 13749ms (19:31:48.408)
Trace[449374747]: ---"Writing http response done" count:40803 322298ms (19:37:10.706)
Trace[449374747]: [5m36.04813648s] [5m36.04813648s] END
  1. 审计日志条目给出了延迟细分:
"annotations": {
    "apiserver.latency.k8s.io/etcd": "13.522549999s",
    "apiserver.latency.k8s.io/response-write": "5m21.445820827s",
    "apiserver.latency.k8s.io/serialize-response-object": "5m22.298206407s",
    "apiserver.latency.k8s.io/total": "5m36.049590964s",
    "apiserver.latency.k8s.io/transform-response-object": "1.724µs",
    "authorization.k8s.io/decision": "allow",
    "authorization.k8s.io/reason": "RBAC: allowed by ClusterRoleBinding \"eks:k8s-metrics\" of ClusterRole \"eks:k8s-metrics\" to User \"eks:k8s-metrics\""
  }
  1. 检查正在使用的APF并发性显示全局默认桶为整个5分钟请求使用了10个座位:
kubectl get --raw /metrics --kubeconfig kubeconfig | grep apiserver_flowcontrol_request_concurrency_in_use
...
apiserver_flowcontrol_request_concurrency_in_use{flow_schema="global-default",priority_level="global-default"} 10

我们需要了解其他信息吗?

  • 无响应*

Kubernetes版本

$ kubectl version
Client Version: version.Info{Major:"1", Minor:"24+", GitVersion:"v1.24.13-eks-0a21954", GitCommit:"6305d65c340554ad8b4d7a5f21391c9fa34932cb", GitTreeState:"clean", BuildDate:"2023-04-15T00:37:31Z", GoVersion:"go1.19.8", Compiler:"gc", Platform:"linux/amd64"}
Kustomize Version: v4.5.4
Server Version: version.Info{Major:"1", Minor:"24+", GitVersion:"v1.24.13-eks-0a21954", GitCommit:"6305d65c340554ad8b4d7a5f21391c9fa34932cb", GitTreeState:"clean", BuildDate:"2023-04-15T00:33:45Z", GoVersion:"go1.19.8", Compiler:"gc", Platform:"linux/amd64"

云提供商

AWS

OS版本

# On Linux:
$ cat /etc/os-release
# paste output here
$ uname -a
# paste output here

# On Windows:
C:\> wmic os get Caption, Version, BuildNumber, OSArchitecture
# paste output here

安装工具

容器运行时(CRI)和版本(如果适用)

相关插件(CNI,CSI,...)和版本(如果适用)

uxhixvfz

uxhixvfz2#

/assign @apelisse
/triage accepted
pbgvytdp

pbgvytdp3#

/sig scalability
cc @wojtek-t@andrewsykim@MikeSpreitzer

hl0ma9xz

hl0ma9xz4#

主要问题是编写响应时并未真正遵循超时,例如:
https://github.com/kubernetes/kubernetes/blob/master/staging/src/k8s.io/apiserver/pkg/endpoints/handlers/responsewriters/writers.go#L134
在理想情况下,我们希望io.Writer接口能够接受上下文,但在此期间,我们可能需要以某种方式解决这个问题。
cc @mborsz

f5emj3cl

f5emj3cl5#

相关问题是,如果客户端从新建立的监视器接收初始事件的速度较慢。在这种情况下,给定优先级的所有座位都可能被足够多的请求占用,每个请求占用一个座位且无限期地保持。这个问题中提到的列表情况可以通过将上下文传递给写入者来解决,但由于监视器没有强制执行超时,因此这种情况不会得到解决。

之前有一个与无限期占用座位的监视器请求相关的讨论,针对未初始化的监视器缓存,其中@shyamjvs建议服务器应该对监视请求的初始阶段实施超时:#115656(评论)。@wojtek-t,你对这个关于监视器的案例有什么想法吗?还是应该将其作为单独的问题进行跟踪?

fcg9iug3

fcg9iug36#

这个问题的另一种形式,会影响到watch或list请求(除了低CPU/网络带宽之外),如果客户端进程在API服务器将HTTP响应写回客户端时暂停/死锁。即使客户端设置了客户端超时来解决服务器端超时未被尊重的问题,客户端也不会运行以终止其自身的请求。必须恢复客户端线程以接收剩余的响应/终止请求,或者需要终止底层TCP连接。

以下是这种问题形式的复现示例:当kubectl进程接收响应时暂停:

# Issue a list pods request with a client-side timeout of 5s and then pause the process:
% time kubectl get --raw "/api/v1/namespaces/default/pods" --request-timeout 5s | wc -c
^Z
zsh: suspended  kubectl get --raw "/api/v1/namespaces/default/pods" --request-timeout 5s | wc -c

# Wait 30 minutes and then resume the process so that the list pod request completes:
% fg
[19]  + continued  kubectl get --raw "/api/v1/namespaces/default/pods" --request-timeout 5s | wc -c
Unable to connect to the server: context deadline exceeded (Client.Timeout exceeded while awaiting headers)
0
kubectl get --raw "/api/v1/namespaces/default/pods" --request-timeout 5s  0.62s user 0.08s system 0% cpu 32:02.06 total
wc -c  0.00s user 0.00s system 0% cpu 32:02.06 total

检查审计日志延迟注解显示请求正在执行并保持APF座位30分钟:

"annotations": {
    "apiserver.latency.k8s.io/etcd": "619.47221ms",
    "apiserver.latency.k8s.io/response-write": "32m4.915489787s",
    "apiserver.latency.k8s.io/serialize-response-object": "32m6.987983593s",
    "apiserver.latency.k8s.io/total": "32m8.894443448s",
    "apiserver.latency.k8s.io/transform-response-object": "2.08µs",
    "authorization.k8s.io/decision": "allow"
  }
3duebb1j

3duebb1j7#

我们在上次SIG会议上讨论了这个问题 - 这是笔记的链接:
https://docs.google.com/document/d/1hEpf25qifVWztaeZPFmjNiJvPo-5JX1z0LSvvVY5G2g/edit#bookmark=id.oh2c71gk85ww
缓解措施的第一部分是 #114189 - 我们将继续思考如何进一步降低风险。
@tkashem - 仅供参考

9rbhqvlz

9rbhqvlz8#

我正在深入研究慢速客户端如何影响watch请求,根据这条评论:
kubernetes/staging/src/k8s.io/apiserver/pkg/storage/cacher/cache_watcher.go
第510行到第516行
| | // 此时我们已经开始处理传入的watch事件。 |
| | // 但是,init事件仍然可以被处理,因为它们的序列化和发送给客户端是异步进行的。 |
| | // TODO:如KEP所述,我们希望通过将初始化信号的延迟与要处理的事件数量成比例来估算,但我们将其留给调优阶段。 |
| | utilflowcontrol.WatchInitialized(ctx) |
在APF KEP中也提到,“在watchcache中,初始化阶段是明确分开的-我们明确计算init事件并处理它们。在这个层面上,我们无法控制的是序列化和发送事件的过程。在最初的版本中,我们将忽略这一点,只需在所有init事件都在结果通道中时立即发送初始化完成信号。在未来,我们可以通过假设某个常数(或与事件大小成比例的时间)来估计它,并通过所有init事件的总和来延迟发送信号。”
@wojtek-t@tkashem 我认为我们需要对watch InitEvents设置超时,但看起来慢速客户端接收InitEvents不能无限期地持有座位是有希望的。

bfhwhh0e

bfhwhh0e9#

为了让写入器尊重上下文,将响应分块并在每个块之间检查上下文是否被取消是否值得探讨?这并不完美,因为调用写入仍然可能无限期阻塞,但是,如果我们可以将块大小中的字节数写入客户端,它将允许为慢(但不挂起)的客户端强制执行超时。
我使用一个接收速度为2000字节/秒的慢速客户端进行了一些初步测试,将响应分块:

$ curl -v -k --header "Authorization: Bearer ${TOKEN}" -X GET "${APISERVER}/api/v1/configmaps" --limit-rate 2000

在没有这个补丁的情况下,列出configmaps请求耗时超过1小时:

I0802 00:01:54.412070      10 trace.go:236] Trace[893363742]: "List" accept:*/*,audit-id:6b4b910e-bd90-43c8-ad55-c3496b8a6d3a,client:205.251.233.233,api-group:,api-version:v1,name:,subresource:,namespace:,protocol:HTTP/2.0,resource:configmaps,scope:cluster,url:/api/v1/configmaps,user-agent:curl/8.3.0,verb:LIST (01-Aug-2024 22:47:29.168) (total time: 4465244ms):
Trace[893363742]: ["List(recursive=true) etcd3" audit-id:6b4b910e-bd90-43c8-ad55-c3496b8a6d3a,key:/configmaps,resourceVersion:,resourceVersionMatch:,limit:0,continue: 4465243ms (22:47:29.168)
Trace[893363742]:  ---"fetched all pages from etcd" page-count:23 937ms (22:47:30.106)]
Trace[893363742]: ---"Writing http response done" count:45193 4464305ms (00:01:54.412)
Trace[893363742]: [1h14m25.244005955s] [1h14m25.244005955s] END
E0802 00:01:54.412260      10 timeout.go:142] post-timeout activity - time-elapsed: 1.505983ms, GET "/api/v1/configmaps" result: <nil>

有了这个补丁,列出configmaps请求在1分钟6秒内完成:

I0801 22:24:56.534337       9 trace.go:236] Trace[123593309]: "List" accept:*/*,audit-id:34a174b3-51e3-4c80-8591-9182088ad8cd,client:205.251.233.233,api-group:,api-version:v1,name:,subresource:,namespace:,protocol:HTTP/2.0,resource:configmaps,scope:cluster,url:/api/v1/configmaps,user-agent:curl/8.3.0,verb:LIST (01-Aug-2024 22:23:49.735) (total time: 66798ms):
Trace[123593309]: ["List(recursive=true) etcd3" audit-id:34a174b3-51e3-4c80-8591-9182088ad8cd,key:/configmaps,resourceVersion:,resourceVersionMatch:,limit:0,continue: 66798ms (22:23:49.735)
Trace[123593309]:  ---"fetched all pages from etcd" page-count:23 845ms (22:23:50.581)]
Trace[123593309]: ---"Writing http response done" count:45193 65952ms (22:24:56.534)
Trace[123593309]: [1m6.798532261s] [1m6.798532261s] END
E0801 22:24:56.534521       9 timeout.go:142] post-timeout activity - time-elapsed: 1.4805ms, GET "/api/v1/configmaps" result: <nil>

我对这种模式下的客户端视角有一些担忧,特别是,我们需要确保HTTP请求因未发送完整响应主体而失败。我的理解是,客户端需要通过HTTP1.1的Transfer-Encoding或通过HTTP2的流错误来检测到这一点,而这已经在处理程序中引发了恐慌(golang/go#16542 (评论))。
我很想听听你们对这种方法的看法,以及我们是否可以在短期内利用它,直到 #114189 。@wojtek-t@tkashem@shyamjvs@mengqiy

相关问题