search

k3s-io / k3s

Lightweight Kubernetes
https://k3s.io
Apache License 2.0
27.73k stars 2.32k forks source link

Flooding Trace message after restart k3s-server #8396

Closed tibetsam closed 1 year ago

tibetsam commented 1 year ago

Environmental Info: K3s Version: k3s -v k3s version v1.25.5+k3s2 (de654222) go version go1.19.4

Node(s) CPU architecture, OS, and Version: uname -a Linux 8BMQ363 5.3.18-150300.59.118-default #1 SMP Tue Apr 4 15:18:05 UTC 2023 (d9b953c) x86_64 x86_64 x86_64 GNU/Linux

Cluster Configuration: single node

Describe the bug: After restart k3s-server service, I found plenty of Trace message in the logs, e.g. All these trace message will be printed if list/watch operation took longer than 10s(https://github.com/kubernetes/kubernetes/blob/ef1aed8cd80a6955dd6ef9e59e8e2f378336cf4f/staging/src/k8s.io/client-go/tools/cache/reflector.go#L475)

from the logs, we think all those trace messages is triggered by api or client current throttling.

Sep 20 12:19:03 8BMQ363 k3s[11943]: I0920 12:19:03.571557 11943 request.go:682] Waited for 11.39126873s due to client-side throttling, not priority and fairness, request: GET:https://10.10.202.1:6443/api/v1/namespaces/pc/secrets?fieldSelector=metadata.name%3Dpm-server-cert&limit=500&resourceVersion=0 Sep 20 12:19:03 8BMQ363 k3s[11943]: I0920 12:19:03.575973 11943 trace.go:205] Trace[975563300]: "Reflector ListAndWatch" name:object-"pc"/"pm-server-cert" (20-Sep-2023 12:18:52.180) (total time: 11395ms): Sep 20 12:19:03 8BMQ363 k3s[11943]: Trace[975563300]: ---"Objects listed" error: 11395ms (12:19:03.575) Sep 20 12:19:03 8BMQ363 k3s[11943]: Trace[975563300]: [11.395738375s] [11.395738375s] END Sep 20 12:19:03 8BMQ363 k3s[11943]: I0920 12:19:03.777198 11943 trace.go:205] Trace[305223644]: "Reflector ListAndWatch" name:object-"pc"/"ah-client-secret" (20-Sep-2023 12:18:52.180) (total time: 11596ms): Sep 20 12:19:03 8BMQ363 k3s[11943]: Trace[305223644]: ---"Objects listed" error: 11596ms (12:19:03.777) Sep 20 12:19:03 8BMQ363 k3s[11943]: Trace[305223644]: [11.596913107s] [11.596913107s] END Sep 20 12:19:03 8BMQ363 k3s[11943]: I0920 12:19:03.976149 11943 trace.go:205] Trace[246029786]: "Reflector ListAndWatch" name:object-"pc"/"lt-client-cert" (20-Sep-2023 12:18:52.180) (total time: 11795ms): Sep 20 12:19:03 8BMQ363 k3s[11943]: Trace[246029786]: ---"Objects listed" error: 11795ms (12:19:03.976) Sep 20 12:19:03 8BMQ363 k3s[11943]: Trace[246029786]: [11.795820059s] [11.795820059s] END Sep 20 12:19:04 8BMQ363 k3s[11943]: I0920 12:19:04.175872 11943 trace.go:205] Trace[715048251]: "Reflector ListAndWatch" name:object-"pc"/"certm" (20-Sep-2023 12:18:52.180) (total time: 11995ms): Sep 20 12:19:04 8BMQ363 k3s[11943]: Trace[715048251]: ---"Objects listed" error: 11995ms (12:19:04.175) Sep 20 12:19:04 8BMQ363 k3s[11943]: Trace[715048251]: [11.995556766s] [11.995556766s] END Sep 20 12:19:04 8BMQ363 k3s[11943]: I0920 12:19:04.377479 11943 trace.go:205] Trace[641719437]: "Reflector ListAndWatch" name:object-"envoy-cm-agent" (20-Sep-2023 12:18:52.180) (total time: 12197ms): Sep 20 12:19:04 8BMQ363 k3s[11943]: Trace[641719437]: ---"Objects listed" error: 12197ms (12:19:04.377) Sep 20 12:19:04 8BMQ363 k3s[11943]: Trace[641719437]: [12.197177615s] [12.197177615s] END Sep 20 12:19:04 8BMQ363 k3s[11943]: I0920 12:19:04.575880 11943 trace.go:205] Trace[1561941294]: "Reflector ListAndWatch" name:object-"pc"/"log-level" (20-Sep-2023 12:18:52.180) (total time: 12395ms): Sep 20 12:19:04 8BMQ363 k3s[11943]: Trace[1561941294]: ---"Objects listed" error: 12395ms (12:19:04.575) Sep 20 12:19:04 8BMQ363 k3s[11943]: Trace[1561941294]: [12.395539435s] [12.395539435s] END Sep 20 12:19:04 8BMQ363 k3s[11943]: I0920 12:19:04.776646 11943 trace.go:205] Trace[204984126]: "Reflector ListAndWatch" name:object-"pc"/"db-pg-metrics-cert" (20-Sep-2023 12:18:52.180) (total time: 12596ms):

Steps To Reproduce: restart k3s

Expected behavior: no trace message

Actual behavior: flooding trace message

Additional context / logs:

tibetsam commented 1 year ago

here is the api metric: curl -s ${purl}/api/v1/query?query=apiserver_flowcontrol_rejected_requests_total {"status":"success","data":{"resultType":"vector","result":[]}}

curl -s ${purl}/api/v1/query?query=apiserver_flowcontrol_request_concurrency_limit | jq '.data.result[] | .metric.priority_level, .value[1]' "catch-all" "13" "global-default" "49" "leader-election" "25" "node-high" "98" "system" "74" "workload-high" "98" "workload-low" "245"

systemctl status k3s-server | grep Active Active: active (running) since Wed 2023-09-20 12:50:31 UTC; 15min ago

curl -s "${purl}/api/v1/query?query=max_over_time((irate(apiserver_flowcontrol_dispatched_requests_total%5B45s%5D))%5B20m%3A10s%5D)" | jq '.data.result[]|.metric.flow_schema, .value[1]' "catch-all" "0" "exempt" "3.3333333333333335" "global-default" "1.1333333333333333" "kube-controller-manager" "0.43333333333333335" "kube-scheduler" "0.13333333333333333" "kube-system-service-accounts" "3.3333333333333335" "probes" "0.1" "service-accounts" "0" "service-accounts" "19.7" "system-leader-election" "2" "system-node-high" "0.23333333333333334" "system-nodes" "12" "catch-all" "2.1333333333333333" "exempt" "23.433333333333334" "global-default" "2.466666666666667" "kube-controller-manager" "10.1" "kube-scheduler" "1.2333333333333334" "kube-system-service-accounts" "17.2" "probes" "0.26666666666666666" "service-accounts" "0" "service-accounts" "64.36666666666666" "system-leader-election" "2" "system-node-high" "0.5" "system-nodes" "13.5"

brandond commented 1 year ago

As you noted, those messages come directly from the Kubernetes apiserver, not anything in K3s itself. Usually, these messages indicate a problem with datastore performance, most frequently caused by insufficient storage - although in this case it looks like whatever you've deployed to the "pc" namespace is throttling itself on the client side, so there's probably not anything wrong with your datastore. I suspect that the client in question is reconnecting to the apiserver after k3s restarts, and throttling itself as it re-lists all the objects in the cluster that it wants to observe.

I am closing this, as I don't see that there is anything to be resolved here in K3s.

tibetsam commented 1 year ago

Hi @brandond , thanks for the reply.

Actually i did a tcp trace during k3s restart, i didn't see anything was connection to api-server rather than k3s itself, that's i think it's k3s issue. Beside tcptrace, i also noticed that while secret.go complains about the error, we saw trace message from request.go here is the tcptrace: 8BMQ363:/usr/share/bcc/tools # ./tcpconnect -P 6443 -t & systemctl restart k3s-server [1] 8674 Tracing connect ... Hit Ctrl-C to end TIME(s) PID COMM IP SADDR DADDR DPORT 0.000 9224 k3s-server 4 10.10.202.1 10.10.202.1 6443 0.001 9224 k3s-server 4 10.10.202.1 10.10.202.1 6443 0.003 9224 k3s-server 4 10.10.202.1 10.10.202.1 6443 0.004 9224 k3s-server 4 10.10.202.1 10.10.202.1 6443 0.004 9224 k3s-server 4 10.10.202.1 10.10.202.1 6443 0.004 9224 k3s-server 4 10.10.202.1 10.10.202.1 6443 0.006 9224 k3s-server 4 10.10.202.1 10.10.202.1 6443 0.006 9224 k3s-server 4 10.10.202.1 10.10.202.1 6443 0.008 9224 k3s-server 4 10.10.202.1 10.10.202.1 6443 0.567 9224 k3s-server 4 10.10.202.1 10.10.202.1 6443 0.607 9224 k3s-server 4 10.10.202.1 10.10.202.1 6443 0.607 9224 k3s-server 4 10.10.202.1 10.10.202.1 6443 0.607 9224 k3s-server 4 10.10.202.1 10.10.202.1 6443 0.608 9224 k3s-server 4 10.10.202.1 10.10.202.1 6443 1.009 9224 k3s-server 4 10.10.202.1 10.10.202.1 6443 1.009 9224 k3s-server 4 10.10.202.1 10.10.202.1 6443 1.012 9224 k3s-server 4 10.10.202.1 10.10.202.1 6443 1.799 9224 k3s-server 4 10.10.202.1 10.10.202.1 6443 1.799 9224 k3s-server 4 10.10.202.1 10.10.202.1 6443 2.007 9224 k3s-server 4 10.10.202.1 10.10.202.1 6443 2.009 9224 k3s-server 4 10.10.202.1 10.10.202.1 6443 2.009 9224 k3s-server 4 10.10.202.1 10.10.202.1 6443 2.010 9224 k3s-server 4 10.10.202.1 10.10.202.1 6443 2.010 9224 k3s-server 4 10.10.202.1 10.10.202.1 6443 2.011 9224 k3s-server 4 10.10.202.1 10.10.202.1 6443 2.018 9224 k3s-server 4 10.10.202.1 10.10.202.1 6443 8BMQ363:/usr/share/bcc/tools # 5.004 9224 k3s-server 4 10.10.202.1 10.10.202.1 6443 5.006 9224 k3s-server 4 10.10.202.1 10.10.202.1 6443 5.008 9224 k3s-server 4 10.10.202.1 10.10.202.1 6443 5.011 9224 k3s-server 4 10.10.202.1 10.10.202.1 6443 5.041 9224 k3s-server 4 10.10.202.1 10.10.202.1 6443 16.320 9224 k3s-server 4 10.10.202.1 10.10.202.1 6443 53.420 9224 k3s-server 4 10.10.202.1 10.10.202.1 6443 53.421 9224 k3s-server 4 10.10.202.1 10.10.202.1 6443 89.306 9224 k3s-server 4 10.10.202.1 10.10.202.1 6443 89.638 9224 k3s-server 4 10.10.202.1 10.10.202.1 6443 89.883 9224 k3s-server 4 10.10.202.1 10.10.202.1 6443 90.103 9224 k3s-server 4 10.10.202.1 10.10.202.1 6443 90.366 9224 k3s-server 4 10.10.202.1 10.10.202.1 6443 116.383 9224 k3s-server 4 10.10.202.1 10.10.202.1 6443 116.525 9224 k3s-server 4 10.10.202.1 10.10.202.1 6443 116.666 9224 k3s-server 4 10.10.202.1 10.10.202.1 6443 116.791 9224 k3s-server 4 10.10.202.1 10.10.202.1 6443 116.921 9224 k3s-server 4 10.10.202.1 10.10.202.1 6443 117.071 9224 k3s-server 4 10.10.202.1 10.10.202.1 6443 139.950 9224 k3s-server 4 10.10.202.1 10.10.202.1 6443 140.090 9224 k3s-server 4 10.10.202.1 10.10.202.1 6443 140.226 9224 k3s-server 4 10.10.202.1 10.10.202.1 6443 140.356 9224 k3s-server 4 10.10.202.1 10.10.202.1 6443 140.490 9224 k3s-server 4 10.10.202.1 10.10.202.1 6443 140.625 9224 k3s-server 4 10.10.202.1 10.10.202.1 6443 here are the snippet logs: Sep 21 08:42:36 8BMQ363 k3s[3564]: E0921 08:42:36.347355 3564 secret.go:192] Couldn't get secret pc/license-getter-client-cert: failed to sync secret cache: timed out waiting for the condition Sep 21 08:42:37 8BMQ363 k3s[3564]: I0921 08:42:37.529668 3564 request.go:682] Waited for 3.737726915s due to client-side throttling, not priority and fairness, request: GET:https://10.10.202.1:6443/api/v1/namespaces/pc/secrets?fieldSelector=metadata.name%3Dlicense-getter-client-cert&resourceVersion=2420880

And I don't think it's datastore performance issue, i collected some database stats which doesn't show me there is issue with DB.

k3s=# SELECT query, calls, stddev_exec_time, total_exec_time, rows, 100.0 shared_blks_hit / nullif(shared_blks_hit + shared_blks_read, 0) AS hit_percent FROM pg_stat_statements ORDER BY total_exec_time DESC LIMIT 2; -[ RECORD 1 ]----+--------------------------------------------------------------------------------------------------------------------------------------------------------------- query | SELECT + | FROM ( + | SELECT ( + | SELECT MAX(rkv.id) AS id + | FROM kine AS rkv), ( + | SELECT MAX(crkv.prev_revision) AS prev_revision + | FROM kine AS crkv + | WHERE crkv.name = $3), kv.id AS theid, kv.name, kv.created, kv.deleted, kv.create_revision, kv.prev_revision, kv.lease, kv.value, kv.old_value+ | FROM kine AS kv + | JOIN ( + | SELECT MAX(mkv.id) AS id + | FROM kine AS mkv + | WHERE + | mkv.name LIKE $1 + | + | GROUP BY mkv.name) AS maxkv + | ON maxkv.id = kv.id + | WHERE + | kv.deleted = $4 OR + | $2 + | ) AS lkv + | ORDER BY lkv.theid ASC calls | 3782544 stddev_exec_time | 4.5409399788557305 total_exec_time | 6988546.127917091 rows | 42216028 hit_percent | 99.9998239192438476 -[ RECORD 2 ]----+--------------------------------------------------------------------------------------------------------------------------------------------------------------- query | SELECT * + | FROM ( + | SELECT ( + | SELECT MAX(rkv.id) AS id + | FROM kine AS rkv), ( + | SELECT MAX(crkv.prev_revision) AS prev_revision + | FROM kine AS crkv + | WHERE crkv.name = $3), kv.id AS theid, kv.name, kv.created, kv.deleted, kv.create_revision, kv.prev_revision, kv.lease, kv.value, kv.old_value+ | FROM kine AS kv + | JOIN ( + | SELECT MAX(mkv.id) AS id + | FROM kine AS mkv + | WHERE + | mkv.name LIKE $1 + | + | GROUP BY mkv.name) AS maxkv + | ON maxkv.id = kv.id + | WHERE + | kv.deleted = $4 OR + | $2 + | ) AS lkv + | ORDER BY lkv.theid ASC + | LIMIT $5 calls | 868906 stddev_exec_time | 3.425867635969894 total_exec_time | 6017251.991769958 rows | 1020798 hit_percent | 99.9998827132751301

brandond commented 1 year ago

This does not look to me like a request that K3s would make: request: GET:https://10.10.202.1:6443/api/v1/namespaces/pc/secrets?fieldSelector=metadata.name%3Dlicense-getter-client-cert&resourceVersion=2420880

Similarly, the other errors all seem to relate to envoy and/or the pc namespace. What have you deployed to that namespace? Do you still see these errors on a similar configuration of k3s that does not have that application deployed?

tibetsam commented 1 year ago

thanks, i can give it try without pc namespace, but i don't think the result is comparable, bcz we have around 100 pods in that pc namespace, and without them i don't think the k3s will be under pressure.

And do you know what is possible reason i don't see other process except k3s with this tracing command? ./tcpconnect -P 6443 -t & systemctl restart k3s-server

last question:D, where did you see this problem might related to envoy? dose envoy use go-client rest?

brandond commented 1 year ago

I'm just working off of the section of logs you provided.

tibetsam commented 1 year ago

@brandond thanks a lot for your support, fight for the user!!!

I don't see those message anymore after upgraded to 1.27.5+ k3s -v k3s version v1.27.5+k3s1 (8d074ecb) go version go1.20.7

brandond commented 1 year ago

That's interesting. I wouldn't have expected it to make a significant difference. Do you see any changes in the responsiveness of the applications you're running in the cluster?

tibetsam commented 1 year ago

Indeed, i've no idea what happened in the back. whole restart process is much faster than before. btw, maybe do you know how to debug all requests received by API server?

~# systemctl status k3s-server | grep since Active: active (running) since Wed 2023-09-27 07:40:47 UTC; 3min 11s ago ~# journalctl --since "2023-09-27 07:40:47" | grep Trace ~# journalctl --since "2023-09-27 07:40:47" | grep secret.go

tibetsam commented 1 year ago

or any command i can run and compare these two versions?

tibetsam commented 1 year ago

i saw some new message from the logs: Sep 27 08:15:43 8BMQ363 k3s[7286]: time="2023-09-27T08:15:43Z" level=info msg="COMPACT compactRev=310256 targetCompactRev=311256 currentRev=313245" Sep 27 08:15:44 8BMQ363 k3s[7286]: time="2023-09-27T08:15:44Z" level=info msg="COMPACT deleted 1000 rows from 1000 revisions in 26.447937ms - compacted to 311256/313245" Sep 27 08:15:44 8BMQ363 k3s[7286]: time="2023-09-27T08:15:44Z" level=info msg="COMPACT compactRev=311256 targetCompactRev=311729 currentRev=313245" Sep 27 08:15:44 8BMQ363 k3s[7286]: time="2023-09-27T08:15:44Z" level=info msg="COMPACT deleted 473 rows from 473 revisions in 18.26506ms - compacted to 311729/313245"

brandond commented 1 year ago

We increased the verbosity of compaction details to info a while back, to provide increased visibility.

If you want to log all requests to the apiserver, the best way to do that is to enable audit logging. That is covered in the upstream docs.

tibetsam commented 1 year ago

Thanks a lot, i will give it a try to audit all api calls

the difference between v1.27 and v1.25 restart logs is basically secret.go:192] Couldn't get secret pc/vpn-gateway-forwarder-mbkf-client-secret: failed to sync secret cache: timed out waiting for the condition and followed by, so i don't think this is something triggered outside of k3s nestedpendingoperations.go:348] Operation for "{volumeName:kubernetes.io/secret/3b9bbbab-9e4e-42fa-85da-44528fd1f554-mbkf-client-certificate podName:3b9bbbab-9e4e-42fa-85da-44528fd1f554 nodeName:}" failed. No retries permitted until 2023-09-13 349 +0000 UTC m=+14.189187497 (durationBeforeRetry 500ms). Error: MountVolume.SetUp failed for volume "mbkf-client-certificate" (UniqueName: "kubernetes.io/secret/3b9bbbab-9e4e-42fa-85da-44528fd1f554-mbkf-client-certificate") pod "vpn-gateway-forwarder-5fc7b69556-zg5qs" (UID: "3b9bbbab-9e4e-42fa-85da-44528fd1f554") :

tibetsam commented 1 year ago

Now, i can see once a while this kind of message, waited more than 1s..so less than 10s to trigger trace log, but still the number bothers me a lot, how dose it calculated and what is client-side in this case, i put audit log below, however i couldn't connect things together, what is system:node:8bmq363? kubelet inside k3s?

k3s logs: Sep 27 14:46:11 8BMQ363 k3s[6620]: I0927 14:46:11.722627 6620 request.go:696] Waited for 1.008160966s due to client-side throttling, not priority and fairness, request: GET:https://10.10.202.1:6443/api/v1/namespaces/pc/secrets?fieldSelector=metadata.name%3Dldap-client-ca&limit=500&resourceVersion=0

k3s audit logs: {"kind":"Event","apiVersion":"audit.k8s.io/v1","level":"Request","auditID":"95ea6212-e95d-4642-98f5-e328c978beec","stage":"RequestReceived","requestURI":"/api/v1/namespaces/pc/secrets?fieldSelector=metadata.name%3Dldap-client-ca\u0026limit=500\u0026resourceVersion=0","verb":"list","user":{"username":"system:node:8bmq363","groups":["system:nodes","system:authenticated"]},"sourceIPs":["10.10.202.1"],"userAgent":"k3s/v1.27.5+k3s1 (linux/amd64) kubernetes/8d074ec","objectRef":{"resource":"secrets","namespace":"pc","name":"ldap-client-ca","apiVersion":"v1"},"requestReceivedTimestamp":"2023-09-27T14:46:11.722895Z","stageTimestamp":"2023-09-27T14:46:11.722895Z"} {"kind":"Event","apiVersion":"audit.k8s.io/v1","level":"Request","auditID":"95ea6212-e95d-4642-98f5-e328c978beec","stage":"ResponseComplete","requestURI":"/api/v1/namespaces/pc/secrets?fieldSelector=metadata.name%3Dldap-client-ca\u0026limit=500\u0026resourceVersion=0","verb":"list","user":{"username":"system:node:8bmq363","groups":["system:nodes","system:authenticated"]},"sourceIPs":["10.10.202.1"],"userAgent":"k3s/v1.27.5+k3s1 (linux/amd64) kubernetes/8d074ec","objectRef":{"resource":"secrets","namespace":"pc","name":"ldap-client-ca","apiVersion":"v1"},"responseStatus":{"metadata":{},"code":200},"requestReceivedTimestamp":"2023-09-27T14:46:11.722895Z","stageTimestamp":"2023-09-27T14:46:11.724208Z","annotations":{"authorization.k8s.io/decision":"allow","authorization.k8s.io/reason":""}}