Update readme on stdout support for plugin log file #1251

jayanthvn · 2020-10-06T19:03:48Z

What type of PR is this?
Bug

Which issue does this PR fix:
#1248

What does this PR do / Why do we need it:
This PR flags an error when stdout is set for AWS_VPC_K8S_PLUGIN_LOG_FILE. Stdout cannot be used for redirecting plugin logs since the plugin expects the network configuration in JSON format must be streamed through stdin and output on success streamed back to stdout. Ref - https://github.com/containernetworking/cni/blob/master/SPEC.md#result

If an issue # is not available please add repro steps and logs from IPAMD/CNI showing the issue:
Attached logs and analysis in #1248

Testing done on this change:

UT 1 -> if stdout is set as plugin log file

NAME                       READY   STATUS             RESTARTS   AGE     IP               NODE                                           NOMINATED NODE   READINESS GATES
aws-node-h2nd4             1/1     Running            0          2m18s   192.168.54.25    ip-192-168-54-25.us-west-2.compute.internal    <none>           <none>
aws-node-klrp9             1/1     Running            0          114s    192.168.65.56    ip-192-168-65-56.us-west-2.compute.internal    <none>           <none>
aws-node-nf45l             0/1     Error              1          10s     192.168.21.154   ip-192-168-21-154.us-west-2.compute.internal   <none>           <none>

{"level":"info","ts":"2020-10-06T18:31:45.784Z","caller":"entrypoint.sh","msg":"Install CNI binary.."}
{"level":"info","ts":"2020-10-06T18:31:45.801Z","caller":"entrypoint.sh","msg":"Starting IPAM daemon in the background ... "}
{"level":"info","ts":"2020-10-06T18:31:45.810Z","caller":"entrypoint.sh","msg":"Checking for IPAM connectivity ... "}
{"level":"info","ts":"2020-10-06T18:31:47.828Z","caller":"entrypoint.sh","msg":"Copying config file ... "}
{"level":"info","ts":"2020-10-06T18:31:47.829Z","caller":"entrypoint.sh","msg":"Validating env variables ..."}
{"level":"error","ts":"2020-10-06T18:31:47.829Z","caller":"entrypoint.sh","msg":"Plugin log file cannot be set to stdout"}

UT 2 - Setting stderr as plugin log file

kubectl set env daemonset aws-node -n kube-system AWS_VPC_K8S_PLUGIN_LOG_FILE=stderr

NAME                       READY   STATUS             RESTARTS   AGE     IP               NODE                                           NOMINATED NODE   READINESS GATES
aws-node-4t6tr             1/1     Running            0          82s     192.168.54.25    ip-192-168-54-25.us-west-2.compute.internal    <none>           <none>
aws-node-7984v             1/1     Running            0          74s     192.168.21.154   ip-192-168-21-154.us-west-2.compute.internal   <none>           <none>
aws-node-klrp9             1/1     Running            0          4m28s   192.168.65.56    ip-192-168-65-56.us-west-2.compute.internal    <none>           <none>

Delete and add running pods -

kubectl delete deployment --all
deployment.apps "my-nginx" deleted

kubectl get pods
No resources found.

kubectl apply -f ~/eks_workshop/run-my-nginx.yaml
deployment.apps/my-nginx created

NAME                       READY   STATUS    RESTARTS   AGE   IP               NODE                                           NOMINATED NODE   READINESS GATES
my-nginx-86b7cfc89-2fgq9   1/1     Running   0          5s    192.168.11.64    ip-192-168-21-154.us-west-2.compute.internal   <none>           <none>
my-nginx-86b7cfc89-5spz7   1/1     Running   0          5s    192.168.91.102   ip-192-168-65-56.us-west-2.compute.internal    <none>           <none>
my-nginx-86b7cfc89-68gt4   1/1     Running   0          5s    192.168.38.254   ip-192-168-54-25.us-west-2.compute.internal    <none>           <none>
my-nginx-86b7cfc89-7l5cn   1/1     Running   0          5s    192.168.60.138   ip-192-168-54-25.us-west-2.compute.internal    <none>           <none>
my-nginx-86b7cfc89-8b8b9   1/1     Running   0          5s    192.168.6.188    ip-192-168-21-154.us-west-2.compute.internal   <none>           <none>
my-nginx-86b7cfc89-8fr7p   1/1     Running   0          5s    192.168.34.100   ip-192-168-54-25.us-west-2.compute.internal    <none>           <none>
my-nginx-86b7cfc89-kk9mt   1/1     Running   0          5s    192.168.83.105   ip-192-168-65-56.us-west-2.compute.internal    <none>           <none>
my-nginx-86b7cfc89-krxbc   1/1     Running   0          5s    192.168.86.163   ip-192-168-65-56.us-west-2.compute.internal    <none>           <none>
my-nginx-86b7cfc89-vgp24   1/1     Running   0          5s    192.168.17.145   ip-192-168-21-154.us-west-2.compute.internal   <none>           <none>

UT 3 - Added interface type which will help during EFA debugging -

{"level":"info","ts":"2020-10-06T23:00:03.704Z","caller":"ipamd/ipamd.go:345","msg":"eni-00f9c798f747cf084 is of type: interface"}
{"level":"info","ts":"2020-10-06T23:00:03.704Z","caller":"ipamd/ipamd.go:345","msg":"eni-03179667233b94b79 is of type: interface"}

UT 4 - Uppercase of STDOUT

kubectl logs aws-node-pjqf9 -n kube-system
{"level":"info","ts":"2020-10-06T23:06:02.555Z","caller":"entrypoint.sh","msg":"Validating env variables ..."}
{"level":"error","ts":"2020-10-06T23:06:02.556Z","caller":"entrypoint.sh","msg":"AWS_VPC_K8S_PLUGIN_LOG_FILE cannot be set to stdout"}

kubectl describe daemonset aws-node -n kube-system | grep AWS_VPC_K8S_PLUGIN_LOG_FILE
      AWS_VPC_K8S_PLUGIN_LOG_FILE:         STDOUT

UT 5 - file name is uppercase, should be retained

kubectl describe daemonset aws-node -n kube-system | grep AWS_VPC_K8S_PLUGIN_LOG_FILE
      AWS_VPC_K8S_PLUGIN_LOG_FILE:         /var/log/aws-routed-eni/PLUGIN.log

Added a pod and file got created with provided name -

[root@ip-192-168-21-154 ec2-user]# ls  /var/log/aws-routed-eni/
ipamd.log  plugin.log
[root@ip-192-168-21-154 ec2-user]# ls  /var/log/aws-routed-eni/
ipamd.log  plugin.log  PLUGIN.log

[root@ip-192-168-21-154 ec2-user]# cat /var/log/aws-routed-eni/PLUGIN.log
{"level":"info","ts":"2020-10-06T23:11:03.886Z","caller":"routed-eni-cni-plugin/cni.go:243","msg":"Received CNI del request: ContainerID(692bf03e601e3dba4c14184993df5b0ec31406d297b554c18b696b08ffaa6667) Netns(/proc/30607/ns/net) IfName(eth0) Args(IgnoreUnknown=1;K8S_POD_NAMESPACE=default;K8S_POD_NAME=my-nginx-86b7cfc89-27mdd;K8S_POD_INFRA_CONTAINER_ID=692bf03e601e3dba4c14184993df5b0ec31406d297b554c18b696b08ffaa6667) Path(/opt/cni/bin) argsStdinData({\"cniVersion\":\"0.3.1\",\"mtu\":\"9001\",\"name\":\"aws-cni\",\"pluginLogFile\":\"/var/log/aws-routed-eni/PLUGIN.log\",\"pluginLogLevel\":\"DEBUG\",\"type\":\"aws-cni\",\"vethPrefix\":\"eni\"})"}
{"level":"info","ts":"2020-10-06T23:11:03.887Z","caller":"routed-eni-cni-plugin/cni.go:243","msg":"Received del network response for pod my-nginx-86b7cfc89-27mdd namespace default sandbox 692bf03e601e3dba4c14184993df5b0ec31406d297b554c18b696b08ffaa6667: Success:true IPv4Addr:\"192.168.22.85\" "}
{"level":"debug","ts":"2020-10-06T23:11:03.887Z","caller":"routed-eni-cni-plugin/cni.go:319","msg":"TeardownNS: addr 192.168.22.85/32, deviceNumber 0"}
{"level":"info","ts":"2020-10-06T23:11:03.887Z","caller":"driver/driver.go:434","msg":"Delete toContainer rule for 192.168.22.85/32 "}
{"level":"debug","ts":"2020-10-06T23:11:03.887Z","caller":"driver/driver.go:434","msg":"Tear down of NS complete"}

Automation added to e2e:

No

Will this break upgrades or downgrades. Has updating a running cluster been tested?:

UT 6 - Upgrade 1.7.4 to 1.7.5

kubectl describe daemonset aws-node -n kube-system | grep Image | cut -d "/" -f 2
amazon-k8s-cni-init:v1.7.4
amazon-k8s-cni:v1.7.4

kubectl describe daemonset aws-node -n kube-system | grep AWS_VPC_K8S_PLUGIN_LOG_FILE
      AWS_VPC_K8S_PLUGIN_LOG_FILE:         stdout

NAME                       READY   STATUS             RESTARTS   AGE     IP               NODE                                           NOMINATED NODE   READINESS GATES
aws-node-dkx8w             1/1     Running            0          50s     192.168.65.56    ip-192-168-65-56.us-west-2.compute.internal    <none>           <none>
aws-node-jxgdh             1/1     Running            0          76s     192.168.54.25    ip-192-168-54-25.us-west-2.compute.internal    <none>           <none>
aws-node-kxcwn             1/1     Running            0          28s     192.168.21.154   ip-192-168-21-154.us-west-2.compute.internal   <none>           <none>

On upgrade -

kubectl patch daemonset aws-node -n kube-system -p '{"spec": {"template": {"spec": {"containers": [{"image": "113910096515.dkr.ecr.us-west-2.amazonaws.com/v1.7-testing:v1.7-stdout-v8","name":"aws-node"}]}}}}'
daemonset.apps/aws-node patched

NAME                       READY   STATUS             RESTARTS   AGE     IP               NODE                                           NOMINATED NODE   READINESS GATES
aws-node-dkx8w             1/1     Running            0          103s    192.168.65.56    ip-192-168-65-56.us-west-2.compute.internal    <none>           <none>
aws-node-kxcwn             1/1     Terminating        0          81s     192.168.21.154   ip-192-168-21-154.us-west-2.compute.internal   <none>           <none>
aws-node-rh9c9             0/1     Error              1          9s      192.168.54.25    ip-192-168-54-25.us-west-2.compute.internal    <none>           <none>

kubectl logs aws-node-rh9c9 -n kube-system
{"level":"info","ts":"2020-10-06T19:01:49.824Z","caller":"entrypoint.sh","msg":"Install CNI binary.."}
{"level":"info","ts":"2020-10-06T19:01:49.838Z","caller":"entrypoint.sh","msg":"Starting IPAM daemon in the background ... "}
{"level":"info","ts":"2020-10-06T19:01:49.842Z","caller":"entrypoint.sh","msg":"Checking for IPAM connectivity ... "}
{"level":"info","ts":"2020-10-06T19:01:51.871Z","caller":"entrypoint.sh","msg":"Copying config file ... "}
{"level":"info","ts":"2020-10-06T19:01:51.871Z","caller":"entrypoint.sh","msg":"Validating env variables ..."}
{"level":"error","ts":"2020-10-06T19:01:51.872Z","caller":"entrypoint.sh","msg":"Plugin log file cannot be set to stdout"}

Does this change require updates to the CNI daemonset config files to work?:

It will work with kubectl patch(ref UT 3)

Does this PR introduce any user-facing change?:

Updated readme and Cx cannot use stdout as plugin log file.

By submitting this pull request, I confirm that my contribution is made under the terms of the Apache 2.0 license.

nithu0115

Thanks @jayanthvn, Minor comments inline.

scripts/entrypoint.sh

README.md

scripts/entrypoint.sh

fawadkhaliq

/lgtm

chlunde · 2020-12-14T11:13:42Z

scripts/entrypoint.sh

+{
+    log_in_json info "Validating env variables ..."
+    if [[ "${AWS_VPC_K8S_PLUGIN_LOG_FILE,,}" == "stdout" ]]; then
+        log_in_json error "AWS_VPC_K8S_PLUGIN_LOG_FILE cannot be set to stdout"


Maybe add a hint that the value "stderr" is the only valid value? Because the docs points to stdout and it works for the other log.

Btw the user guide still says stdout: https://docs.aws.amazon.com/eks/latest/userguide/cni-env-vars.html

https://github.com/awsdocs/amazon-eks-user-guide/edit/master/doc_source/cni-env-vars.md

jayanthvn requested review from fawadkhaliq and SaranBalaji90 October 6, 2020 19:04

jayanthvn self-assigned this Oct 6, 2020

jayanthvn added this to the v1.7.5 milestone Oct 6, 2020

nithu0115 reviewed Oct 6, 2020

View reviewed changes

scripts/entrypoint.sh Outdated Show resolved Hide resolved

scripts/entrypoint.sh Outdated Show resolved Hide resolved

nithu0115 reviewed Oct 6, 2020

View reviewed changes

README.md Show resolved Hide resolved

jayanthvn force-pushed the stdout_fix branch from 1ef8df2 to 44161d9 Compare October 6, 2020 19:37

fawadkhaliq suggested changes Oct 6, 2020

View reviewed changes

scripts/entrypoint.sh Outdated Show resolved Hide resolved

Update readme on stdout support

7622bb9

jayanthvn force-pushed the stdout_fix branch from 44161d9 to 7622bb9 Compare October 6, 2020 23:15

fawadkhaliq approved these changes Oct 6, 2020

View reviewed changes

jayanthvn modified the milestones: v1.7.5, v1.7.6 Oct 8, 2020

mogren approved these changes Oct 11, 2020

View reviewed changes

jayanthvn merged commit ccd6887 into aws:master Oct 12, 2020

jayanthvn mentioned this pull request Oct 12, 2020

Log to standard output result in garbage character in add function #1248

Closed

jayanthvn mentioned this pull request Oct 22, 2020

New pods failing to start with FailedCreatePodSandBox warning for CNI versions 1.7.x with Cilium #1265

Closed

jayanthvn mentioned this pull request Nov 30, 2020

Cherrypick #1251 #1301

Merged

chlunde reviewed Dec 14, 2020

View reviewed changes

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Update readme on stdout support for plugin log file #1251

Update readme on stdout support for plugin log file #1251

jayanthvn commented Oct 6, 2020 •

edited

Loading

nithu0115 left a comment

fawadkhaliq left a comment

chlunde Dec 14, 2020

Update readme on stdout support for plugin log file #1251

Update readme on stdout support for plugin log file #1251

Conversation

jayanthvn commented Oct 6, 2020 • edited Loading

nithu0115 left a comment

Choose a reason for hiding this comment

fawadkhaliq left a comment

Choose a reason for hiding this comment

chlunde Dec 14, 2020

Choose a reason for hiding this comment

jayanthvn commented Oct 6, 2020 •

edited

Loading