Bad result returned if endpoint attach fails because container has stopped

[PatrickLang]

Is this an ISSUE or FEATURE REQUEST? (choose one): Issue
Which release version?: 1.0.27
Which component (CNI/IPAM/CNM/CNS): CNI
Which Operating System (Linux/Windows): Windows Server 2019
Which Orchestrator and version (e.g. Kubernetes, Docker): Kubernetes

What happened:

A container in a pod was stopping before the network endpoint was attached by CNI. In this case, a malformed result is passed back to the kubelet, causing this message in the logs.

E1110 14:23:32.842611    4564 cni_windows.go:50] error while adding to cni network: invalid character '{' after top-level value
W1110 14:23:32.842611    4564 docker_sandbox.go:384] failed to read pod IP from plugin/docker: NetworkPlugin cni failed on the status hook for pod "<name removed>": invalid character '{' after top-level value

What you expected to happen:

I would expect a well-formed error to be returned that has a message stating "A virtual machine or container with the specified identifier does not exist". Parsing errors make the kubelet logs difficult to understand and don't help identify the root cause of a failure.

[PatrickLang]

Here's an easy repro. kubectl create this

apiVersion: apps/v1
kind: Deployment
metadata:
  name: crash1
  labels:
    app: crash1
spec:
  replicas: 1
  template:
    metadata:
      name: crash1
      labels:
        app: crash1
    spec:
      containers:
      - name: windowswebserver
        resources:
          limits:
            cpu: .5
            memory: 2Gi
        image: mcr.microsoft.com/windows/servercore:ltsc2019
        command:
        - cmd.exe
        - /c
        - exit 2
      nodeSelector:
        "beta.kubernetes.io/os": windows
  selector:
    matchLabels:
      app: crash1

And the resulting errors:

I1211 00:15:34.190831    5644 fake_cpu_manager.go:47] [fake cpumanager] RemoveContainer (container id: 9ace9a71ec6c80f00a3bfd4caea6355f4be61dcfd5d745a38b49b709a310b6a2)
E1211 00:15:34.191824    5644 pod_workers.go:191] Error syncing pod 600a0bcf-758f-4aa1-8b85-6213fccab21c ("crash1-78f45f46cc-mwxdt_default(600a0bcf-758f-4aa1-8b85-6213fccab21c)"), skipping: failed to "StartContainer" for "windowswebserver" with CrashLoopBackOff: "back-off 2m40s restarting failed container=windowswebserver pod=crash1-78f45f46cc-mwxdt_default(600a0bcf-758f-4aa1-8b85-6213fccab21c)"
E1211 00:15:35.535185    5644 cni.go:364] Error adding default_crash1-78f45f46cc-mwxdt/9ace9a71ec6c80f00a3bfd4caea6355f4be61dcfd5d745a38b49b709a310b6a2 to network azure-vnet/azure: invalid character '{' after top-level value
E1211 00:15:35.535185    5644 cni_windows.go:59] error while adding to cni network: invalid character '{' after top-level value
W1211 00:15:35.535185    5644 docker_sandbox.go:394] failed to read pod IP from plugin/docker: networkPlugin cni failed on the status hook for pod "crash1-78f45f46cc-mwxdt_default": invalid character '{' after top-level value
I1211 00:15:46.769840    5644 fake_cpu_manager.go:47] [fake cpumanager] RemoveContainer (container id: 9ace9a71ec6c80f00a3bfd4caea6355f4be61dcfd5d745a38b49b709a310b6a2)
E1211 00:15:46.769840    5644 pod_workers.go:191] Error syncing pod 600a0bcf-758f-4aa1-8b85-6213fccab21c ("crash1-78f45f46cc-mwxdt_default(600a0bcf-758f-4aa1-8b85-6213fccab21c)"), skipping: failed to "StartContainer" for "windowswebserver" with CrashLoopBackOff: "back-off 2m40s restarting failed container=windowswebserver pod=crash1-78f45f46cc-mwxdt_default(600a0bcf-758f-4aa1-8b85-6213fccab21c)"

[trgabrie]

We are experiencing a similar issue. Azure CNI version is 1.0.27 as well. What we are seeing happen is that multiple pods will be unable to talk to other pods causing them to crash, and after that runs for a while, the node will end up crashing. The erroring node kubelet.err logs contain:

I0128 16:16:56.012105 18216 fake_cpu_manager.go:45] [fake cpumanager] RemoveContainer (container id: f5fd17ba23f7fc983f1dbbbaac64c8d89a0745402228e24ffe403a1a00aef245)
I0128 16:16:56.173003 18216 fake_cpu_manager.go:40] [fake cpumanager] AddContainer (pod: feedadmin-68644b5684-rbp79, container: feedadmin, container id: ae7406228e2e0a56083cd15be347c193acfbaa41551aca831aab3e1e829d7bfa)
E0128 16:16:56.952164 18216 cni.go:331] Error adding oncallprtest-19207_loi-669888c8d7-nbfl4/60efc16f1dd2414a62dbaae1862c2ffcdb3ac329f39b546b911a8a81ed6e05fa to network azure-vnet/azure: invalid character '{' after top-level value
E0128 16:16:56.952164 18216 cni_windows.go:50] error while adding to cni network: invalid character '{' after top-level value
W0128 16:16:56.952164 18216 docker_sandbox.go:384] failed to read pod IP from plugin/docker: NetworkPlugin cni failed on the status hook for pod "loi-669888c8d7-nbfl4_oncallprtest-19207": invalid character '{' after top-level value

This happens a few times a day on an environment that we are frequently adding and removing entire deployments.

[aanandr]

@trgbrie - we will look into this
@tamilmani1989 - how can we get the latest and best CNI version when deploying with aks-engine? Can you let us know?

[tamilmani1989]

@aanandr This ticket was opened by patrick stating that cni error was not returned in right error format. The error may not necessarily due to azure cni and it can be a different reason also. satya started working on this. Let me check with him.

[tamilmani1989]

satya is working on this