Log to stdout

[mogren]

Fix for issue #869

Description of changes:

• Use tee instead of > to redirect logs
• Reduce the logging that happens every 5 seconds to be once per minute

With default logging:

> kubectl logs aws-node-bd8mn -n kube-system 
starting IPAM daemon in background ... ok.
checking for IPAM connectivity ... ok.
copying CNI plugin binaries and config files ...  ok.
Foregrounding IPAM daemon ...

In /var/log/aws-routed-eni:

Apr  7 22:41 ipamd.log

With stdout

> kubectl logs aws-node-2qnmj -n kube-system -f                                                                                                                                                                                                   ~/src/cni-tests
Starting IPAM daemon in the background ... ok.
Checking for IPAM connectivity ... {"level":"info","ts":"2020-04-07T22:43:10.700Z","caller":"aws-k8s-agent/main.go:31","msg":"Starting L-IPAMD v1.6.1-rc1  ..."}
{"level":"info","ts":"2020-04-07T22:43:10.721Z","caller":"aws-k8s-agent/main.go:43","msg":"Testing communication with server"}
{"level":"info","ts":"2020-04-07T22:43:10.721Z","caller":"aws-k8s-agent/main.go:43","msg":"Successful communication with the Cluster! Cluster Version is: v1.14+. git version: v1.14.9-eks-502bfb. git tree state: clean. commit: 502bfb383169b124d87848f89e17a04b9fc1f6f0. platform: linux/amd64"}
{"level":"info","ts":"2020-04-07T22:43:10.722Z","caller":"runtime/asm_amd64.s:1357","msg":"Starting Pod controller"}
{"level":"info","ts":"2020-04-07T22:43:10.722Z","caller":"runtime/asm_amd64.s:1357","msg":"Waiting for controller cache sync"}
{"level":"debug","ts":"2020-04-07T22:43:10.723Z","caller":"ipamd/ipamd.go:250","msg":"Discovered region: us-west-2"}
.
.
.

And once every minute

{"level":"debug","ts":"2020-04-07T23:09:21.181Z","caller":"ipamd/ipamd.go:462","msg":"Reconciling ENI/IP pool info because time since last 1m0.157321578s <= 1m0s"}
{"level":"debug","ts":"2020-04-07T23:09:21.182Z","caller":"ipamd/ipamd.go:933","msg":"Total number of interfaces found: 3 "}
{"level":"debug","ts":"2020-04-07T23:09:21.182Z","caller":"awsutils/awsutils.go:437","msg":"Found ENI mac address : 02:01:bb:31:e6:e4"}
{"level":"debug","ts":"2020-04-07T23:09:21.184Z","caller":"awsutils/awsutils.go:437","msg":"Found ENI: eni-05fdeb760b99ea109, MAC 02:01:bb:31:e6:e4, device 2"}
{"level":"debug","ts":"2020-04-07T23:09:21.184Z","caller":"awsutils/awsutils.go:457","msg":"Found CIDR 10.10.64.0/19 for ENI 02:01:bb:31:e6:e4"}
{"level":"debug","ts":"2020-04-07T23:09:21.185Z","caller":"awsutils/awsutils.go:457","msg":"Found IP addresses [10.10.71.142 10.10.77.42 10.10.78.171 10.10.90.233 10.10.65.41 10.10.84.169 10.10.88.141 10.10.64.229 10.10.85.250 10.10.73.186 10.10.87.27 10.10.82.216 10.10.73.253 10.10.71.150 10.10.75.21] on ENI 02:01:bb:31:e6:e4"}
{"level":"debug","ts":"2020-04-07T23:09:21.270Z","caller":"awsutils/awsutils.go:437","msg":"Found ENI mac address : 02:13:74:67:80:d0"}
{"level":"debug","ts":"2020-04-07T23:09:21.273Z","caller":"awsutils/awsutils.go:451","msg":"Using device number 0 for primary eni: eni-099be66bfda61ff39"}
{"level":"debug","ts":"2020-04-07T23:09:21.273Z","caller":"awsutils/awsutils.go:437","msg":"Found ENI: eni-099be66bfda61ff39, MAC 02:13:74:67:80:d0, device 0"}
{"level":"debug","ts":"2020-04-07T23:09:21.273Z","caller":"awsutils/awsutils.go:457","msg":"Found CIDR 10.10.64.0/19 for ENI 02:13:74:67:80:d0"}
{"level":"debug","ts":"2020-04-07T23:09:21.274Z","caller":"awsutils/awsutils.go:457","msg":"Found IP addresses [10.10.80.162 10.10.88.78 10.10.77.141 10.10.78.195 10.10.82.99 10.10.69.160 10.10.89.166 10.10.84.158 10.10.65.221 10.10.78.51 10.10.68.243 10.10.86.211 10.10.71.81 10.10.95.55 10.10.93.52] on ENI 02:13:74:67:80:d0"}
{"level":"debug","ts":"2020-04-07T23:09:21.354Z","caller":"awsutils/awsutils.go:437","msg":"Found ENI mac address : 02:33:87:77:48:a0"}
{"level":"debug","ts":"2020-04-07T23:09:21.356Z","caller":"awsutils/awsutils.go:437","msg":"Found ENI: eni-0db951bd7338c92c9, MAC 02:33:87:77:48:a0, device 3"}
{"level":"debug","ts":"2020-04-07T23:09:21.356Z","caller":"awsutils/awsutils.go:457","msg":"Found CIDR 10.10.64.0/19 for ENI 02:33:87:77:48:a0"}
{"level":"debug","ts":"2020-04-07T23:09:21.357Z","caller":"awsutils/awsutils.go:457","msg":"Found IP addresses [10.10.69.223 10.10.89.234 10.10.92.171 10.10.80.136 10.10.71.200 10.10.90.14 10.10.69.238 10.10.91.205 10.10.68.35 10.10.77.165 10.10.90.152 10.10.82.62 10.10.95.18 10.10.65.82 10.10.75.176] on ENI 02:33:87:77:48:a0"}
{"level":"debug","ts":"2020-04-07T23:09:21.440Z","caller":"ipamd/ipamd.go:462","msg":"Reconcile existing ENI eni-05fdeb760b99ea109 IP pool"}
{"level":"debug","ts":"2020-04-07T23:09:21.440Z","caller":"ipamd/ipamd.go:951","msg":"Reconcile and skip primary IP 10.10.71.142 on ENI eni-05fdeb760b99ea109"}
{"level":"debug","ts":"2020-04-07T23:09:21.440Z","caller":"ipamd/ipamd.go:462","msg":"Reconcile existing ENI eni-099be66bfda61ff39 IP pool"}
{"level":"debug","ts":"2020-04-07T23:09:21.440Z","caller":"ipamd/ipamd.go:951","msg":"Reconcile and skip primary IP 10.10.80.162 on ENI eni-099be66bfda61ff39"}
{"level":"debug","ts":"2020-04-07T23:09:21.440Z","caller":"ipamd/ipamd.go:462","msg":"Reconcile existing ENI eni-0db951bd7338c92c9 IP pool"}
{"level":"debug","ts":"2020-04-07T23:09:21.440Z","caller":"ipamd/ipamd.go:951","msg":"Reconcile and skip primary IP 10.10.69.223 on ENI eni-0db951bd7338c92c9"}
{"level":"debug","ts":"2020-04-07T23:09:21.440Z","caller":"ipamd/ipamd.go:462","msg":"Successfully Reconciled ENI/IP pool"}
{"level":"debug","ts":"2020-04-07T23:09:21.440Z","caller":"ipamd/ipamd.go:462","msg":"IP Address Pool stats: total: 42, assigned: 18"}

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

[nithu0115]

Thanks, @mogren. Changes LGTM!

[nithu0115]

Nice :)

[jaypipes]

Very good. I like this a lot.

I wonder, though, whether we should just remove the echo calls entirely from the entrypoint.sh script EXCEPT for the echo about timing out waiting for the ipamd. That way, logging to stdout has a consistent JSON format (since zap is now outputting structured log records) instead of some non-structured log messages followed by structured JSON records.

[mogren]

Great point! I'll create an issue for that.