search

CentaurusInfra / mizar

Mizar – Experimental, High Scale and High Performance Cloud Network https://mizar.readthedocs.io
https://mizar.readthedocs.io
GNU General Public License v2.0
112 stars 50 forks source link

Extra Add/del call to CNI to get interface added to pod #609

Closed yb01 closed 2 years ago

yb01 commented 2 years ago

Root cause will be investigated. here is what i found in the log. this doesn't seem right to me from the log. it took 6 add to get the interface added to the test container pod

What happened:

root@ip-172-31-39-83:~/go/src/k8s.io/arktos# grep netpod /tmp/mizarcni.log | grep '"Command":"ADD"'
I0202 05:52:54.365744   23419 mizarcni.go:57] Network variables: {"Command":"ADD","ContainerID":"d682b478b7dfdb479de6989e68e9b2bb5d5c38221d3e3590484f9957e98e5718","NetNS":"/var/run/netns/cni-9169dd3f-c78b-5abf-b35c-6a3926a5cf21","IfName":"eth0","CniPath":"/opt/cni/bin","K8sPodNamespace":"kube-system","K8sPodName":"netpod1-1","K8sPodTenant":"system","CniVersion":"0.3.1","NetworkName":"mizarcni","Plugin":"mizarcni"}
I0202 05:53:09.295178   24155 mizarcni.go:57] Network variables: {"Command":"ADD","ContainerID":"7c0cf7e87b18e30256c66d0caa5267811bc2f7f64317f8de775f988ab124ad31","NetNS":"/var/run/netns/cni-94eb770a-6dc1-d6ee-291b-629cf9fe6968","IfName":"eth0","CniPath":"/opt/cni/bin","K8sPodNamespace":"kube-system","K8sPodName":"netpod1-1","K8sPodTenant":"system","CniVersion":"0.3.1","NetworkName":"mizarcni","Plugin":"mizarcni"}
I0202 05:56:58.513918    2259 mizarcni.go:57] Network variables: {"Command":"ADD","ContainerID":"6efbbb20cdf618090d98674f6ca1884d463a09d821fa64fd684d86b8442b8114","NetNS":"/var/run/netns/cni-b93845db-a4c1-5299-5608-f6a2d2dfb1fb","IfName":"eth0","CniPath":"/opt/cni/bin","K8sPodNamespace":"kube-system","K8sPodName":"netpod1-1","K8sPodTenant":"system","CniVersion":"0.3.1","NetworkName":"mizarcni","Plugin":"mizarcni"}
I0202 05:56:59.498074    2358 mizarcni.go:57] Network variables: {"Command":"ADD","ContainerID":"f41e4abd66f8cee2c66591b346d17f06e22d7f7b8a0270723ba6aee4be5b67ee","NetNS":"/var/run/netns/cni-1240f4a9-27b4-1fdc-4032-c3358ea91c26","IfName":"eth0","CniPath":"/opt/cni/bin","K8sPodNamespace":"kube-system","K8sPodName":"netpod1-1","K8sPodTenant":"system","CniVersion":"0.3.1","NetworkName":"mizarcni","Plugin":"mizarcni"}
I0202 05:57:11.260293    3468 mizarcni.go:57] Network variables: {"Command":"ADD","ContainerID":"1e5ac39a7fe795443435579ee67ccddd69e059b73407e5350b9c422ddbfd2f2e","NetNS":"/var/run/netns/cni-809adf83-0227-5c43-d46e-a0c72666ca2f","IfName":"eth0","CniPath":"/opt/cni/bin","K8sPodNamespace":"kube-system","K8sPodName":"netpod1-1","K8sPodTenant":"system","CniVersion":"0.3.1","NetworkName":"mizarcni","Plugin":"mizarcni"}
I0202 05:57:23.542530    4648 mizarcni.go:57] Network variables: {"Command":"ADD","ContainerID":"189eddbc1b39912270ac471393b630b29003405463787e6df23d781ea87e6990","NetNS":"/var/run/netns/cni-cdac77d8-979c-b0c9-5e9b-e13a683a7562","IfName":"eth0","CniPath":"/opt/cni/bin","K8sPodNamespace":"kube-system","K8sPodName":"netpod1-1","K8sPodTenant":"system","CniVersion":"0.3.1","NetworkName":"mizarcni","Plugin":"mizarcni"}
root@ip-172-31-39-83:~/go/src/k8s.io/arktos# 
root@ip-172-31-39-83:~/go/src/k8s.io/arktos# 
root@ip-172-31-39-83:~/go/src/k8s.io/arktos# grep netpod /tmp/mizarcni.log | grep '"Command":"ADD"' | wc -l
6
root@ip-172-31-39-83:~/go/src/k8s.io/arktos# grep netpod /tmp/mizarcni.log | grep '"Command":"DELETE"' | wc -l
0
root@ip-172-31-39-83:~/go/src/k8s.io/arktos# 
root@ip-172-31-39-83:~/go/src/k8s.io/arktos# grep netpod /tmp/mizarcni.log | grep '"Command":"DEL"' | wc -l
5
root@ip-172-31-39-83:~/go/src/k8s.io/arktos# grep netpod /tmp/mizarcni.log | grep '"Command":"DEL"' | wc -l
5
root@ip-172-31-39-83:~/go/src/k8s.io/arktos# grep netpod /tmp/mizarcni.log | grep '"Command":"DEL"'
I0202 05:52:54.376485   23436 mizarcni.go:73] Network variables: {"Command":"DEL","ContainerID":"d682b478b7dfdb479de6989e68e9b2bb5d5c38221d3e3590484f9957e98e5718","NetNS":"/var/run/netns/cni-9169dd3f-c78b-5abf-b35c-6a3926a5cf21","IfName":"eth0","CniPath":"/opt/cni/bin","K8sPodNamespace":"kube-system","K8sPodName":"netpod1-1","K8sPodTenant":"system","CniVersion":"0.3.1","NetworkName":"mizarcni","Plugin":"mizarcni"}
I0202 05:56:53.398091    1450 mizarcni.go:73] Network variables: {"Command":"DEL","ContainerID":"7c0cf7e87b18e30256c66d0caa5267811bc2f7f64317f8de775f988ab124ad31","NetNS":"/var/run/netns/cni-94eb770a-6dc1-d6ee-291b-629cf9fe6968","IfName":"eth0","CniPath":"/opt/cni/bin","K8sPodNamespace":"kube-system","K8sPodName":"netpod1-1","K8sPodTenant":"system","CniVersion":"0.3.1","NetworkName":"mizarcni","Plugin":"mizarcni"}
I0202 05:56:58.523856    2274 mizarcni.go:73] Network variables: {"Command":"DEL","ContainerID":"6efbbb20cdf618090d98674f6ca1884d463a09d821fa64fd684d86b8442b8114","NetNS":"/var/run/netns/cni-b93845db-a4c1-5299-5608-f6a2d2dfb1fb","IfName":"eth0","CniPath":"/opt/cni/bin","K8sPodNamespace":"kube-system","K8sPodName":"netpod1-1","K8sPodTenant":"system","CniVersion":"0.3.1","NetworkName":"mizarcni","Plugin":"mizarcni"}
I0202 05:56:59.508730    2376 mizarcni.go:73] Network variables: {"Command":"DEL","ContainerID":"f41e4abd66f8cee2c66591b346d17f06e22d7f7b8a0270723ba6aee4be5b67ee","NetNS":"/var/run/netns/cni-1240f4a9-27b4-1fdc-4032-c3358ea91c26","IfName":"eth0","CniPath":"/opt/cni/bin","K8sPodNamespace":"kube-system","K8sPodName":"netpod1-1","K8sPodTenant":"system","CniVersion":"0.3.1","NetworkName":"mizarcni","Plugin":"mizarcni"}
I0202 05:57:11.270217    3484 mizarcni.go:73] Network variables: {"Command":"DEL","ContainerID":"1e5ac39a7fe795443435579ee67ccddd69e059b73407e5350b9c422ddbfd2f2e","NetNS":"/var/run/netns/cni-809adf83-0227-5c43-d46e-a0c72666ca2f","IfName":"eth0","CniPath":"/opt/cni/bin","K8sPodNamespace":"kube-system","K8sPodName":"netpod1-1","K8sPodTenant":"system","CniVersion":"0.3.1","NetworkName":"mizarcni","Plugin":"mizarcni"}
root@ip-172-31-39-83:~/go/src/k8s.io/arktos#

containerd log indicated failures from cni as well:

root@ip-172-31-39-83:~/go/src/k8s.io/arktos# journalctl -u containerd | grep netpod
Feb 02 05:52:54 ip-172-31-39-83 containerd[13485]: time="2022-02-02T05:52:54.355436640Z" level=info msg="RunPodsandbox for &PodSandboxMetadata{Name:netpod1-1,Uid:4be90ad0-11eb-4e7e-8476-6602bff1af6e,Namespace:kube-system,Attempt:0,Tenant:system,}"
Feb 02 05:52:54 ip-172-31-39-83 containerd[13485]: E0202 05:52:54.365808   23419 mizarcni.go:60] rpc error: code = Unknown desc = Exception calling application: 'netpod1-1-kube-system-system'
Feb 02 05:52:54 ip-172-31-39-83 containerd[13485]: time="2022-02-02T05:52:54.379653361Z" level=error msg="RunPodSandbox for &PodSandboxMetadata{Name:netpod1-1,Uid:4be90ad0-11eb-4e7e-8476-6602bff1af6e,Namespace:kube-system,Attempt:0,Tenant:system,} failed, error" error="failed to setup network for sandbox \"d682b478b7dfdb479de6989e68e9b2bb5d5c38221d3e3590484f9957e98e5718\": rpc error: code = Unknown desc = Exception calling application: 'netpod1-1-kube-system-system'"
Feb 02 05:53:08 ip-172-31-39-83 containerd[13485]: time="2022-02-02T05:53:08.981759366Z" level=info msg="RunPodsandbox for &PodSandboxMetadata{Name:netpod1-1,Uid:4be90ad0-11eb-4e7e-8476-6602bff1af6e,Namespace:kube-system,Attempt:0,Tenant:system,}"
Feb 02 05:53:09 ip-172-31-39-83 containerd[13485]: time="2022-02-02T05:53:09.375069715Z" level=info msg="RunPodSandbox for &PodSandboxMetadata{Name:netpod1-1,Uid:4be90ad0-11eb-4e7e-8476-6602bff1af6e,Namespace:kube-system,Attempt:0,Tenant:system,} returns sandbox id \"7c0cf7e87b18e30256c66d0caa5267811bc2f7f64317f8de775f988ab124ad31\""
Feb 02 05:56:58 ip-172-31-39-83 containerd[13485]: time="2022-02-02T05:56:58.503348152Z" level=info msg="RunPodsandbox for &PodSandboxMetadata{Name:netpod1-1,Uid:39530e1c-340a-4699-9b1d-aa97eae4d47e,Namespace:kube-system,Attempt:0,Tenant:system,}"
Feb 02 05:56:58 ip-172-31-39-83 containerd[13485]: time="2022-02-02T05:56:58.526536743Z" level=error msg="RunPodSandbox for &PodSandboxMetadata{Name:netpod1-1,Uid:39530e1c-340a-4699-9b1d-aa97eae4d47e,Namespace:kube-system,Attempt:0,Tenant:system,} failed, error" error="failed to setup network for sandbox \"6efbbb20cdf618090d98674f6ca1884d463a09d821fa64fd684d86b8442b8114\": rpc error: code = Internal desc = Failed to serialize response!"
Feb 02 05:56:59 ip-172-31-39-83 containerd[13485]: time="2022-02-02T05:56:59.486345875Z" level=info msg="RunPodsandbox for &PodSandboxMetadata{Name:netpod1-1,Uid:39530e1c-340a-4699-9b1d-aa97eae4d47e,Namespace:kube-system,Attempt:0,Tenant:system,}"
Feb 02 05:56:59 ip-172-31-39-83 containerd[13485]: time="2022-02-02T05:56:59.511461719Z" level=error msg="RunPodSandbox for &PodSandboxMetadata{Name:netpod1-1,Uid:39530e1c-340a-4699-9b1d-aa97eae4d47e,Namespace:kube-system,Attempt:0,Tenant:system,} failed, error" error="failed to setup network for sandbox \"f41e4abd66f8cee2c66591b346d17f06e22d7f7b8a0270723ba6aee4be5b67ee\": rpc error: code = Internal desc = Failed to serialize response!"
Feb 02 05:57:11 ip-172-31-39-83 containerd[13485]: time="2022-02-02T05:57:11.249816517Z" level=info msg="RunPodsandbox for &PodSandboxMetadata{Name:netpod1-1,Uid:39530e1c-340a-4699-9b1d-aa97eae4d47e,Namespace:kube-system,Attempt:0,Tenant:system,}"
Feb 02 05:57:11 ip-172-31-39-83 containerd[13485]: time="2022-02-02T05:57:11.273328304Z" level=error msg="RunPodSandbox for &PodSandboxMetadata{Name:netpod1-1,Uid:39530e1c-340a-4699-9b1d-aa97eae4d47e,Namespace:kube-system,Attempt:0,Tenant:system,} failed, error" error="failed to setup network for sandbox \"1e5ac39a7fe795443435579ee67ccddd69e059b73407e5350b9c422ddbfd2f2e\": rpc error: code = Internal desc = Failed to serialize response!"
Feb 02 05:57:23 ip-172-31-39-83 containerd[13485]: time="2022-02-02T05:57:23.249885149Z" level=info msg="RunPodsandbox for &PodSandboxMetadata{Name:netpod1-1,Uid:39530e1c-340a-4699-9b1d-aa97eae4d47e,Namespace:kube-system,Attempt:0,Tenant:system,}"
Feb 02 05:57:23 ip-172-31-39-83 containerd[13485]: time="2022-02-02T05:57:23.603824053Z" level=info msg="RunPodSandbox for &PodSandboxMetadata{Name:netpod1-1,Uid:39530e1c-340a-4699-9b1d-aa97eae4d47e,Namespace:kube-system,Attempt:0,Tenant:system,} returns sandbox id \"189eddbc1b39912270ac471393b630b29003405463787e6df23d781ea87e6990\""
root@ip-172-31-39-83:~/go/src/k8s.io/arktos# date
Wed Feb  2 06:14:36 UTC 2022
root@ip-172-31-39-83:~/go/src/k8s.io/arktos#

What you expected to happen:

How to reproduce it (as minimally and precisely as possible):

create this test pod with Mizar:

apiVersion: v1
kind: Pod
metadata:
  name: netpod1-1
  namespace: kube-system
  tenant: system
  labels:
    app: netpod
spec:
  restartPolicy: OnFailure
  terminationGracePeriodSeconds: 10
  containers:
  - name: netctr
    image: mizarnet/testpod
    ports:
    - containerPort: 9001
      protocol: TCP
    - containerPort: 5001
      protocol: UDP
    - containerPort: 7000
      protocol: TCP

Anything else we need to know?:

Environment:

vinaykul commented 2 years ago

@yb01 CNI is allowed to return error if it is unable to successfully complete the ADD. I don't think this is an issue but I'll take a closer look.

vinaykul commented 2 years ago

We don't see DEL being called in upstream code. Typically one or two ADDs that fail because interface is not yet produced by operator. This seems arktos-specific issue.

root@kind-worker2:/var/log# more mizarcni.log 
Log file created at: 2022/02/05 21:06:17
Running on machine: kind-worker2
Binary: Built with gc go1.13.9 for linux/amd64
Log line format: [IWEF]mmdd hh:mm:ss.uuuuuu threadid file:line] msg
I0205 21:06:17.211563    1390 mizarcni.go:42] CNI_INIT: >>>>
I0205 21:06:17.211661    1390 mizarcni.go:51] CNI_INIT: <<<<
I0205 21:06:17.214265    1390 mizarcni.go:56] CNI_ADD: >>>> args: '&{ContainerID:0845264e36471081113c90dd5e0e1de9d7adbc8b1b72657fdde2f6e970c5bf2c Netns:/var/run/netns/
cni-34cee939-cb24-1a72-1e69-8153e3fc7478 IfName:eth0 Args:IgnoreUnknown=1;K8S_POD_NAMESPACE=default;K8S_POD_NAME=netpod2;K8S_POD_INFRA_CONTAINER_ID=0845264e36471081113
c90dd5e0e1de9d7adbc8b1b72657fdde2f6e970c5bf2c Path:/opt/cni/bin StdinData:[123 34 99 110 105 86 101 114 115 105 111 110 34 58 34 48 46 51 46 49 34 44 34 110 97 109 101
 34 58 34 109 105 122 97 114 99 110 105 34 44 34 116 121 112 101 34 58 34 109 105 122 97 114 99 110 105 34 125]}'
I0205 21:06:17.226072    1390 mizarcni.go:60] CNI_ADD: Tracelog: 'CNI_ADD: Args: '{"Command":"ADD","ContainerID":"0845264e36471081113c90dd5e0e1de9d7adbc8b1b72657fdde2f
6e970c5bf2c","NetNS":"/var/run/netns/cni-34cee939-cb24-1a72-1e69-8153e3fc7478","IfName":"eth0","CniPath":"/opt/cni/bin","K8sPodNamespace":"default","K8sPodName":"netpo
d2","K8sPodTenant":"","CniVersion":"0.3.1","NetworkName":"mizarcni","Plugin":"mizarcni"}'
'
E0205 21:06:17.226086    1390 mizarcni.go:63] CNI_ADD: Error: 'rpc error: code = Unknown desc = Exception calling application: ConsumeInterfaces: Interface not found f
or pod 'netpod2-default-''
I0205 21:06:17.226759    1390 mizarcni.go:68] CNI_ADD: <<<<
--------------------------------
Log file created at: 2022/02/05 21:06:17
Running on machine: kind-worker2
Binary: Built with gc go1.13.9 for linux/amd64
Log line format: [IWEF]mmdd hh:mm:ss.uuuuuu threadid file:line] msg
I0205 21:06:17.747829    1404 mizarcni.go:42] CNI_INIT: >>>>
I0205 21:06:17.747900    1404 mizarcni.go:51] CNI_INIT: <<<<
I0205 21:06:17.749953    1404 mizarcni.go:56] CNI_ADD: >>>> args: '&{ContainerID:395f74ace4f9cbe285a75768b209968e48df23b624d25220ad8df38a41a07545 Netns:/var/run/netns/
cni-f24e8a5a-2610-12b3-25f1-cdd15e5b3f37 IfName:eth0 Args:IgnoreUnknown=1;K8S_POD_NAMESPACE=default;K8S_POD_NAME=netpod2;K8S_POD_INFRA_CONTAINER_ID=395f74ace4f9cbe285a
75768b209968e48df23b624d25220ad8df38a41a07545 Path:/opt/cni/bin StdinData:[123 34 99 110 105 86 101 114 115 105 111 110 34 58 34 48 46 51 46 49 34 44 34 110 97 109 101
 34 58 34 109 105 122 97 114 99 110 105 34 44 34 116 121 112 101 34 58 34 109 105 122 97 114 99 110 105 34 125]}'
I0205 21:06:18.109880    1404 mizarcni.go:60] CNI_ADD: Tracelog: 'CNI_ADD: Args: '{"Command":"ADD","ContainerID":"395f74ace4f9cbe285a75768b209968e48df23b624d25220ad8df
38a41a07545","NetNS":"/var/run/netns/cni-f24e8a5a-2610-12b3-25f1-cdd15e5b3f37","IfName":"eth0","CniPath":"/opt/cni/bin","K8sPodNamespace":"default","K8sPodName":"netpo
d2","K8sPodTenant":"","CniVersion":"0.3.1","NetworkName":"mizarcni","Plugin":"mizarcni"}'
CNI_ADD: Activating interface: 'interface_id:{pod_id:{k8s_pod_name:"netpod2" k8s_namespace:"default"} interface:"eth0"} veth:{name:"eth-ceff5236" peer:"veth-ceff5236"}
 address:{version:"4" ip_address:"20.0.0.5" ip_prefix:"8" gateway_ip:"20.0.0.1" mac:"22:b5:36:e9:a5:3a" tunnel_id:"1"} droplet:{version:"4" ip_address:"172.18.0.3" mac
:"02:42:ac:12:00:03"} bouncers:{version:"4" ip_address:"172.18.0.2" mac:"02:42:ac:12:00:02"} status:consumed pod_label_value:"0" namespace_label_value:"0" egress_bandw
idth_bytes_per_sec:"0" pod_network_priority:"High" pod_network_class:"Premium"'
CNI_ADD: Activate interface result: '[Move interface 'eth-ceff5236/5' to netns 'cni-f24e8a5a-2610-12b3-25f1-cdd15e5b3f37'] + [Rename interface 'eth-ceff5236' to 'eth0'
] + [Retrieve loopback interface] + [Set loopback interface UP] + [Set interface 'eth0' UP] + [Set ip addr '20.0.0.5' on interface 'eth0'] + [Set gateway '20.0.0.1' fo
r interface 'eth0'] + [Disable tso on interface 'eth0'] + [Cmd: '/usr/sbin/ip netns exec cni-f24e8a5a-2610-12b3-25f1-cdd15e5b3f37 ethtool -K eth0 tso off gso off ufo o
ff -> Result: 'Cannot change udp-fragmentation-offload
'] + [Cmd: '/usr/sbin/ip netns exec cni-f24e8a5a-2610-12b3-25f1-cdd15e5b3f37 ethtool --offload eth0 rx off tx off' -> Result: '']'
'
I0205 21:06:18.109898    1404 mizarcni.go:65] CNI_ADD: Success - interface added for pod 'default/netpod2'
I0205 21:06:18.109901    1404 mizarcni.go:68] CNI_ADD: <<<<
--------------------------------
Log file created at: 2022/02/05 23:43:21
Running on machine: kind-worker2
Binary: Built with gc go1.13.9 for linux/amd64
Log line format: [IWEF]mmdd hh:mm:ss.uuuuuu threadid file:line] msg
I0205 23:43:21.097505    7682 mizarcni.go:42] CNI_INIT: >>>>
I0205 23:43:21.097567    7682 mizarcni.go:51] CNI_INIT: <<<<
I0205 23:43:21.117342    7682 mizarcni.go:56] CNI_ADD: >>>> args: '&{ContainerID:af9451c02ed4050ec49d36b98375d4567eb39d0a4fa89ab3c2511e16579c327f Netns:/var/run/netns/cni-363f5eb5-fc96-30d8-aefe-83e621808cd4 IfName:eth0 Args:IgnoreUnknown=1;K8S_POD_NAMESPACE=kube-system;K8S_POD_NAME=arknetpod;K8S_POD_INFRA_CONTAINER_ID=af9451c02ed4050ec49d36b98375d4567eb39d0a4fa89ab3c2511e16579c327f Path:/opt/cni/bin StdinData:[123 34 99 110 105 86 101 114 115 105 111 110 34 58 34 48 46 51 46 49 34 44 34 110 97 109 101 34 58 34 109 105 122 97 114 99 110 105 34 44 34 116 121 112 101 34 58 34 109 105 122 97 114 99 110 105 34 125]}'
I0205 23:43:21.121540    7682 mizarcni.go:60] CNI_ADD: Tracelog: 'CNI_ADD: Args: '{"Command":"ADD","ContainerID":"af9451c02ed4050ec49d36b98375d4567eb39d0a4fa89ab3c2511e16579c327f","NetNS":"/var/run/netns/cni-363f5eb5-fc96-30d8-aefe-83e621808cd4","IfName":"eth0","CniPath":"/opt/cni/bin","K8sPodNamespace":"kube-system","K8sPodName":"arknetpod","K8sPodTenant":"","CniVersion":"0.3.1","NetworkName":"mizarcni","Plugin":"mizarcni"}'
'
E0205 23:43:21.121568    7682 mizarcni.go:63] CNI_ADD: Error: 'rpc error: code = Unknown desc = Exception calling application: ConsumeInterfaces: Interface not found for pod 'arknetpod-kube-system-''
I0205 23:43:21.122251    7682 mizarcni.go:68] CNI_ADD: <<<<
--------------------------------
Log file created at: 2022/02/05 23:43:21
Running on machine: kind-worker2
Binary: Built with gc go1.13.9 for linux/amd64
Log line format: [IWEF]mmdd hh:mm:ss.uuuuuu threadid file:line] msg
I0205 23:43:21.232652    7698 mizarcni.go:42] CNI_INIT: >>>>
I0205 23:43:21.232723    7698 mizarcni.go:51] CNI_INIT: <<<<
I0205 23:43:21.234978    7698 mizarcni.go:56] CNI_ADD: >>>> args: '&{ContainerID:89d5595055e40bfd5d82614e86c54f747206b04a600ad8f6ed9f5b3290119b14 Netns:/var/run/netns/cni-d0dd3c4e-acb0-b34b-fd2a-2f0a1806317f IfName:eth0 Args:K8S_POD_NAMESPACE=kube-system;K8S_POD_NAME=arknetpod;K8S_POD_INFRA_CONTAINER_ID=89d5595055e40bfd5d82614e86c54f747206b04a600ad8f6ed9f5b3290119b14;IgnoreUnknown=1 Path:/opt/cni/bin StdinData:[123 34 99 110 105 86 101 114 115 105 111 110 34 58 34 48 46 51 46 49 34 44 34 110 97 109 101 34 58 34 109 105 122 97 114 99 110 105 34 44 34 116 121 112 101 34 58 34 109 105 122 97 114 99 110 105 34 125]}'
I0205 23:43:21.239317    7698 mizarcni.go:60] CNI_ADD: Tracelog: 'CNI_ADD: Args: '{"Command":"ADD","ContainerID":"89d5595055e40bfd5d82614e86c54f747206b04a600ad8f6ed9f5b3290119b14","NetNS":"/var/run/netns/cni-d0dd3c4e-acb0-b34b-fd2a-2f0a1806317f","IfName":"eth0","CniPath":"/opt/cni/bin","K8sPodNamespace":"kube-system","K8sPodName":"arknetpod","K8sPodTenant":"","CniVersion":"0.3.1","NetworkName":"mizarcni","Plugin":"mizarcni"}'
'
E0205 23:43:21.239331    7698 mizarcni.go:63] CNI_ADD: Error: 'rpc error: code = Unknown desc = Exception calling application: ConsumeInterfaces: Interface not found for pod 'arknetpod-kube-system-''
I0205 23:43:21.239448    7698 mizarcni.go:68] CNI_ADD: <<<<
--------------------------------
Log file created at: 2022/02/05 23:43:34
Running on machine: kind-worker2
Binary: Built with gc go1.13.9 for linux/amd64
Log line format: [IWEF]mmdd hh:mm:ss.uuuuuu threadid file:line] msg
I0205 23:43:34.133091    7722 mizarcni.go:42] CNI_INIT: >>>>
I0205 23:43:34.133168    7722 mizarcni.go:51] CNI_INIT: <<<<
I0205 23:43:34.134932    7722 mizarcni.go:56] CNI_ADD: >>>> args: '&{ContainerID:47920652ebcfcf93b908a8b32425fb671d1761819cf5cabab421f3e1d08becf7 Netns:/var/run/netns/cni-e0b00fbf-12db-05c0-cb7f-c520c6391c8c IfName:eth0 Args:IgnoreUnknown=1;K8S_POD_NAMESPACE=kube-system;K8S_POD_NAME=arknetpod;K8S_POD_INFRA_CONTAINER_ID=47920652ebcfcf93b908a8b32425fb671d1761819cf5cabab421f3e1d08becf7 Path:/opt/cni/bin StdinData:[123 34 99 110 105 86 101 114 115 105 111 110 34 58 34 48 46 51 46 49 34 44 34 110 97 109 101 34 58 34 109 105 122 97 114 99 110 105 34 44 34 116 121 112 101 34 58 34 109 105 122 97 114 99 110 105 34 125]}'
I0205 23:43:34.442631    7722 mizarcni.go:60] CNI_ADD: Tracelog: 'CNI_ADD: Args: '{"Command":"ADD","ContainerID":"47920652ebcfcf93b908a8b32425fb671d1761819cf5cabab421f3e1d08becf7","NetNS":"/var/run/netns/cni-e0b00fbf-12db-05c0-cb7f-c520c6391c8c","IfName":"eth0","CniPath":"/opt/cni/bin","K8sPodNamespace":"kube-system","K8sPodName":"arknetpod","K8sPodTenant":"","CniVersion":"0.3.1","NetworkName":"mizarcni","Plugin":"mizarcni"}'
CNI_ADD: Activating interface: 'interface_id:{pod_id:{k8s_pod_name:"arknetpod" k8s_namespace:"kube-system"} interface:"eth0"} veth:{name:"eth-bcdb2c6d" peer:"veth-bcdb2c6d"} address:{version:"4" ip_address:"20.0.0.7" ip_prefix:"8" gateway_ip:"20.0.0.1" mac:"aa:99:74:b5:68:aa" tunnel_id:"1"} droplet:{version:"4" ip_address:"172.18.0.3" mac:"02:42:ac:12:00:03"} bouncers:{version:"4" ip_address:"172.18.0.2" mac:"02:42:ac:12:00:02"} status:consumed pod_label_value:"11" namespace_label_value:"0" egress_bandwidth_bytes_per_sec:"0" pod_network_priority:"High" pod_network_class:"Premium"'
CNI_ADD: Activate interface result: '[Move interface 'eth-bcdb2c6d/7' to netns 'cni-e0b00fbf-12db-05c0-cb7f-c520c6391c8c'] + [Rename interface 'eth-bcdb2c6d' to 'eth0'] + [Retrieve loopback interface] + [Set loopback interface UP] + [Set interface 'eth0' UP] + [Set ip addr '20.0.0.7' on interface 'eth0'] + [Set gateway '20.0.0.1' for interface 'eth0'] + [Disable tso on interface 'eth0'] + [Cmd: '/usr/sbin/ip netns exec cni-e0b00fbf-12db-05c0-cb7f-c520c6391c8c ethtool -K eth0 tso off gso off ufo off -> Result: 'Cannot change udp-fragmentation-offload
'] + [Cmd: '/usr/sbin/ip netns exec cni-e0b00fbf-12db-05c0-cb7f-c520c6391c8c ethtool --offload eth0 rx off tx off' -> Result: '']'
'
I0205 23:43:34.442647    7722 mizarcni.go:65] CNI_ADD: Success - interface added for pod 'kube-system/arknetpod'
I0205 23:43:34.442655    7722 mizarcni.go:68] CNI_ADD: <<<<
--------------------------------
root@kind-worker2:/var/log# 
root@kind-worker2:/var/log#
vinaykul commented 2 years ago

This is normal behavior for containerd. If ADD fails, it calls DEL and then calls ADD. I'll check our code to ensure that interface rolls back exactly what the add did and nothing more and see if there is a race between interface producer & consumer code that we need to be concerned about.

root@ip-192-168-1-144:~/vmizar# cat /var/log/mizarcni.log 
Log file created at: 2022/02/09 02:18:07
Running on machine: ip-192-168-1-144
Binary: Built with gc go1.13.9 for linux/amd64
Log line format: [IWEF]mmdd hh:mm:ss.uuuuuu threadid file:line] msg
I0209 02:18:07.410321    9598 mizarcni.go:42] CNI_INIT: >>>>
I0209 02:18:07.410458    9598 mizarcni.go:51] CNI_INIT: <<<<
I0209 02:18:07.413040    9598 mizarcni.go:56] CNI_ADD: >>>> args: '&{ContainerID:09f218ef5c10cc3f35e24dbce4bafb5285a9a3f2dd826500f2fef88797e81147 Netns:/var/run/netns/cni-fc5f1f3e-e99a-57e3-d535-f415bd7b5c12 IfName:eth0 Args:K8S_POD_NAMESPACE=kube-system;K8S_POD_NAME=netpod1;K8S_POD_INFRA_CONTAINER_ID=09f218ef5c10cc3f35e24dbce4bafb5285a9a3f2dd826500f2fef88797e81147;K8S_POD_UID=dbc25c6f-bd39-44e2-8ec4-bc3264f6730b;IgnoreUnknown=1 Path:/opt/cni/bin StdinData:[123 34 99 110 105 86 101 114 115 105 111 110 34 58 34 48 46 51 46 49 34 44 34 110 97 109 101 34 58 34 109 105 122 97 114 99 110 105 34 44 34 116 121 112 101 34 58 34 109 105 122 97 114 99 110 105 34 125]}'
I0209 02:18:07.417180    9598 mizarcni.go:60] CNI_ADD: Tracelog: 'CNI_ADD: Args: '{"Command":"ADD","ContainerID":"09f218ef5c10cc3f35e24dbce4bafb5285a9a3f2dd826500f2fef88797e81147","NetNS":"/var/run/netns/cni-fc5f1f3e-e99a-57e3-d535-f415bd7b5c12","IfName":"eth0","CniPath":"/opt/cni/bin","K8sPodNamespace":"kube-system","K8sPodName":"netpod1","K8sPodTenant":"","CniVersion":"0.3.1","NetworkName":"mizarcni","Plugin":"mizarcni"}'
'
E0209 02:18:07.417184    9598 mizarcni.go:63] CNI_ADD: Error: 'rpc error: code = Unknown desc = Exception calling application: ConsumeInterfaces: Interface not found for pod 'netpod1-kube-system-''
I0209 02:18:07.417438    9598 mizarcni.go:68] CNI_ADD: <<<<
--------------------------------
Log file created at: 2022/02/09 02:18:07
Running on machine: ip-192-168-1-144
Binary: Built with gc go1.13.9 for linux/amd64
Log line format: [IWEF]mmdd hh:mm:ss.uuuuuu threadid file:line] msg
I0209 02:18:07.427637    9614 mizarcni.go:42] CNI_INIT: >>>>
I0209 02:18:07.427718    9614 mizarcni.go:51] CNI_INIT: <<<<
I0209 02:18:07.429704    9614 mizarcni.go:75] CNI_DEL: >>>> args: '&{ContainerID:09f218ef5c10cc3f35e24dbce4bafb5285a9a3f2dd826500f2fef88797e81147 Netns:/var/run/netns/cni-fc5f1f3e-e99a-57e3-d535-f415bd7b5c12 IfName:eth0 Args:K8S_POD_NAME=netpod1;K8S_POD_INFRA_CONTAINER_ID=09f218ef5c10cc3f35e24dbce4bafb5285a9a3f2dd826500f2fef88797e81147;K8S_POD_UID=dbc25c6f-bd39-44e2-8ec4-bc3264f6730b;IgnoreUnknown=1;K8S_POD_NAMESPACE=kube-system Path:/opt/cni/bin StdinData:[123 34 99 110 105 86 101 114 115 105 111 110 34 58 34 48 46 51 46 49 34 44 34 110 97 109 101 34 58 34 109 105 122 97 114 99 110 105 34 44 34 116 121 112 101 34 58 34 109 105 122 97 114 99 110 105 34 125]}'
I0209 02:18:07.433746    9614 mizarcni.go:79] CNI_DEL: Tracelog: 'CNI_DEL: Deleting NetNS: '/var/run/netns/cni-fc5f1f3e-e99a-57e3-d535-f415bd7b5c12'
'
I0209 02:18:07.433756    9614 mizarcni.go:84] CNI_DEL: Success - interface deleted for pod 'kube-system/netpod1'
I0209 02:18:07.433758    9614 mizarcni.go:87] CNI_DEL: <<<<
--------------------------------
Log file created at: 2022/02/09 02:18:07
Running on machine: ip-192-168-1-144
Binary: Built with gc go1.13.9 for linux/amd64
Log line format: [IWEF]mmdd hh:mm:ss.uuuuuu threadid file:line] msg
I0209 02:18:07.475187    9627 mizarcni.go:42] CNI_INIT: >>>>
I0209 02:18:07.475298    9627 mizarcni.go:51] CNI_INIT: <<<<
I0209 02:18:07.477355    9627 mizarcni.go:56] CNI_ADD: >>>> args: '&{ContainerID:61c28b794111eba54192d1c0a29b44bd47afaa23434615f24b04f6fe2544165e Netns:/var/run/netns/cni-776bb0fb-16c8-b34d-7604-b9f138592d7c IfName:eth0 Args:K8S_POD_UID=dbc25c6f-bd39-44e2-8ec4-bc3264f6730b;IgnoreUnknown=1;K8S_POD_NAMESPACE=kube-system;K8S_POD_NAME=netpod1;K8S_POD_INFRA_CONTAINER_ID=61c28b794111eba54192d1c0a29b44bd47afaa23434615f24b04f6fe2544165e Path:/opt/cni/bin StdinData:[123 34 99 110 105 86 101 114 115 105 111 110 34 58 34 48 46 51 46 49 34 44 34 110 97 109 101 34 58 34 109 105 122 97 114 99 110 105 34 44 34 116 121 112 101 34 58 34 109 105 122 97 114 99 110 105 34 125]}'
I0209 02:18:07.480216    9627 mizarcni.go:60] CNI_ADD: Tracelog: 'CNI_ADD: Args: '{"Command":"ADD","ContainerID":"61c28b794111eba54192d1c0a29b44bd47afaa23434615f24b04f6fe2544165e","NetNS":"/var/run/netns/cni-776bb0fb-16c8-b34d-7604-b9f138592d7c","IfName":"eth0","CniPath":"/opt/cni/bin","K8sPodNamespace":"kube-system","K8sPodName":"netpod1","K8sPodTenant":"","CniVersion":"0.3.1","NetworkName":"mizarcni","Plugin":"mizarcni"}'
'
E0209 02:18:07.480224    9627 mizarcni.go:63] CNI_ADD: Error: 'rpc error: code = Unknown desc = Exception calling application: ConsumeInterfaces: Interface not found for pod 'netpod1-kube-system-''
I0209 02:18:07.480340    9627 mizarcni.go:68] CNI_ADD: <<<<
--------------------------------
Log file created at: 2022/02/09 02:18:07
Running on machine: ip-192-168-1-144
Binary: Built with gc go1.13.9 for linux/amd64
Log line format: [IWEF]mmdd hh:mm:ss.uuuuuu threadid file:line] msg
I0209 02:18:07.488788    9642 mizarcni.go:42] CNI_INIT: >>>>
I0209 02:18:07.488865    9642 mizarcni.go:51] CNI_INIT: <<<<
I0209 02:18:07.490967    9642 mizarcni.go:75] CNI_DEL: >>>> args: '&{ContainerID:61c28b794111eba54192d1c0a29b44bd47afaa23434615f24b04f6fe2544165e Netns:/var/run/netns/cni-776bb0fb-16c8-b34d-7604-b9f138592d7c IfName:eth0 Args:K8S_POD_NAME=netpod1;K8S_POD_INFRA_CONTAINER_ID=61c28b794111eba54192d1c0a29b44bd47afaa23434615f24b04f6fe2544165e;K8S_POD_UID=dbc25c6f-bd39-44e2-8ec4-bc3264f6730b;IgnoreUnknown=1;K8S_POD_NAMESPACE=kube-system Path:/opt/cni/bin StdinData:[123 34 99 110 105 86 101 114 115 105 111 110 34 58 34 48 46 51 46 49 34 44 34 110 97 109 101 34 58 34 109 105 122 97 114 99 110 105 34 44 34 116 121 112 101 34 58 34 109 105 122 97 114 99 110 105 34 125]}'
I0209 02:18:07.492388    9642 mizarcni.go:79] CNI_DEL: Tracelog: 'CNI_DEL: Deleting NetNS: '/var/run/netns/cni-776bb0fb-16c8-b34d-7604-b9f138592d7c'
'
I0209 02:18:07.492401    9642 mizarcni.go:84] CNI_DEL: Success - interface deleted for pod 'kube-system/netpod1'
I0209 02:18:07.492405    9642 mizarcni.go:87] CNI_DEL: <<<<
--------------------------------
Log file created at: 2022/02/09 02:18:22
Running on machine: ip-192-168-1-144
Binary: Built with gc go1.13.9 for linux/amd64
Log line format: [IWEF]mmdd hh:mm:ss.uuuuuu threadid file:line] msg
I0209 02:18:22.683447    9789 mizarcni.go:42] CNI_INIT: >>>>
I0209 02:18:22.683524    9789 mizarcni.go:51] CNI_INIT: <<<<
I0209 02:18:22.685554    9789 mizarcni.go:56] CNI_ADD: >>>> args: '&{ContainerID:991cde077bc21760e945a211e9e9576d4cce0e8ae85506f95112c67d44a7535a Netns:/var/run/netns/cni-c9d3cfed-21d2-a534-450d-3da1890afa86 IfName:eth0 Args:IgnoreUnknown=1;K8S_POD_NAMESPACE=kube-system;K8S_POD_NAME=netpod1;K8S_POD_INFRA_CONTAINER_ID=991cde077bc21760e945a211e9e9576d4cce0e8ae85506f95112c67d44a7535a;K8S_POD_UID=dbc25c6f-bd39-44e2-8ec4-bc3264f6730b Path:/opt/cni/bin StdinData:[123 34 99 110 105 86 101 114 115 105 111 110 34 58 34 48 46 51 46 49 34 44 34 110 97 109 101 34 58 34 109 105 122 97 114 99 110 105 34 44 34 116 121 112 101 34 58 34 109 105 122 97 114 99 110 105 34 125]}'
I0209 02:18:23.007161    9789 mizarcni.go:60] CNI_ADD: Tracelog: 'CNI_ADD: Args: '{"Command":"ADD","ContainerID":"991cde077bc21760e945a211e9e9576d4cce0e8ae85506f95112c67d44a7535a","NetNS":"/var/run/netns/cni-c9d3cfed-21d2-a534-450d-3da1890afa86","IfName":"eth0","CniPath":"/opt/cni/bin","K8sPodNamespace":"kube-system","K8sPodName":"netpod1","K8sPodTenant":"","CniVersion":"0.3.1","NetworkName":"mizarcni","Plugin":"mizarcni"}'
CNI_ADD: Activating interface: 'interface_id:{pod_id:{k8s_pod_name:"netpod1"  k8s_namespace:"kube-system"}  interface:"eth0"}  veth:{name:"eth-fd355ad4"  peer:"veth-fd355ad4"}  address:{version:"4"  ip_address:"20.0.0.4"  ip_prefix:"8"  gateway_ip:"20.0.0.1"  mac:"9e:ca:03:e4:9e:f6"  tunnel_id:"1"}  droplet:{version:"4"  ip_address:"192.168.1.144"  mac:"02:4a:a1:fb:ce:f1"}  bouncers:{version:"4"  ip_address:"192.168.1.144"  mac:"02:4a:a1:fb:ce:f1"}  status:consumed  pod_label_value:"0"  namespace_label_value:"1"  egress_bandwidth_bytes_per_sec:"0"  pod_network_priority:"High"  pod_network_class:"Premium"'
CNI_ADD: Activate interface result: '[Move interface 'eth-fd355ad4/7' to netns 'cni-c9d3cfed-21d2-a534-450d-3da1890afa86'] + [Rename interface 'eth-fd355ad4' to 'eth0'] + [Retrieve loopback interface] + [Set loopback interface UP] + [Set interface 'eth0' UP] + [Set ip addr '20.0.0.4' on interface 'eth0'] + [Set gateway '20.0.0.1' for interface 'eth0'] + [Disable tso on interface 'eth0'] + [Cmd: '/sbin/ip netns exec cni-c9d3cfed-21d2-a534-450d-3da1890afa86 ethtool -K eth0 tso off gso off ufo off -> Result: 'Cannot change udp-fragmentation-offload
'] + [Cmd: '/sbin/ip netns exec cni-c9d3cfed-21d2-a534-450d-3da1890afa86 ethtool --offload eth0 rx off tx off' -> Result: '']'
'
I0209 02:18:23.007230    9789 mizarcni.go:65] CNI_ADD: Success - interface added for pod 'kube-system/netpod1'
I0209 02:18:23.007242    9789 mizarcni.go:68] CNI_ADD: <<<<
--------------------------------
Log file created at: 2022/02/09 02:22:06
Running on machine: ip-192-168-1-144
Binary: Built with gc go1.13.9 for linux/amd64
Log line format: [IWEF]mmdd hh:mm:ss.uuuuuu threadid file:line] msg
I0209 02:22:06.405454   11196 mizarcni.go:42] CNI_INIT: >>>>
I0209 02:22:06.405535   11196 mizarcni.go:51] CNI_INIT: <<<<
I0209 02:22:06.408034   11196 mizarcni.go:75] CNI_DEL: >>>> args: '&{ContainerID:991cde077bc21760e945a211e9e9576d4cce0e8ae85506f95112c67d44a7535a Netns:/var/run/netns/cni-c9d3cfed-21d2-a534-450d-3da1890afa86 IfName:eth0 Args:K8S_POD_UID=dbc25c6f-bd39-44e2-8ec4-bc3264f6730b;IgnoreUnknown=1;K8S_POD_NAMESPACE=kube-system;K8S_POD_NAME=netpod1;K8S_POD_INFRA_CONTAINER_ID=991cde077bc21760e945a211e9e9576d4cce0e8ae85506f95112c67d44a7535a Path:/opt/cni/bin StdinData:[123 34 99 110 105 86 101 114 115 105 111 110 34 58 34 48 46 51 46 49 34 44 34 110 97 109 101 34 58 34 109 105 122 97 114 99 110 105 34 44 34 116 121 112 101 34 58 34 109 105 122 97 114 99 110 105 34 125]}'
I0209 02:22:06.409215   11196 mizarcni.go:79] CNI_DEL: Tracelog: 'CNI_DEL: Deleting NetNS: '/var/run/netns/cni-c9d3cfed-21d2-a534-450d-3da1890afa86'
'
I0209 02:22:06.409224   11196 mizarcni.go:84] CNI_DEL: Success - interface deleted for pod 'kube-system/netpod1'
I0209 02:22:06.409227   11196 mizarcni.go:87] CNI_DEL: <<<<
--------------------------------
Log file created at: 2022/02/09 02:22:06
Running on machine: ip-192-168-1-144
Binary: Built with gc go1.13.9 for linux/amd64
Log line format: [IWEF]mmdd hh:mm:ss.uuuuuu threadid file:line] msg
I0209 02:22:06.888222   11223 mizarcni.go:42] CNI_INIT: >>>>
I0209 02:22:06.888319   11223 mizarcni.go:51] CNI_INIT: <<<<
I0209 02:22:06.891264   11223 mizarcni.go:75] CNI_DEL: >>>> args: '&{ContainerID:991cde077bc21760e945a211e9e9576d4cce0e8ae85506f95112c67d44a7535a Netns: IfName:eth0 Args:IgnoreUnknown=1;K8S_POD_NAMESPACE=kube-system;K8S_POD_NAME=netpod1;K8S_POD_INFRA_CONTAINER_ID=991cde077bc21760e945a211e9e9576d4cce0e8ae85506f95112c67d44a7535a;K8S_POD_UID=dbc25c6f-bd39-44e2-8ec4-bc3264f6730b Path:/opt/cni/bin StdinData:[123 34 99 110 105 86 101 114 115 105 111 110 34 58 34 48 46 51 46 49 34 44 34 110 97 109 101 34 58 34 109 105 122 97 114 99 110 105 34 44 34 116 121 112 101 34 58 34 109 105 122 97 114 99 110 105 34 125]}'
I0209 02:22:06.892605   11223 mizarcni.go:79] CNI_DEL: Tracelog: 'CNI_DEL: Deleting NetNS: '/var/run/netns'
'
I0209 02:22:06.892613   11223 mizarcni.go:84] CNI_DEL: Success - interface deleted for pod 'kube-system/netpod1'
I0209 02:22:06.892616   11223 mizarcni.go:87] CNI_DEL: <<<<
--------------------------------
Log file created at: 2022/02/09 02:22:07
Running on machine: ip-192-168-1-144
Binary: Built with gc go1.13.9 for linux/amd64
Log line format: [IWEF]mmdd hh:mm:ss.uuuuuu threadid file:line] msg
I0209 02:22:07.684082   11237 mizarcni.go:42] CNI_INIT: >>>>
I0209 02:22:07.684177   11237 mizarcni.go:51] CNI_INIT: <<<<
I0209 02:22:07.686201   11237 mizarcni.go:75] CNI_DEL: >>>> args: '&{ContainerID:991cde077bc21760e945a211e9e9576d4cce0e8ae85506f95112c67d44a7535a Netns: IfName:eth0 Args:K8S_POD_NAMESPACE=kube-system;K8S_POD_NAME=netpod1;K8S_POD_INFRA_CONTAINER_ID=991cde077bc21760e945a211e9e9576d4cce0e8ae85506f95112c67d44a7535a;K8S_POD_UID=dbc25c6f-bd39-44e2-8ec4-bc3264f6730b;IgnoreUnknown=1 Path:/opt/cni/bin StdinData:[123 34 99 110 105 86 101 114 115 105 111 110 34 58 34 48 46 51 46 49 34 44 34 110 97 109 101 34 58 34 109 105 122 97 114 99 110 105 34 44 34 116 121 112 101 34 58 34 109 105 122 97 114 99 110 105 34 125]}'
I0209 02:22:07.687485   11237 mizarcni.go:79] CNI_DEL: Tracelog: 'CNI_DEL: Deleting NetNS: '/var/run/netns'
'
I0209 02:22:07.687492   11237 mizarcni.go:84] CNI_DEL: Success - interface deleted for pod 'kube-system/netpod1'
I0209 02:22:07.687495   11237 mizarcni.go:87] CNI_DEL: <<<<
--------------------------------
Log file created at: 2022/02/09 02:22:07
Running on machine: ip-192-168-1-144
Binary: Built with gc go1.13.9 for linux/amd64
Log line format: [IWEF]mmdd hh:mm:ss.uuuuuu threadid file:line] msg
I0209 02:22:07.888849   11249 mizarcni.go:42] CNI_INIT: >>>>
I0209 02:22:07.888951   11249 mizarcni.go:51] CNI_INIT: <<<<
I0209 02:22:07.891108   11249 mizarcni.go:75] CNI_DEL: >>>> args: '&{ContainerID:991cde077bc21760e945a211e9e9576d4cce0e8ae85506f95112c67d44a7535a Netns: IfName:eth0 Args:K8S_POD_UID=dbc25c6f-bd39-44e2-8ec4-bc3264f6730b;IgnoreUnknown=1;K8S_POD_NAMESPACE=kube-system;K8S_POD_NAME=netpod1;K8S_POD_INFRA_CONTAINER_ID=991cde077bc21760e945a211e9e9576d4cce0e8ae85506f95112c67d44a7535a Path:/opt/cni/bin StdinData:[123 34 99 110 105 86 101 114 115 105 111 110 34 58 34 48 46 51 46 49 34 44 34 110 97 109 101 34 58 34 109 105 122 97 114 99 110 105 34 44 34 116 121 112 101 34 58 34 109 105 122 97 114 99 110 105 34 125]}'
I0209 02:22:07.892374   11249 mizarcni.go:79] CNI_DEL: Tracelog: 'CNI_DEL: Deleting NetNS: '/var/run/netns'
'
I0209 02:22:07.892388   11249 mizarcni.go:84] CNI_DEL: Success - interface deleted for pod 'kube-system/netpod1'
I0209 02:22:07.892392   11249 mizarcni.go:87] CNI_DEL: <<<<
--------------------------------
Log file created at: 2022/02/09 02:22:17
Running on machine: ip-192-168-1-144
Binary: Built with gc go1.13.9 for linux/amd64
Log line format: [IWEF]mmdd hh:mm:ss.uuuuuu threadid file:line] msg
I0209 02:22:17.293622   11291 mizarcni.go:42] CNI_INIT: >>>>
I0209 02:22:17.293734   11291 mizarcni.go:51] CNI_INIT: <<<<
I0209 02:22:17.296205   11291 mizarcni.go:75] CNI_DEL: >>>> args: '&{ContainerID:991cde077bc21760e945a211e9e9576d4cce0e8ae85506f95112c67d44a7535a Netns: IfName:eth0 Args:IgnoreUnknown=1;K8S_POD_NAMESPACE=kube-system;K8S_POD_NAME=netpod1;K8S_POD_INFRA_CONTAINER_ID=991cde077bc21760e945a211e9e9576d4cce0e8ae85506f95112c67d44a7535a;K8S_POD_UID=dbc25c6f-bd39-44e2-8ec4-bc3264f6730b Path:/opt/cni/bin StdinData:[123 34 99 110 105 86 101 114 115 105 111 110 34 58 34 48 46 51 46 49 34 44 34 110 97 109 101 34 58 34 109 105 122 97 114 99 110 105 34 44 34 116 121 112 101 34 58 34 109 105 122 97 114 99 110 105 34 125]}'
I0209 02:22:17.297686   11291 mizarcni.go:79] CNI_DEL: Tracelog: 'CNI_DEL: Deleting NetNS: '/var/run/netns'
'
I0209 02:22:17.297694   11291 mizarcni.go:84] CNI_DEL: Success - interface deleted for pod 'kube-system/netpod1'
I0209 02:22:17.297697   11291 mizarcni.go:87] CNI_DEL: <<<<
--------------------------------
root@ip-192-168-1-144:~/vmizar#
vinaykul commented 2 years ago

@yb01 After recent fixes, I don't see this reproduce even in arktos. Can you try again and let me know? (Make sure to delete all existing images so it downloads latest dev images)

yb01 commented 2 years ago

with Hong Changes for for issue #618, i checked the mizar cni log and didn't see this neither. here is the log with creating the netpod twice (create, delete, create), the twoo create both carries two CNI_ADD command -- the first one failed due to the interface is not ready.

so likely Hong Changes fix to #618 addressed this issue to some level. it is not ideal to see the timing issue with interface creation, but seems much better than before in terms of this bug.

Hong Change, can you explain this from the code changes perspective ?

I0211 01:52:36.016334   25679 mizarcni.go:60] CNI_ADD: Tracelog: 'CNI_ADD: Args: '{"Command":"ADD","ContainerID":"cb4632552b03260b3b2063ee1908c7dc46bf4311ccd707246ec5ce581b4e447e","NetNS":"/var/run/netns/cni-0641bdb6-8463-16c2-2839-20fd38ed9544","IfName":"eth0","CniPath":"/opt/cni/bin","K8sPodNamespace":"default","K8sPodName":"netpod1-1","K8sPodTenant":"system","CniVersion":"0.3.1","NetworkName":"mizarcni","Plugin":"mizarcni"}'
I0211 01:52:36.990496   25735 mizarcni.go:60] CNI_ADD: Tracelog: 'CNI_ADD: Args: '{"Command":"ADD","ContainerID":"d7c0affc0b4424079eba8c47757f2df6921bdaded2aebee6192bfb92889d2433","NetNS":"/var/run/netns/cni-fffa1c77-0e49-465c-bc06-d2baba4be7aa","IfName":"eth0","CniPath":"/opt/cni/bin","K8sPodNamespace":"default","K8sPodName":"netpod1-1","K8sPodTenant":"system","CniVersion":"0.3.1","NetworkName":"mizarcni","Plugin":"mizarcni"}'
I0211 02:01:14.754647   24053 mizarcni.go:60] CNI_ADD: Tracelog: 'CNI_ADD: Args: '{"Command":"ADD","ContainerID":"ab24fd4f8063b64dd1dbecc82b3524fa15fcc0af6c2e68a5e13ee20dd8ac4b8f","NetNS":"/var/run/netns/cni-9273dfc2-64bd-ebbf-ff20-364f28193c22","IfName":"eth0","CniPath":"/opt/cni/bin","K8sPodNamespace":"default","K8sPodName":"netpod1-1","K8sPodTenant":"system","CniVersion":"0.3.1","NetworkName":"mizarcni","Plugin":"mizarcni"}'
I0211 02:01:15.271271   24114 mizarcni.go:60] CNI_ADD: Tracelog: 'CNI_ADD: Args: '{"Command":"ADD","ContainerID":"a09ba431a58837da2fc6f72f1dfd5dcaa329d3991067cc39db49949cc958179f","NetNS":"/var/run/netns/cni-8a44acdf-8654-d4f9-d0f1-de5ef1dd9b16","IfName":"eth0","CniPath":"/opt/cni/bin","K8sPodNamespace":"default","K8sPodName":"netpod1-1","K8sPodTenant":"system","CniVersion":"0.3.1","NetworkName":"mizarcni","Plugin":"mizarcni"}'
root@ip-172-31-39-83:~/go/src/k8s.io/arktos#
vinaykul commented 2 years ago

It is normal behavior for containerd to call a delete if CNI returns error for CNI_ADD (which CNI is allowed to do). Hong is looking into whether a short wait can help iwth the DEL quickly followed by ADD. But the driver is functionally operations.

vinaykul commented 2 years ago

After Hong Chang's latest commit today, CNI_ADD succeeds in the first attempt. This is more of an optimization. Ideally we might want to consider a more scalable approach in future releases.