Hide Forgot
Description of problem: It's possible that pods are created and the creation of KuryrPort CRD is triggered, but the pod gets removed before Kuryrport handler finalize handling the event resulting in errors in the KuryrPort side and leftover KuryrPort CRDs. Version-Release number of selected component (if applicable): How reproducible: Steps to Reproduce: 1. 2. 3. Actual results: Expected results: Additional info:
To verify this it's probably best to do a number of fast pod creation-deletion sequences and look for tracebacks in kuryr-controller or orphaned KuryrPort CRDs.
Failed on 4.6.0-0.nightly-2020-09-03-063148 over RHOS-16.1-RHEL-8-20200831.n.1. Running several times beloww command: $ oc --image kuryr/demo run demo && sleep 1 && oc delete pod/demo is killing VIFHandler on kuryr-controller: 2020-09-04 09:57:28.905 1 ERROR kuryr_kubernetes.controller.managers.health [-] Component VIFHandler is dead. due to below: Forbidden: no new finalizers can be added if the object is being deleted, found new finalizers []string{\"kuryr.openstack.org/pod-finalizer\" Attaching kuryr-controller logs.
Created attachment 1713758 [details] kuryr-controller logs
Failed on 4.6.0-0.nightly-2020-09-10-011413. forbidden exception not caught so kuryr-controller is still restarting. 2020-09-10 09:05:18.694 1 ERROR kuryr_kubernetes.controller.handlers.vif [-] Failed to add finalizer to pod object: {"kind":"Status","apiVersion":"v1","metadata":{},"status":"Failure","message":"Pod \"demo\" is invalid: metadata.finalizers: Forbidden: no new finalizers can be added if the object is being deleted, found new finalizers []string{\"kuryr.openstack.org/pod-finalizer\"}","reason":"Invalid","details":{"name":"demo","kind":"Pod","causes":[{"reason":"FieldValueForbidden","message":"Forbidden: no new finalizers can be added if the object is being deleted, found new finalizers []string{\"kuryr.openstack.org/pod-finalizer\"}","field":"metadata.finalizers"},{"reason":"FieldValueForbidden","message":"Forbidden: no new finalizers can be added if the object is being deleted, found new finalizers []string{\"kuryr.openstack.org/pod-finalizer\"}","field":"metadata.finalizers"}]},"code":422} : kuryr_kubernetes.exceptions.K8sClientException: {"kind":"Status","apiVersion":"v1","metadata":{},"status":"Failure","message":"Pod \"demo\" is invalid: metadata.finalizers: Forbidden: no new finalizers can be added if the object is being deleted, found new finalizers []string{\"kuryr.openstack.org/pod-finalizer\"}","reason":"Invalid","details":{"name":"demo","kind":"Pod","causes":[{"reason":"FieldValueForbidden","message":"Forbidden: no new finalizers can be added if the object is being deleted, found new finalizers []string{\"kuryr.openstack.org/pod-finalizer\"}","field":"metadata.finalizers"},{"reason":"FieldValueForbidden","message":"Forbidden: no new finalizers can be added if the object is being deleted, found new finalizers []string{\"kuryr.openstack.org/pod-finalizer\"}","field":"metadata.finalizers"}]},"code":422} 2020-09-10 09:05:18.694 1 ERROR kuryr_kubernetes.controller.handlers.vif Traceback (most recent call last): 2020-09-10 09:05:18.694 1 ERROR kuryr_kubernetes.controller.handlers.vif File "/usr/lib/python3.6/site-packages/kuryr_kubernetes/controller/handlers/vif.py", line 80, in on_present 2020-09-10 09:05:18.694 1 ERROR kuryr_kubernetes.controller.handlers.vif if not k8s.add_finalizer(pod, constants.POD_FINALIZER): 2020-09-10 09:05:18.694 1 ERROR kuryr_kubernetes.controller.handlers.vif File "/usr/lib/python3.6/site-packages/kuryr_kubernetes/k8s_client.py", line 256, in add_finalizer 2020-09-10 09:05:18.694 1 ERROR kuryr_kubernetes.controller.handlers.vif self._raise_from_response(response) 2020-09-10 09:05:18.694 1 ERROR kuryr_kubernetes.controller.handlers.vif File "/usr/lib/python3.6/site-packages/kuryr_kubernetes/k8s_client.py", line 91, in _raise_from_response 2020-09-10 09:05:18.694 1 ERROR kuryr_kubernetes.controller.handlers.vif raise exc.K8sClientException(response.text) 2020-09-10 09:05:18.694 1 ERROR kuryr_kubernetes.controller.handlers.vif kuryr_kubernetes.exceptions.K8sClientException: {"kind":"Status","apiVersion":"v1","metadata":{},"status":"Failure","message":"Pod \"demo\" is invalid: metadata.finalizers: Forbidden: no new finalizers can be added if the object is being deleted, found new finalizers []string{\"kuryr.openstack.org/pod-finalizer\"}","reason":"Invalid","details":{"name":"demo","kind":"Pod","causes":[{"reason":"FieldValueForbidden","message":"Forbidden: no new finalizers can be added if the object is being deleted, found new finalizers []string{\"kuryr.openstack.org/pod-finalizer\"}","field":"metadata.finalizers"},{"reason":"FieldValueForbidden","message":"Forbidden: no new finalizers can be added if the object is being deleted, found new finalizers []string{\"kuryr.openstack.org/pod-finalizer\"}","field":"metadata.finalizers"}]},"code":422} 2020-09-10 09:05:18.694 1 ERROR kuryr_kubernetes.controller.handlers.vif 2020-09-10 09:05:18.694 1 ERROR kuryr_kubernetes.controller.handlers.vif 2020-09-10 09:05:18.697 1 ERROR kuryr_kubernetes.handlers.retry [-] Report handler unhealthy VIFHandler: kuryr_kubernetes.exceptions.K8sClientException: {"kind":"Status","apiVersion":"v1","metadata":{},"status":"Failure","message":"Pod \"demo\" is invalid: metadata.finalizers: Forbidden: no new finalizers can be added if the object is being deleted, found new finalizers []string{\"kuryr.openstack.org/pod-finalizer\"}","reason":"Invalid","details":{"name":"demo","kind":"Pod","causes":[{"reason":"FieldValueForbidden","message":"Forbidden: no new finalizers can be added if the object is being deleted, found new finalizers []string{\"kuryr.openstack.org/pod-finalizer\"}","field":"metadata.finalizers"},{"reason":"FieldValueForbidden","message":"Forbidden: no new finalizers can be added if the object is being deleted, found new finalizers []string{\"kuryr.openstack.org/pod-finalizer\"}","field":"metadata.finalizers"}]},"code":422} 2020-09-10 09:05:18.697 1 ERROR kuryr_kubernetes.handlers.retry Traceback (most recent call last): 2020-09-10 09:05:18.697 1 ERROR kuryr_kubernetes.handlers.retry File "/usr/lib/python3.6/site-packages/kuryr_kubernetes/handlers/retry.py", line 78, in __call__ 2020-09-10 09:05:18.697 1 ERROR kuryr_kubernetes.handlers.retry self._handler(event, *args, **kwargs) 2020-09-10 09:05:18.697 1 ERROR kuryr_kubernetes.handlers.retry File "/usr/lib/python3.6/site-packages/kuryr_kubernetes/handlers/k8s_base.py", line 84, in __call__ 2020-09-10 09:05:18.697 1 ERROR kuryr_kubernetes.handlers.retry self.on_present(obj) 2020-09-10 09:05:18.697 1 ERROR kuryr_kubernetes.handlers.retry File "/usr/lib/python3.6/site-packages/kuryr_kubernetes/controller/handlers/vif.py", line 80, in on_present 2020-09-10 09:05:18.697 1 ERROR kuryr_kubernetes.handlers.retry if not k8s.add_finalizer(pod, constants.POD_FINALIZER): 2020-09-10 09:05:18.697 1 ERROR kuryr_kubernetes.handlers.retry File "/usr/lib/python3.6/site-packages/kuryr_kubernetes/k8s_client.py", line 256, in add_finalizer 2020-09-10 09:05:18.697 1 ERROR kuryr_kubernetes.handlers.retry self._raise_from_response(response) 2020-09-10 09:05:18.697 1 ERROR kuryr_kubernetes.handlers.retry File "/usr/lib/python3.6/site-packages/kuryr_kubernetes/k8s_client.py", line 91, in _raise_from_response 2020-09-10 09:05:18.697 1 ERROR kuryr_kubernetes.handlers.retry raise exc.K8sClientException(response.text) 2020-09-10 09:05:18.697 1 ERROR kuryr_kubernetes.handlers.retry kuryr_kubernetes.exceptions.K8sClientException: {"kind":"Status","apiVersion":"v1","metadata":{},"status":"Failure","message":"Pod \"demo\" is invalid: metadata.finalizers: Forbidden: no new finalizers can be added if the object is being deleted, found new finalizers []string{\"kuryr.openstack.org/pod-finalizer\"}","reason":"Invalid","details":{"name":"demo","kind":"Pod","causes":[{"reason":"FieldValueForbidden","message":"Forbidden: no new finalizers can be added if the object is being deleted, found new finalizers []string{\"kuryr.openstack.org/pod-finalizer\"}","field":"metadata.finalizers"},{"reason":"FieldValueForbidden","message":"Forbidden: no new finalizers can be added if the object is being deleted, found new finalizers []string{\"kuryr.openstack.org/pod-finalizer\"}","field":"metadata.finalizers"}]},"code":422} 2020-09-10 09:05:18.697 1 ERROR kuryr_kubernetes.handlers.retry 2020-09-10 09:05:18.697 1 ERROR kuryr_kubernetes.handlers.retry 2020-09-10 09:05:18.699 1 ERROR kuryr_kubernetes.handlers.logging [-] Failed to handle event {'type': 'MODIFIED', 'object': {'kind': 'Pod', 'apiVersion': 'v1', 'metadata': {'name': 'demo', 'namespace': 'test', 'selfLink': '/api/v1/namespaces/test/pods/demo', 'uid': '57fcbdab-366f-4902-97bb-495a6ccdd4e7', 'resourceVersion': '111623', 'creationTimestamp': '2020-09-10T09:05:15Z', 'labels': {'run': 'demo'}, 'annotations': {'openshift.io/scc': 'anyuid'}, 'managedFields': [{'manager': 'kubectl-run', 'operation': 'Update', 'apiVersion': 'v1', 'time': '2020-09-10T09:05:15Z', 'fieldsType': 'FieldsV1', 'fieldsV1': {'f:metadata': {'f:labels': {'.': {}, 'f:run': {}}}, 'f:spec': {'f:containers': {'k:{"name":"demo"}': {'.': {}, 'f:image': {}, 'f:imagePullPolicy': {}, 'f:name': {}, 'f:resources': {}, 'f:terminationMessagePath': {}, 'f:terminationMessagePolicy': {}}}, 'f:dnsPolicy': {}, 'f:enableServiceLinks': {}, 'f:restartPolicy': {}, 'f:schedulerName': {}, 'f:securityContext': {}, 'f:terminationGracePeriodSeconds': {}}}}, {'manager': 'kubelet', 'operation': 'Update', 'apiVersion': 'v1', 'time': '2020-09-10T09:05:15Z', 'fieldsType': 'FieldsV1', 'fieldsV1': {'f:status': {'f:conditions': {'k:{"type":"ContainersReady"}': {'.': {}, 'f:lastProbeTime': {}, 'f:lastTransitionTime': {}, 'f:message': {}, 'f:reason': {}, 'f:status': {}, 'f:type': {}}, 'k:{"type":"Initialized"}': {'.': {}, 'f:lastProbeTime': {}, 'f:lastTransitionTime': {}, 'f:status': {}, 'f:type': {}}, 'k:{"type":"Ready"}': {'.': {}, 'f:lastProbeTime': {}, 'f:lastTransitionTime': {}, 'f:message': {}, 'f:reason': {}, 'f:status': {}, 'f:type': {}}}, 'f:containerStatuses': {}, 'f:hostIP': {}, 'f:startTime': {}}}}]}, 'spec': {'volumes': [{'name': 'default-token-xz8bq', 'secret': {'secretName': 'default-token-xz8bq', 'defaultMode': 420}}], 'containers': [{'name': 'demo', 'image': 'kuryr/demo', 'resources': {}, 'volumeMounts': [{'name': 'default-token-xz8bq', 'readOnly': True, 'mountPath': '/var/run/secrets/kubernetes.io/serviceaccount'}], 'terminationMessagePath': '/dev/termination-log', 'terminationMessagePolicy': 'File', 'imagePullPolicy': 'Always', 'securityContext': {'capabilities': {'drop': ['MKNOD']}}}], 'restartPolicy': 'Always', 'terminationGracePeriodSeconds': 30, 'dnsPolicy': 'ClusterFirst', 'serviceAccountName': 'default', 'serviceAccount': 'default', 'nodeName': 'ostest-bwl6w-worker-0-85tkz', 'securityContext': {'seLinuxOptions': {'level': 's0:c25,c0'}}, 'imagePullSecrets': [{'name': 'default-dockercfg-tk2ln'}], 'schedulerName': 'default-scheduler', 'tolerations': [{'key': 'node.kubernetes.io/not-ready', 'operator': 'Exists', 'effect': 'NoExecute', 'tolerationSeconds': 300}, {'key': 'node.kubernetes.io/unreachable', 'operator': 'Exists', 'effect': 'NoExecute', 'tolerationSeconds': 300}], 'priority': 0, 'dnsConfig': {'options': [{'name': 'use-vc', 'value': ''}]}, 'enableServiceLinks': True, 'preemptionPolicy': 'PreemptLowerPriority'}, 'status': {'phase': 'Pending', 'conditions': [{'type': 'Initialized', 'status': 'True', 'lastProbeTime': None, 'lastTransitionTime': '2020-09-10T09:05:15Z'}, {'type': 'Ready', 'status': 'False', 'lastProbeTime': None, 'lastTransitionTime': '2020-09-10T09:05:15Z', 'reason': 'ContainersNotReady', 'message': 'containers with unready status: [demo]'}, {'type': 'ContainersReady', 'status': 'False', 'lastProbeTime': None, 'lastTransitionTime': '2020-09-10T09:05:15Z', 'reason': 'ContainersNotReady', 'message': 'containers with unready status: [demo]'}, {'type': 'PodScheduled', 'status': 'True', 'lastProbeTime': None, 'lastTransitionTime': '2020-09-10T09:05:15Z'}], 'hostIP': '10.196.0.203', 'startTime': '2020-09-10T09:05:15Z', 'containerStatuses': [{'name': 'demo', 'state': {'waiting': {'reason': 'ContainerCreating'}}, 'lastState': {}, 'ready': False, 'restartCount': 0, 'image': 'kuryr/demo', 'imageID': '', 'started': False}], 'qosClass': 'BestEffort'}}}: kuryr_kubernetes.exceptions.K8sClientException: {"kind":"Status","apiVersion":"v1","metadata":{},"status":"Failure","message":"Pod \"demo\" is invalid: metadata.finalizers: Forbidden: no new finalizers can be added if the object is being deleted, found new finalizers []string{\"kuryr.openstack.org/pod-finalizer\"}","reason":"Invalid","details":{"name":"demo","kind":"Pod","causes":[{"reason":"FieldValueForbidden","message":"Forbidden: no new finalizers can be added if the object is being deleted, found new finalizers []string{\"kuryr.openstack.org/pod-finalizer\"}","field":"metadata.finalizers"},{"reason":"FieldValueForbidden","message":"Forbidden: no new finalizers can be added if the object is being deleted, found new finalizers []string{\"kuryr.openstack.org/pod-finalizer\"}","field":"metadata.finalizers"}]},"code":422} 2020-09-10 09:05:18.699 1 ERROR kuryr_kubernetes.handlers.logging Traceback (most recent call last): 2020-09-10 09:05:18.699 1 ERROR kuryr_kubernetes.handlers.logging File "/usr/lib/python3.6/site-packages/kuryr_kubernetes/handlers/logging.py", line 37, in __call__ 2020-09-10 09:05:18.699 1 ERROR kuryr_kubernetes.handlers.logging self._handler(event, *args, **kwargs) 2020-09-10 09:05:18.699 1 ERROR kuryr_kubernetes.handlers.logging File "/usr/lib/python3.6/site-packages/kuryr_kubernetes/handlers/retry.py", line 78, in __call__ 2020-09-10 09:05:18.699 1 ERROR kuryr_kubernetes.handlers.logging self._handler(event, *args, **kwargs) 2020-09-10 09:05:18.699 1 ERROR kuryr_kubernetes.handlers.logging File "/usr/lib/python3.6/site-packages/kuryr_kubernetes/handlers/k8s_base.py", line 84, in __call__ 2020-09-10 09:05:18.699 1 ERROR kuryr_kubernetes.handlers.logging self.on_present(obj) 2020-09-10 09:05:18.699 1 ERROR kuryr_kubernetes.handlers.logging File "/usr/lib/python3.6/site-packages/kuryr_kubernetes/controller/handlers/vif.py", line 80, in on_present 2020-09-10 09:05:18.699 1 ERROR kuryr_kubernetes.handlers.logging if not k8s.add_finalizer(pod, constants.POD_FINALIZER): 2020-09-10 09:05:18.699 1 ERROR kuryr_kubernetes.handlers.logging File "/usr/lib/python3.6/site-packages/kuryr_kubernetes/k8s_client.py", line 256, in add_finalizer 2020-09-10 09:05:18.699 1 ERROR kuryr_kubernetes.handlers.logging self._raise_from_response(response) 2020-09-10 09:05:18.699 1 ERROR kuryr_kubernetes.handlers.logging File "/usr/lib/python3.6/site-packages/kuryr_kubernetes/k8s_client.py", line 91, in _raise_from_response 2020-09-10 09:05:18.699 1 ERROR kuryr_kubernetes.handlers.logging raise exc.K8sClientException(response.text) 2020-09-10 09:05:18.699 1 ERROR kuryr_kubernetes.handlers.logging kuryr_kubernetes.exceptions.K8sClientException: {"kind":"Status","apiVersion":"v1","metadata":{},"status":"Failure","message":"Pod \"demo\" is invalid: metadata.finalizers: Forbidden: no new finalizers can be added if the object is being deleted, found new finalizers []string{\"kuryr.openstack.org/pod-finalizer\"}","reason":"Invalid","details":{"name":"demo","kind":"Pod","causes":[{"reason":"FieldValueForbidden","message":"Forbidden: no new finalizers can be added if the object is being deleted, found new finalizers []string{\"kuryr.openstack.org/pod-finalizer\"}","field":"metadata.finalizers"},{"reason":"FieldValueForbidden","message":"Forbidden: no new finalizers can be added if the object is being deleted, found new finalizers []string{\"kuryr.openstack.org/pod-finalizer\"}","field":"metadata.finalizers"}]},"code":422} 2020-09-10 09:05:18.699 1 ERROR kuryr_kubernetes.handlers.logging 2020-09-10 09:05:18.699 1 ERROR kuryr_kubernetes.handlers.logging 2020-09-10 09:05:24.011 1 ERROR kuryr_kubernetes.controller.managers.health [-] Component VIFHandler is dead. 2020-09-10 09:05:32.841 1 ERROR kuryr_kubernetes.controller.managers.health [-] Component VIFHandler is dead. 2020-09-10 09:05:42.839 1 ERROR kuryr_kubernetes.controller.managers.health [-] Component VIFHandler is dead. 2020-09-10 09:05:52.835 1 ERROR kuryr_kubernetes.controller.managers.health [-] Component VIFHandler is dead. 2020-09-10 09:06:02.837 1 ERROR kuryr_kubernetes.controller.managers.health [-] Component VIFHandler is dead. 2020-09-10 09:06:13.580 1 ERROR kuryr_kubernetes.controller.managers.health [-] Component VIFHandler is dead. 2020-09-10 09:06:22.837 1 ERROR kuryr_kubernetes.controller.managers.health [-] Component VIFHandler is dead. 2020-09-10 09:06:32.837 1 ERROR kuryr_kubernetes.controller.managers.health [-] Component VIFHandler is dead. 2020-09-10 09:06:42.836 1 ERROR kuryr_kubernetes.controller.managers.health [-] Component VIFHandler is dead. 2020-09-10 09:06:52.837 1 ERROR kuryr_kubernetes.controller.managers.health [-] Component VIFHandler is dead. 2020-09-10 09:06:53.113 1 INFO kuryr_kubernetes.controller.service [-] Service 'KuryrK8sService' stopping 2020-09-10 09:06:53.116 1 INFO kuryr_kubernetes.watcher [-] Stopped watching '/api/v1/endpoints' 2020-09-10 09:06:53.133 1 INFO kuryr_kubernetes.watcher [-] Stopped watching '/api/v1/namespaces' 2020-09-10 09:06:53.202 1 INFO kuryr_kubernetes.watcher [-] Stopped watching '/api/v1/services' 2020-09-10 09:06:53.338 1 INFO kuryr_kubernetes.watcher [-] Stopped watching '/apis/openstack.org/v1/kuryrports' 2020-09-10 09:06:53.352 1 INFO kuryr_kubernetes.watcher [-] Stopped watching '/apis/networking.k8s.io/v1/networkpolicies' 2020-09-10 09:06:53.506 1 INFO kuryr_kubernetes.watcher [-] Stopped watching '/apis/openstack.org/v1/kuryrloadbalancers' 2020-09-10 09:06:53.670 1 INFO kuryr_kubernetes.watcher [-] Stopped watching '/apis/openstack.org/v1/kuryrnetworkpolicies' 2020-09-10 09:06:53.911 1 INFO kuryr_kubernetes.watcher [-] Stopped watching '/apis/openstack.org/v1/kuryrnetworks' 2020-09-10 09:06:53.971 1 INFO kuryr_kubernetes.watcher [-] Stopped watching '/api/v1/pods' 2020-09-10 09:06:53.971 1 INFO kuryr_kubernetes.watcher [-] No remaining active watchers, Exiting... 2020-09-10 09:06:53.972 1 INFO kuryr_kubernetes.controller.service [-] Service 'KuryrK8sService' stopping 2020-09-10 09:06:54.024 1 INFO kuryr_kubernetes.controller.service [-] Service 'KuryrK8sService' stopped
Verified on OCP 4.6.0-0.nightly-2020-09-17-073141 over OSP RHOS-16.1-RHEL-8-20200903.n.0 with ovn-octavia. Creating and destroying a pod 100 times do not restart kuryr-controller: $ oc get pods -n openshift-kuryr NAME READY STATUS RESTARTS AGE kuryr-cni-7869s 1/1 Running 0 3h22m kuryr-cni-7lgg6 1/1 Running 0 3h20m kuryr-cni-n6lwn 1/1 Running 0 3h18m kuryr-cni-v4ccn 1/1 Running 0 3h21m kuryr-cni-wdnxk 1/1 Running 0 3h20m kuryr-cni-xkvcr 1/1 Running 0 3h18m kuryr-controller-66469ccbb9-bbmph 1/1 Running 1 177m run $ for i in `seq 100`; do echo $i; oc --image kuryr/demo run demo && sleep 1 && oc delete pod/demo; done $ oc get pods -n openshift-kuryr NAME READY STATUS RESTARTS AGE kuryr-cni-7869s 1/1 Running 0 3h38m kuryr-cni-7lgg6 1/1 Running 0 3h37m kuryr-cni-n6lwn 1/1 Running 0 3h35m kuryr-cni-v4ccn 1/1 Running 1 3h37m kuryr-cni-wdnxk 1/1 Running 0 3h36m kuryr-cni-xkvcr 1/1 Running 0 3h34m kuryr-controller-66469ccbb9-bbmph 1/1 Running 1 3h14m