Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Kubelet: Periodically reporting image pulling progress in log #26145

Merged
merged 1 commit into from
May 28, 2016
Merged

Kubelet: Periodically reporting image pulling progress in log #26145

merged 1 commit into from
May 28, 2016

Conversation

Random-Liu
Copy link
Member

@Random-Liu Random-Liu commented May 24, 2016 •
edited
Loading

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.

Analytics

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

@Random-Liu Random-Liu added area/kubelet sig/node Categorizes an issue or PR as relevant to SIG Node. labels May 24, 2016
@Random-Liu Random-Liu mentioned this pull request May 24, 2016
Closed
22 tasks
@k8s-github-robot 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 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
@ncdc
Copy link
Member

ncdc commented May 24, 2016

I think this is worth a release note. WDYT?

@dchen1107 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
Copy link
Member

+1 on release note.

@dchen1107 dchen1107 assigned dchen1107 and unassigned yujuhong May 24, 2016
@dchen1107 dchen1107 added this to the v1.3 milestone May 24, 2016
@dchen1107
Copy link
Member

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
yujuhong reviewed May 24, 2016
View reviewed changes
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())
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

ACK.

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Changed to "Stop pulling image".

@Random-Liu
Copy link
Member Author

Random-Liu commented May 24, 2016 •
edited
Loading

@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
Copy link
Contributor

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.

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

ncdc commented May 24, 2016

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

@Random-Liu
Copy link
Member Author

Random-Liu commented May 24, 2016 •
edited
Loading

@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
Copy link
Member

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
vishh reviewed May 24, 2016
View reviewed changes
pkg/kubelet/dockertools/kube_docker_client.go
ticker := time.NewTicker(p.interval)
defer ticker.Stop()
for {
// TODO(random-liu): Report as events.
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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

Copy link
Member Author

@Random-Liu Random-Liu May 24, 2016 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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

@Random-Liu
Copy link
Member Author

@k8s-bot test this issue #26004.

@Random-Liu
Copy link
Member Author

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
Copy link
Member Author

@k8s-bot test this issue #25967.

@dchen1107
Copy link
Member

LGTM

@dchen1107 dchen1107 added the lgtm "Looks good to me", indicates that a PR is ready to be merged. label May 25, 2016
@yujuhong yujuhong mentioned this pull request May 25, 2016
Closed
@Random-Liu 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
Copy link

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

@k8s-bot
Copy link

k8s-bot commented May 28, 2016

GCE e2e build/test passed for commit 151d0ab.

@k8s-github-robot
Copy link

Automatic merge from submit-queue

@k8s-github-robot k8s-github-robot merged commit 344f26a into kubernetes:master May 28, 2016
@Random-Liu Random-Liu deleted the image-pulling-progress branch May 29, 2016 04:27
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Reviewers
No reviews
Assignees

@dchen1107 dchen1107

Labels
area/kubelet lgtm "Looks good to me", indicates that a PR is ready to be merged. release-note Denotes a PR that will be considered when it comes time to generate release notes. sig/node Categorizes an issue or PR as relevant to SIG Node. size/M Denotes a PR that changes 30-99 lines, ignoring generated files.
Projects
None yet
Milestone
v1.3
Development

Successfully merging this pull request may close these issues.
8 participants
@Random-Liu @ncdc @dchen1107 @yujuhong @k8s-github-robot @k8s-bot @vishh @googlebot