Kubelet: Periodically reporting image pulling progress in log #26145

Random-Liu · 2016-05-24T08:07:28Z

Addresses #26075 (comment) and #26122 (comment).

This PR changes kube_docker_client to log pulling progress every 10 seconds. We can't print all progress messages into the log, because there are too many. So I make it report newest progress every 10 seconds to reduce log spam.
If the image pulling is too slow or stuck, we'll see image pulling progress unchanged or changed little overtime.

The following is the result if I set the reporting interval to 1 second.

I0524 00:53:26.189086  145099 kube_docker_client.go:252] Pulling image "ubuntu:latest": "17b6a9e179d7: Pulling fs layer "
I0524 00:53:27.189082  145099 kube_docker_client.go:252] Pulling image "ubuntu:latest": "202e40f8bb3a: Download complete "
I0524 00:53:28.189160  145099 kube_docker_client.go:252] Pulling image "ubuntu:latest": "487bffc61de6: Downloading [=>                                                 ] 1.474 MB/48.35 MB"
I0524 00:53:29.189156  145099 kube_docker_client.go:252] Pulling image "ubuntu:latest": "487bffc61de6: Downloading [====>                                              ] 3.931 MB/48.35 MB"
I0524 00:53:30.189089  145099 kube_docker_client.go:252] Pulling image "ubuntu:latest": "487bffc61de6: Downloading [=========>                                         ] 8.847 MB/48.35 MB"
I0524 00:53:31.189089  145099 kube_docker_client.go:252] Pulling image "ubuntu:latest": "487bffc61de6: Downloading [==================>                                ] 18.19 MB/48.35 MB"
I0524 00:53:32.189076  145099 kube_docker_client.go:252] Pulling image "ubuntu:latest": "487bffc61de6: Downloading [=======================================>           ] 38.34 MB/48.35 MB"
I0524 00:53:33.189106  145099 kube_docker_client.go:252] Pulling image "ubuntu:latest": "487bffc61de6: Extracting [=============>                                     ] 12.78 MB/48.35 MB"
I0524 00:53:34.189067  145099 kube_docker_client.go:252] Pulling image "ubuntu:latest": "487bffc61de6: Extracting [==================================>                ] 33.42 MB/48.35 MB"
I0524 00:53:35.189083  145099 kube_docker_client.go:252] Pulling image "ubuntu:latest": "487bffc61de6: Extracting [==================================================>] 48.35 MB/48.35 MB"
I0524 00:53:35.376667  145099 kube_docker_client.go:254] Finish pulling image "ubuntu:latest": "Status: Downloaded newer image for ubuntu:latest"

Ref image pulling related issue #19077.

@yujuhong @dchen1107
/cc @kubernetes/sig-node

ncdc · 2016-05-24T15:25:42Z

I think this is worth a release note. WDYT?

dchen1107 · 2016-05-24T16:34:27Z

+1 on release note.

dchen1107 · 2016-05-24T16:37:09Z

I marked this for 1.3 milestone since showing the pulling progress improves a lot of the debuggability for both flaky tests and real production.

yujuhong · 2016-05-24T16:43:37Z

pkg/kubelet/dockertools/kube_docker_client.go

+			case <-ticker.C:
+				glog.V(2).Infof("Pulling image %q: %q", p.image, p.progress.get())
+			case <-p.stopCh:
+				glog.V(2).Infof("Finish pulling image %q: %q", p.image, p.progress.get())


This message implies that pulling succeeded. This could be misleading when PullImage errors out. Maybe just print "Pulling image" as above

Changed to "Stop pulling image".

Random-Liu · 2016-05-24T16:52:56Z

@ncdc @dchen1107 This PR only reports image pulling progress in kubelet.log, and only reports every 10 seconds.
It means that:

The log is not directly user facing currently.
There should be only one or two lines of progress reporting for normal image pulling.

Given this, should we still add this in release note? Should we shorten the reporting interval to 5 seconds or less? :)

yujuhong · 2016-05-24T16:58:02Z

I think it'd be more "release-note" worthy if we report events. Printing in the log seems like a debugging detail which should not be noticed by most users.

ncdc · 2016-05-24T17:06:58Z

Ok, I agree this doesn't need a release note now 😄

Random-Liu · 2016-05-24T17:08:49Z

@yujuhong Yeah. It is not hard to change the logic to report via events. But then this may become a UX change: if too few progresses sent, the information will be segmented and uninformative; if too many sent, it could be event spam.
It would be better if we have realtime progress updating in kubectl result just like docker pull.

dchen1107 · 2016-05-24T17:11:01Z

I think it deserve a release note especially for the user who has their own logging system integrated to Kubernetes. They can not only check today's pulling image related events with this change.

vishh · 2016-05-24T17:33:03Z

pkg/kubelet/dockertools/kube_docker_client.go

+		ticker := time.NewTicker(p.interval)
+		defer ticker.Stop()
+		for {
+			// TODO(random-liu): Report as events.


Note: #19077 tracks exposing image pull progress. Events might not be the best mechanism.

@vishh Yeah. Event is a easily doable approach better than log, but as what you said, it's not the best solution.

Random-Liu · 2016-05-24T18:09:48Z

@k8s-bot test this issue #26004.

Random-Liu · 2016-05-24T18:56:47Z

Prepull image failed:

I0524 18:20:26.486302    2069 e2e_node_suite_test.go:67] Pre-pulling images so that they are cached for the tests.
W0524 18:20:41.679642    2069 container_list.go:56] Could not pre-pull image %s %v output:  %sgcr.io/google_containers/pause-amd64:3.0exit status 1 [69 114 114 111 114 32 114 101 115 112 111 110 115 101 32 102 114 111 109 32 100 97 101 109 111 110 58 32 71 101 116 32 104 116 116 112 115 58 47 47 103 99 114 46 105 111 47 118 50 47 103 111 111 103 108 101 95 99 111 110 116 97 105 110 101 114 115 47 112 97 117 115 101 45 97 109 100 54 52 47 109 97 110 105 102 101 115 116 115 47 51 46 48 58 32 71 101 116 32 104 116 116 112 115 58 47 47 103 99 114 46 105 111 47 118 50 47 116 111 107 101 110 63 115 99 111 112 101 61 114 101 112 111 115 105 116 111 114 121 37 51 65 103 111 111 103 108 101 95 99 111 110 116 97 105 110 101 114 115 37 50 70 112 97 117 115 101 45 97 109 100 54 52 37 51 65 112 117 108 108 38 115 101 114 118 105 99 101 61 103 99 114 46 105 111 58 32 110 101 116 47 104 116 116 112 58 32 114 101 113 117 101 115 116 32 99 97 110 99 101 108 101 100 32 119 104 105 108 101 32 119 97 105 116 105 110 103 32 102 111 114 32 99 111 110 110 101 99 116 105 111 110 32 40 67 108 105 101 110 116 46 84 105 109 101 111 117 116 32 101 120 99 101 101 100 101 100 32 119 104 105 108 101 32 97 119 97 105 116 105 110 103 32 104 101 97 100 101 114 115 41 10]

Unfortunately the log is not printed properly. I've sent PR #26192 to fix the log, and will file issue with right log if this happens again.

@k8s-bot test this issue #IGNORE.

Random-Liu · 2016-05-24T19:55:45Z

@k8s-bot test this issue #25967.

dchen1107 · 2016-05-25T07:02:49Z

LGTM

k8s-github-robot · 2016-05-28T19:40:45Z

@k8s-bot test this [submit-queue is verifying that this PR is safe to merge]

k8s-bot · 2016-05-28T20:26:52Z

GCE e2e build/test passed for commit 151d0ab.

k8s-github-robot · 2016-05-28T20:34:28Z

Automatic merge from submit-queue

Random-Liu added area/kubelet sig/node Categorizes an issue or PR as relevant to SIG Node. labels May 24, 2016

Random-Liu assigned yujuhong May 24, 2016

googlebot added the cla: yes label May 24, 2016

Random-Liu mentioned this pull request May 24, 2016

Kubelet: Switch to Docker engine-api and add timeout for all docker calls #23563

Closed

22 tasks

k8s-github-robot added size/M Denotes a PR that changes 30-99 lines, ignoring generated files. release-note-label-needed labels May 24, 2016

Random-Liu added release-note-none Denotes a PR that doesn't merit a release note. and removed release-note-label-needed labels May 24, 2016

dchen1107 added release-note Denotes a PR that will be considered when it comes time to generate release notes. and removed release-note-none Denotes a PR that doesn't merit a release note. labels May 24, 2016

dchen1107 assigned dchen1107 and unassigned yujuhong May 24, 2016

dchen1107 added this to the v1.3 milestone May 24, 2016

yujuhong reviewed May 24, 2016
View reviewed changes

Periodically reporing image pulling progress in log

151d0ab

Random-Liu force-pushed the image-pulling-progress branch from 0ce0cfd to 151d0ab Compare May 24, 2016 16:58

vishh reviewed May 24, 2016
View reviewed changes

dchen1107 added the lgtm "Looks good to me", indicates that a PR is ready to be merged. label May 25, 2016

yujuhong mentioned this pull request May 25, 2016

Set timeout for docker image pull calls #26300

Closed

Random-Liu changed the title ~~Kubelet: Periodically reporing image pulling progress in log~~ Kubelet: Periodically reporting image pulling progress in log May 26, 2016

k8s-github-robot merged commit 344f26a into kubernetes:master May 28, 2016

Random-Liu deleted the image-pulling-progress branch May 29, 2016 04:27

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Kubelet: Periodically reporting image pulling progress in log #26145

Kubelet: Periodically reporting image pulling progress in log #26145

Random-Liu commented May 24, 2016 •

edited

ncdc commented May 24, 2016

dchen1107 commented May 24, 2016

dchen1107 commented May 24, 2016

yujuhong May 24, 2016

Random-Liu May 24, 2016

Random-Liu May 24, 2016

Random-Liu commented May 24, 2016 •

edited

yujuhong commented May 24, 2016

ncdc commented May 24, 2016

Random-Liu commented May 24, 2016 •

edited

dchen1107 commented May 24, 2016

vishh May 24, 2016

Random-Liu May 24, 2016 •

edited

Random-Liu commented May 24, 2016

Random-Liu commented May 24, 2016

Random-Liu commented May 24, 2016

dchen1107 commented May 25, 2016

k8s-github-robot commented May 28, 2016

k8s-bot commented May 28, 2016

k8s-github-robot commented May 28, 2016

Kubelet: Periodically reporting image pulling progress in log #26145

Kubelet: Periodically reporting image pulling progress in log #26145

Conversation

Random-Liu commented May 24, 2016 • edited

ncdc commented May 24, 2016

dchen1107 commented May 24, 2016

dchen1107 commented May 24, 2016

yujuhong May 24, 2016

Choose a reason for hiding this comment

Random-Liu May 24, 2016

Choose a reason for hiding this comment

Random-Liu May 24, 2016

Choose a reason for hiding this comment

Random-Liu commented May 24, 2016 • edited

yujuhong commented May 24, 2016

ncdc commented May 24, 2016

Random-Liu commented May 24, 2016 • edited

dchen1107 commented May 24, 2016

vishh May 24, 2016

Choose a reason for hiding this comment

Random-Liu May 24, 2016 • edited

Choose a reason for hiding this comment

Random-Liu commented May 24, 2016

Random-Liu commented May 24, 2016

Random-Liu commented May 24, 2016

dchen1107 commented May 25, 2016

k8s-github-robot commented May 28, 2016

k8s-bot commented May 28, 2016

k8s-github-robot commented May 28, 2016

Random-Liu commented May 24, 2016 •

edited

Random-Liu commented May 24, 2016 •

edited

Random-Liu commented May 24, 2016 •

edited

Random-Liu May 24, 2016 •

edited