API complains on resources exist during helm install and which actually not #8708
Comments
|
additional logs from postgres and audit.log shows that although db receives insert command, but looks like data isn't saved correctly in DB, bcz looking at the pattern in postgres log and timestamp in audit.log, we can see that whenever api fails, the following db insert command uses same prev_revision. audit log: |
Don't do that. Kubernetes has an eventual consistency model. When you delete a resource, it isn't actually deleted immediately. It just sets a deletion timestamp on the object, and any controllers that have a finalizer on the object are given a chance to see that it has been marked for deletion. Once all controllers remove themselves from the finalizer list on the object, it is actually deleted by the garbage collector. Even with no finalizers, it may be a moment before the object is actually deleted. You can check out https://kubernetes.io/docs/concepts/overview/working-with-objects/finalizers/ for more information. If you want your Helm chart to actually wait for all the objects to be deleted before you try to reinstall, you should use the Ideally you would also use the |
|
@brandond thanks for the tip. I think my problem is not bcz couldn't delete resources cleanly. I can even reproduce this issue on a fresh cluster. And from postgres logs we can see both insert with create and delete from api server. |
|
FYI, the issue exist with --wait command INSTALLING, 1 ITERATION INSTALLING, 2 ITERATION INSTALLING, 3 ITERATION INSTALLING, 4 ITERATION INSTALLING, 5 ITERATION INSTALLING, 6 ITERATION INSTALLING, 7 ITERATION INSTALLING, 8 ITERATION |
|
please note , the issue is not "not found", it is "already exist". :D |
It looks to me like it still exists from the previous run, and then a moment later is gone. Postgres is one of the lower performance backends for kine for whatever reason, so I wouldn't be surprised if issues like this are easier to reproduce when using it. I'll see if this can be reproduced without helm, but it really looks to me like a race condition in helm and not an issue with the apiserver or kine. |
but then it can't explain why this can happen on a fresh cluster, and here fresh means complete new VM and new k3s cluster.
thanks, what i can also try is to put more delay in between and delete namespace and check resources before installing helm |
|
@brandond I have reproduced this issue with a modified version of the loadmap.py testscript from kine. Usually 10-50 creations out of 1000 fails with this script. Please let me know if you want any log files or other bits. |
@brandond could you please elaborate a little bit more on this one? |
What version of postgres are you using, and in what sort of configuration? What are the specific errors you're getting?
We run a full test suite against all the supported backends on every PR to Kine; you can find the perf figures in there for example see https://drone-pr.k3s.io/k3s-io/kine/276/1/3 I'm not sure why postgres is slower than some other engines when used as a Kine backend, but it is a frequent complaint that I hear. Folks have poked at it periodically but not made any significant difference as far as I know. For example see k3s-io/kine#78 and k3s-io/kine#151. |
|
Oh, I see what you're doing. You modified the script to sequentially create configmaps, while deleting the configmap created 5 iterations prior. Sometimes when creating the configmap, an error is returned indicating that the configmap that you expected to have been previously deleted, still exists. I was able to do a quick test just using postgres 13.2 running in Docker. A few interesting notes:
This feels to me like a slow datastore causing a cache somewhere in the apiserver to go stale, but it's hard to say where. This sounds very similar to an issue we've been tracking internally with watch events being missed in Kubernetes 1.27 and 1.28. We don't have an issue in GH yet but some basic logs from reproduction are available at https://gist.github.com/brandond/dd349d65d5afaf2e084e3d173d6c311e. Another possibility is that kine is affected by the GRPC watch stream starvation issue mentioned in #8415; I haven't had a chance to test to see whether or not removing the http mux from the kine listener makes any difference. |
|
Just out of curiosity I tried |
|
I'm going to tinker with changing the grpc mux, and fixing k3s-io/kine#215, and I'll see if I get any different behavior out of it. |
|
OK, so I ran kine standalone with trace logging enabled and confirmed that the error is coming from postgres, NOT anything in the Kubernetes layer. We can see that kine is running the EXACT SAME query to create the row both times, but the first time postgres claims there's a "duplicate key". I first suspected that the duplicate key in question was for the name,prev_revision index but we know this can't be true because the same query succeeds the second time. If we look at what's going on around this timeframe, we see kine complaining that the auto-increment primary key jumped forward at the exact same time we were trying to insert the row; kine responds by creating a "gap" record to ensure strict sequencing of event records. It appears that kine doesn't handle the slow insert properly, due to our expecting the database engine to enforce sequential inserts when using auto-increment primary keys.
I'll have to do some research to figure out where this needs to be fixed. Apparently |
|
Apparently this is due to how postgres implements auto-increment using sequences - the next number in the sequence is retrieved at the start of the insert operation, but not used until the end. Other engines assign the auto-increment id at the end of the operation, based on the current max value of the row at the time the operation completes. In the above example, sqlite and mysql would have assigned the row ids sequentially by the order they completed, not the order they started - and kine's expectations around linear ordering would be met. I'm going to have to think about how to handle this without creating further performance regressions on postgres. |
@brandond thanks for the analysis, could you please help me to understand. why same id is used in my testcase? if we assume there was gap key inserted?
{"kind":"Event","apiVersion":"audit.k8s.io/v1","level":"Metadata","auditID":"9ce9f005-3e39-4e91-a254-aaff9296ed66","stage":"ResponseComplete","requestURI":"/api/v1/namespaces/pc/configmaps?fieldManager=helm","verb":"create","user":{"username":"system:admin","groups":["system:masters","system:authenticated"]},"sourceIPs":["10.10.202.1"],"userAgent":"Go-http-client/2.0","objectRef":{"resource":"configmaps","namespace":"pc","name":"yang-provider-confd-config","apiVersion":"v1"},"responseStatus":{"metadata":{},"status":"Failure","message":"configmaps "yang-provider-confd-config" already exists","reason":"AlreadyExists","details":{"name":"yang-provider-confd-config","kind":"configmaps"},"code":409},"requestReceivedTimestamp":"2023-10-20T15:02:26.216425Z","stageTimestamp":"2023-10-20T15:02:26.247106Z","annotations":{"authorization.k8s.io/decision":"allow","authorization.k8s.io/reason":""}} and this one worked
{"kind":"Event","apiVersion":"audit.k8s.io/v1","level":"Metadata","auditID":"2f3d09c8-7abc-4146-8ab2-5595b85c56d4","stage":"ResponseComplete","requestURI":"/api/v1/namespaces/pc/configmaps?fieldManager=helm","verb":"create","user":{"username":"system:admin","groups":["system:masters","system:authenticated"]},"sourceIPs":["10.10.202.1"],"userAgent":"Go-http-client/2.0","objectRef":{"resource":"configmaps","namespace":"pc","name":"yang-provider-confd-config","apiVersion":"v1"},"responseStatus":{"metadata":{},"code":201},"requestReceivedTimestamp":"2023-10-20T15:02:33.681942Z","stageTimestamp":"2023-10-20T15:02:33.712285Z","annotations":{"authorization.k8s.io/decision":"allow","authorization.k8s.io/reason":""}} |
|
I stepped through the logic and logs above, and discussed the fix in comments within the linked PR. I'm not sure what ID you're referring to. Are you talking about the create_revision field? That's just the current max revision at the time the entry is inserted. That's how the mvcc model works. |
|
This is painful to reproduce because it skirts the edge of what the nodes can handle resource wise but you can see some of the behavior here where pods are stuck terminating on the cluster. Reproducing this isn't very consistent but Brad's gist is very handy to do so. ##Environment Details Infrastructure
Node(s) CPU architecture, OS, and version: Linux 5.14.21-150500.53-default x86_64 GNU/Linux Cluster Configuration: Config.yaml: Pods stuck terminating after scaling down the deploymentResults: |
|
Longer running error example $ kgn $ kgp -n test |
|
##Environment Details Infrastructure
Node(s) CPU architecture, OS, and version: Cluster Configuration: Config.yaml: Validation StepsResults: behavior for the pods stuck terminating is resolved and the logs are clear for the starting the watch issue truncated output from rapidly scaling down observer pods from 200 to 3 starting watch isn't found |
Environmental Info:
K3s Version:
k3s version v1.27.5+k3s1 (8d074ec)
go version go1.20.7
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 with postgresql as etcd db
Postgresql Config:
~/yang-provider # cat /var/lib/pgsql/data/postgresql.conf
listen_addresses = '10.10.202.1' # what IP address(es) to listen on;
max_connections = 200
k3s-server config:
~/yang-provider # cat /etc/rancher/k3s/k3s-server.env
K3S_SERVER_ARGS="--disable coredns,servicelb,traefik,local-storage,metrics-server
--flannel-backend=none
--datastore-endpoint='postgres://k3s:k3s@10.10.202.1:5432/k3s?sslmode=disable'
--pause-image=docker-registry.docker-registry.svc.cluster.local:5000/rancher/mirrored-pause:3.6
--bind-address 10.10.202.1
--node-ip=10.10.202.1
--service-cidr 10.10.201.0/24
--cluster-dns 10.10.201.10
--cluster-cidr=10.10.200.0/24
--disable-network-policy
--kube-controller-manager-arg node-cidr-mask-size=24
--kubelet-arg config=/var/lib/rancher/k3s/server/kubelet.yaml
--kube-apiserver-arg feature-gates=ServiceIPStaticSubrange=true
--kube-apiserver-arg='audit-log-path=/var/log/k3s/audit/audit.log'
--kube-apiserver-arg='audit-policy-file=/var/lib/rancher/k3s/server/audit.yaml'
--debug
-v=9
--log=/var/log/k3s/k3s.log
--kube-apiserver-arg event-ttl=4h"
Describe the bug:
during helm installation kube-api complains resources exist, but while checking cluster information, the resources were not there.
Steps To Reproduce:
run this simply one line script with given chart in https://github.com/tibetsam/yang-provider
~/yang-provider # for i in $(seq 1 20); do printf "\nINSTALLING, $i ITERATION\n"; helm install yang -n pc ./ ; kubectl get configmap yang-provider-confd-config -n pc; echo "sleeping 5s"; sleep 5; echo "DELETING"; helm delete yang -n pc; done
INSTALLING, 1 ITERATION
NAME: yang
LAST DEPLOYED: Fri Oct 20 13:59:52 2023
NAMESPACE: pc
STATUS: deployed
REVISION: 1
TEST SUITE: None
NOTES:
Service is deployed as yang-provider
NAME DATA AGE
yang-provider-confd-config 2 0s
sleeping 5s
DELETING
release "yang" uninstalled
INSTALLING, 2 ITERATION
Error: INSTALLATION FAILED: configmaps "yang-provider-confd-config" already exists
Error from server (NotFound): configmaps "yang-provider-confd-config" not found
sleeping 5s
DELETING
release "yang" uninstalled
INSTALLING, 3 ITERATION
NAME: yang
LAST DEPLOYED: Fri Oct 20 14:00:07 2023
NAMESPACE: pc
STATUS: deployed
REVISION: 1
TEST SUITE: None
NOTES:
Service is deployed as yang-provider
NAME DATA AGE
yang-provider-confd-config 2 0s
sleeping 5s
DELETING
release "yang" uninstalled
INSTALLING, 4 ITERATION
NAME: yang
LAST DEPLOYED: Fri Oct 20 14:00:15 2023
NAMESPACE: pc
STATUS: deployed
REVISION: 1
TEST SUITE: None
NOTES:
Service is deployed as yang-provider
NAME DATA AGE
yang-provider-confd-config 2 1s
sleeping 5s
DELETING
release "yang" uninstalled
INSTALLING, 5 ITERATION
Error: INSTALLATION FAILED: configmaps "yang-provider-confd-config" already exists
Error from server (NotFound): configmaps "yang-provider-confd-config" not found
sleeping 5s
DELETING
release "yang" uninstalled
INSTALLING, 6 ITERATION
NAME: yang
LAST DEPLOYED: Fri Oct 20 14:00:30 2023
NAMESPACE: pc
STATUS: deployed
REVISION: 1
TEST SUITE: None
NOTES:
Service is deployed as yang-provider
NAME DATA AGE
yang-provider-confd-config 2 1s
sleeping 5s
DELETING
release "yang" uninstalled
INSTALLING, 7 ITERATION
Error: INSTALLATION FAILED: configmaps "yang-provider-confd-config" already exists
Error from server (NotFound): configmaps "yang-provider-confd-config" not found
sleeping 5s
DELETING
release "yang" uninstalled
INSTALLING, 8 ITERATION
NAME: yang
LAST DEPLOYED: Fri Oct 20 14:00:44 2023
NAMESPACE: pc
STATUS: deployed
REVISION: 1
TEST SUITE: None
NOTES:
Service is deployed as yang-provider
NAME DATA AGE
yang-provider-confd-config 2 0s
sleeping 5s
DELETING
release "yang" uninstalled
INSTALLING, 9 ITERATION
Error: INSTALLATION FAILED: configmaps "yang-provider-confd-config" already exists
Error from server (NotFound): configmaps "yang-provider-confd-config" not found
sleeping 5s
DELETING
release "yang" uninstalled
INSTALLING, 10 ITERATION
NAME: yang
LAST DEPLOYED: Fri Oct 20 14:00:59 2023
NAMESPACE: pc
STATUS: deployed
REVISION: 1
TEST SUITE: None
NOTES:
Service is deployed as yang-provider
NAME DATA AGE
yang-provider-confd-config 2 0s
sleeping 5s
DELETING
release "yang" uninstalled
INSTALLING, 11 ITERATION
NAME: yang
LAST DEPLOYED: Fri Oct 20 14:01:08 2023
NAMESPACE: pc
STATUS: deployed
REVISION: 1
TEST SUITE: None
NOTES:
Service is deployed as yang-provider
NAME DATA AGE
yang-provider-confd-config 2 1s
sleeping 5s
DELETING
release "yang" uninstalled
INSTALLING, 12 ITERATION
NAME: yang
LAST DEPLOYED: Fri Oct 20 14:01:17 2023
NAMESPACE: pc
STATUS: deployed
REVISION: 1
TEST SUITE: None
NOTES:
Service is deployed as yang-provider
NAME DATA AGE
yang-provider-confd-config 2 1s
sleeping 5s
DELETING
release "yang" uninstalled
INSTALLING, 13 ITERATION
Error: INSTALLATION FAILED: configmaps "yang-provider-confd-config" already exists
Error from server (NotFound): configmaps "yang-provider-confd-config" not found
sleeping 5s
DELETING
release "yang" uninstalled
INSTALLING, 14 ITERATION
NAME: yang
LAST DEPLOYED: Fri Oct 20 14:01:34 2023
NAMESPACE: pc
STATUS: deployed
REVISION: 1
TEST SUITE: None
NOTES:
Service is deployed as yang-provider
NAME DATA AGE
yang-provider-confd-config 2 0s
sleeping 5s
DELETING
release "yang" uninstalled
INSTALLING, 15 ITERATION
NAME: yang
LAST DEPLOYED: Fri Oct 20 14:01:42 2023
NAMESPACE: pc
STATUS: deployed
REVISION: 1
TEST SUITE: None
NOTES:
Service is deployed as yang-provider
NAME DATA AGE
yang-provider-confd-config 2 1s
sleeping 5s
DELETING
release "yang" uninstalled
INSTALLING, 16 ITERATION
NAME: yang
LAST DEPLOYED: Fri Oct 20 14:01:49 2023
NAMESPACE: pc
STATUS: deployed
REVISION: 1
TEST SUITE: None
NOTES:
Service is deployed as yang-provider
NAME DATA AGE
yang-provider-confd-config 2 0s
sleeping 5s
DELETING
release "yang" uninstalled
INSTALLING, 17 ITERATION
NAME: yang
LAST DEPLOYED: Fri Oct 20 14:01:57 2023
NAMESPACE: pc
STATUS: deployed
REVISION: 1
TEST SUITE: None
NOTES:
Service is deployed as yang-provider
NAME DATA AGE
yang-provider-confd-config 2 1s
sleeping 5s
DELETING
release "yang" uninstalled
INSTALLING, 18 ITERATION
NAME: yang
LAST DEPLOYED: Fri Oct 20 14:02:04 2023
NAMESPACE: pc
STATUS: deployed
REVISION: 1
TEST SUITE: None
NOTES:
Service is deployed as yang-provider
NAME DATA AGE
yang-provider-confd-config 2 0s
sleeping 5s
DELETING
release "yang" uninstalled
INSTALLING, 19 ITERATION
NAME: yang
LAST DEPLOYED: Fri Oct 20 14:02:11 2023
NAMESPACE: pc
STATUS: deployed
REVISION: 1
TEST SUITE: None
NOTES:
Service is deployed as yang-provider
NAME DATA AGE
yang-provider-confd-config 2 1s
sleeping 5s
DELETING
release "yang" uninstalled
INSTALLING, 20 ITERATION
NAME: yang
LAST DEPLOYED: Fri Oct 20 14:02:19 2023
NAMESPACE: pc
STATUS: deployed
REVISION: 1
TEST SUITE: None
NOTES:
Service is deployed as yang-provider
NAME DATA AGE
yang-provider-confd-config 2 0s
sleeping 5s
DELETING
release "yang" uninstalled
Expected behavior:
helm install should succeed no matter how many times install/uninstall
Actual behavior:
helm install failing time to time
Additional context / logs:
The text was updated successfully, but these errors were encountered: