Log completion of image pulls.

[nmeyerhans]

Summary

This change adds an Info-level message upon completion of container image pull including the amount of time needed to complete the pull.

Implementation details

Minor reorganization and conversion to seelog of some existing logging statements. time.Duration measures elapsed time for logging. Sample logs:

2017-02-20T19:25:15Z [INFO] Pulling container sleep(938878489526.dkr.ecr.us-west-2.amazonaws.com/sleep) (NONE->RUNNING) concurrently. Task: sleep:2 arn:aws:ecs:us-west-2:938878489526:task/75bfd2e7-d031-41ca-890e-75bb49491441, Status: (NONE->RUNNING) Containers: [sleep (NONE->RUNNING),~internal~ecs-emptyvolume-source (STOPPED->STOPPED),]
2017-02-20T19:25:16Z [INFO] Finished pulling container sleep(938878489526.dkr.ecr.us-west-2.amazonaws.com/sleep) (PULLED->RUNNING) after 232ns.

Testing

• Builds on Linux (make release)
• Builds on Windows (go build -out amazon-ecs-agent.exe ./agent)
• Unit tests on Linux (make test) pass
• Unit tests on Windows (go test -timeout=25s ./agent/...) pass
• Integration tests on Linux (make run-integ-tests) pass
• Integration tests on Windows (.\scripts\run-integ-tests.ps1) pass
• Functional tests on Linux (make run-functional-tests) pass
• Functional tests on Windows (.\scripts\run-functional-tests.ps1) pass

New tests cover the changes: n/a

Description for the changelog

Enhancement - Log completion of image pulls.

Licensing

This contribution is under the terms of the Apache 2.0 License: yes

[samuelkarp]

It looks like this line includes the time waiting to acquire the pull lock. Can we make that explicit in the message and potentially add a second log line that is inside the lock scope so we can measure the pull time without lock acquisition?

[samuelkarp]

👍

[mkleint]

does the time mentioned in
2017-02-20T19:25:16Z [INFO] Finished pulling container sleep(938878489526.dkr.ecr.us-west-2.amazonaws.com/sleep) (PULLED->RUNNING) after 232ns.

actually include the time it took to download the docker image in question? it looks like it doesn't and I misunderstood this PR in the release notes. When I grep the message on a fresh instance with 1.14.1 I get always just times smaller than 500ns while our images are in gigabytes. and take long to download.
I was hoping to use this to debug and eventually monitor varied performance of our internal docker registry.

[richardpen]

@mkleint Thanks for reporting this, looks like there is a bug in the code where defer statement calculate the time.Since before the pull, as indicated in the doc:

A deferred function's arguments are evaluated when the defer statement is evaluated.

We are working on a fix and will let you know when there is an update.

Thanks,
Richard