builders: simplified image progress reporting #9212

csrwng · 2016-06-07T23:57:18Z

Refactors the pull progress writer from 'oc cluster up' to work with push as well.
Updates the output of s2i and docker builders to report push progress as part of the regular build output.

Fixes #9138

csrwng · 2016-06-07T23:57:59Z

@bparees ptal

bparees · 2016-06-08T02:05:37Z

this will make @johnkeck very happy.

Can you put a sample of the output (at default log levels) in this PR?

it looks like it'll fallback to the existing output behavior at higher log levels? (i think that's good).

Also what are the odds of docker changing the json status format and completely breaking this? do they make any statements around the api stability of it?

bparees · 2016-06-08T02:09:47Z

pkg/build/builder/sti.go

@@ -265,8 +267,8 @@ func (s *S2IBuilder) Build() error {
 		} else {
 			glog.V(2).Infof("No push secret provided")
 		}
-		glog.V(1).Infof("Pushing %s image ...", pushTag)
-		if err := pushImage(s.dockerClient, pushTag, pushAuthConfig); err != nil {
+		fmt.Fprintf(s.out, "Pushing %s image ...\n", pushTag)


why is this changing from glog? (which is not really glog anyway it's the wrapper glog clayton created)

because I want it to be printed regardless of the log level, given that image push progress is going to be written to the same output stream.

V(0) should handle that.

(even V(1) is always enabled unless someone did something weird)

cool, will update

V(1) wasn't showing anything for me

i don't understand that, our default log level is "2" i believe, you should see any glog.V(2) and below messages.... what messages were you seeing?

When I start with no loglevel set ('oc cluster up'), I get this (no v(1) messages):

... Copying built war files into /wildfly/standalone/deployments for later deployment... ...done Waiting to push 12 layers Pushing 4 layers ( 10%), 1 pending Pushing 5 layers ( 16%) Pushing 4 layers ( 24%) Pushing 4 layers ( 50%) Pushing 3 layers ( 49%) Pushing 3 layers ( 77%) Pushing 2 layers ( 73%) Pushing 1 layer (100%)

so w/ existing master, if i do openshift start w/ no loglevel, i get this message:

Creating a new S2I builder with build config: blah blah blah.....

which is logged at level 2:

glog.V(2).Infof("Creating a new S2I builder with build config: %#v\n", describe.DescribeConfig(config))

csrwng · 2016-06-08T14:00:38Z

Can you put a sample of the output (at default log levels) in this PR?

Pushing 172.30.212.248:5000/myproject/openshift-jee-sample:latest image ...
Waiting to push 12 layers
Pushing 2 layers ( 83%)
Pushing 1 layer  (100%)
Successfully pushed 172.30.212.248:5000/myproject/openshift-jee-sample:latest

it looks like it'll fallback to the existing output behavior at higher log levels? (i think that's good).

yes

Also what are the odds of docker changing the json status format and completely breaking this? do they make any statements around the api stability of it?

Not sure, there's no statement about its stability in the official API doc, but given that it hasn't changed since as far back as I know of (docker 1.4), I'd say it's pretty stable.

csrwng · 2016-06-08T16:42:45Z

Updated with comments so far.
@bparees, I wanted your opinion on the progress messages, currently, I have something like:

Waiting to push 12 layers
Pushing 4 layers ( 10%), 1 pending
Pushing 5 layers ( 16%)
Pushing 4 layers ( 24%)
Pushing 4 layers ( 50%)
Pushing 3 layers ( 49%)
Pushing 3 layers ( 77%)
Pushing 2 layers ( 73%)
Pushing 1 layer  (100%)

At any given point, I have 3 counts of layers ... # pending, # being pushed, #completed. Should I also include the # of completed layers in the status?

Also, the percent that I'm showing is the percent progress of layers actively being pushed (not total percent). Would it make more sense if I have something like:

Pushed  16% of 5 layers, 7 complete, 1 waiting
Pushed  24% of 4 layers, 8 complete
Pushed  50% of 4 layers, 8 complete

bparees · 2016-06-08T16:46:32Z

Not sure, there's no statement about its stability in the official API doc, but given that it hasn't changed since as far back as I know of (docker 1.4), I'd say it's pretty stable.

does it work with docker1.10? if so i'm convinced since they broke everything else in 1.10 :)

csrwng · 2016-06-08T16:48:00Z

does it work with docker1.10? if so i'm convinced since they broke everything else in 1.10 :)

amazingly it does :) ... I've tried both 1.10 and 1.11

bparees · 2016-06-08T16:48:52Z

Also, the percent that I'm showing is the percent progress of layers actively being pushed (not total percent). Would it make more sense if I have something like:

yes i like that second format that shows the count of layers in each status (waiting, complete, etc).

what i'm still not clear on is what the percentage represents. percentage of the total data for layers that are currently being pushed? percentage of the total data including layers that are waiting? something else entirely? (percentage of the number of layers?)

csrwng · 2016-06-08T16:49:38Z

what i'm still not clear on is what the percentage represents. percentage of the total data for layers that are currently being pushed? percentage of the total data including layers that are waiting? something else entirely? (percentage of the number of layers?)

1 - percentage of the total data for layers that are currently being pushed

bparees · 2016-06-08T16:50:44Z

pkg/build/builder/docker.go

@@ -116,11 +116,11 @@ func (d *DockerBuilder) Build() error {
 		if authPresent {
 			glog.V(4).Infof("Authenticating Docker push with user %q", pushAuthConfig.Username)
 		}
-		glog.V(1).Infof("Pushing image %s ...", pushTag)
+		glog.V(0).Infof("Pushing image %s ...", pushTag)


not your fault but this message format and the message format in sti.go are different, can you sync them?

bparees · 2016-06-08T16:52:25Z

1 - percentage of the total data for layers that are currently being pushed

that means the percentage could go down as layers that were waiting enter the pushing(or pulling) state, right? that seems bad/confusing for a user.

csrwng · 2016-06-08T16:54:15Z

that means the percentage could go down as layers that were waiting enter the pushing(or pulling) state, right? that seems bad/confusing for a user.

right, that's why I wanted to word it in a way that would be non-confusing. I could try to get a cumulative percent, but it's harder. I have no way of knowing the size of layers that are pending until they actually start pushing.

liggitt · 2016-06-08T16:56:49Z

if you know the number of layers up front, can you slice the 100% by number of layers, then slice each subsection by percentage of layer size?

csrwng · 2016-06-08T17:00:38Z

@liggitt that's a good idea ... I can try doing that. It would at least make it more understandable.

csrwng · 2016-06-08T18:28:16Z

udpated using @liggitt's suggestion and also updated the pull call in @smarterclayton's dockerfile builder.

csrwng · 2016-06-08T18:37:55Z

dockerbuild output:

14:22 $ oc ex dockerbuild . openshift/origin-sti-builder
--> Image openshift/origin was not found, pulling ...
--> Downloading 1 layer  ( 25%), 3 pending
--> Downloading 2 layers ( 71%), 2 complete
--> Extracting
--> FROM openshift/origin
--> LABEL io.k8s.display-name="OpenShift Origin S2I Builder"       io.k8s.description="This is a component of OpenShift Origin and is responsible for executing source-to-image (s2i) image builds."
--> ENTRYPOINT ["/usr/bin/openshift-sti-build"]
--> Committing changes to openshift/origin-sti-builder ...
--> Done

oc cluster up output:

-- Checking for openshift/origin:latest image ...
   Pulling image openshift/origin:latest
   Preparing to pull 4 layers
   Downloading 3 layers ( 28%), 1 complete
   Downloading 3 layers ( 41%), 1 complete
   Downloading 3 layers ( 53%), 1 complete
   Downloading 3 layers ( 66%), 1 complete
   Downloading 3 layers ( 79%), 1 complete
   Downloading 2 layers ( 83%), 2 complete
   Downloading 2 layers ( 93%), 2 complete
   Downloading 1 layer  ( 98%), 3 complete
   Extracting
   Image pull comlete

builder output:

Pushing image 172.30.205.173:5000/myproject/openshift-jee-sample:latest ...
Preparing to push 12 layers
Pushing 4 layers ( 78%), 8 complete
Pushing 3 layers ( 92%), 9 complete
Pushing 1 layer  ( 99%), 11 complete
Successfully pushed 172.30.205.173:5000/myproject/openshift-jee-sample:latest

smarterclayton · 2016-06-08T20:35:53Z

[test]

On Wed, Jun 8, 2016 at 2:37 PM, Cesar Wong [email protected] wrote:

dockerbuild output:

14:22 $ oc ex dockerbuild . openshift/origin-sti-builder
--> Image openshift/origin was not found, pulling ...
--> Downloading 1 layer ( 25%), 3 pending
--> Downloading 2 layers ( 71%), 2 complete
--> Extracting
--> FROM openshift/origin
--> LABEL io.k8s.display-name="OpenShift Origin S2I Builder" io.k8s.description="This is a component of OpenShift Origin and is responsible for executing source-to-image (s2i) image builds."
--> ENTRYPOINT ["/usr/bin/openshift-sti-build"]
--> Committing changes to openshift/origin-sti-builder ...
--> Done

oc cluster up output:

-- Checking for openshift/origin:latest image ...
Pulling image openshift/origin:latest
Preparing to pull 4 layers
Downloading 3 layers ( 28%), 1 complete
Downloading 3 layers ( 41%), 1 complete
Downloading 3 layers ( 53%), 1 complete
Downloading 3 layers ( 66%), 1 complete
Downloading 3 layers ( 79%), 1 complete
Downloading 2 layers ( 83%), 2 complete
Downloading 2 layers ( 93%), 2 complete
Downloading 1 layer ( 98%), 3 complete
Extracting
Image pull comlete

builder output:

Pushing image 172.30.205.173:5000/myproject/openshift-jee-sample:latest ...
Preparing to push 12 layers
Pushing 4 layers ( 78%), 8 complete
Pushing 3 layers ( 92%), 9 complete
Pushing 1 layer ( 99%), 11 complete
Successfully pushed 172.30.205.173:5000/myproject/openshift-jee-sample:latest

—
You are receiving this because you were mentioned.
Reply to this email directly, view it on GitHub
#9212 (comment),
or mute the thread
https://github.com/notifications/unsubscribe/ABG_p_4yW0v-GlgBtk1DZk0mJ1rDbsTOks5qJwwGgaJpZM4IweSz
.

smarterclayton · 2016-06-08T20:36:45Z

pkg/util/docker/dockerfile/builder/client.go

@@ -17,6 +17,8 @@ import (
 	"github.com/fsouza/go-dockerclient/external/github.com/docker/docker/pkg/archive"
 	"github.com/fsouza/go-dockerclient/external/github.com/docker/docker/pkg/fileutils"
 	"github.com/golang/glog"
+
+	"github.com/openshift/origin/pkg/cmd/util/imageprogress"


Unfortunately you can't take this dependency because we are going to move the builder out of our repo. You can put image progress as a sub package of this code though.

ok, will move

csrwng · 2016-06-08T20:41:31Z

Updating to new format suggested by @liggitt. I think I like it better:

Pushing image 172.30.225.168:5000/myproject/openshift-jee-sample:latest ...
Pushed 0/12 layers, 0% complete
Pushed 8/12 layers, 74% complete
Pushed 9/12 layers, 86% complete
Pushed 10/12 layers, 97% complete
Successfully pushed 172.30.225.168:5000/myproject/openshift-jee-sample:latest

-- Checking for openshift/origin:latest image ...
   Pulling image openshift/origin:latest
   Pulled 1/4 layers, 25% complete
   Pulled 1/4 layers, 61% complete
   Pulled 3/4 layers, 98% complete
   Extracting
   Image pull comlete

smarterclayton · 2016-06-08T20:48:19Z

One minor nit (because of your output) - we don't need to say where we
pushed to a second time.

On Wed, Jun 8, 2016 at 4:41 PM, Cesar Wong [email protected] wrote:

Updating to new format suggested by @liggitt https://github.com/liggitt.
I think I like it better:

Pushing image 172.30.225.168:5000/myproject/openshift-jee-sample:latest ...
Pushed 0/12 layers, 0% complete
Pushed 8/12 layers, 74% complete
Pushed 9/12 layers, 86% complete
Pushed 10/12 layers, 97% complete
Successfully pushed 172.30.225.168:5000/myproject/openshift-jee-sample:latest

Pushing image 172.30.225.168:5000/myproject/openshift-jee-sample:latest ...
Pushed 0/12 layers, 0% complete
Pushed 8/12 layers, 74% complete
Pushed 9/12 layers, 86% complete
Pushed 10/12 layers, 97% complete
Successfully pushed 172.30.225.168:5000/myproject/openshift-jee-sample:latest

—
You are receiving this because you were mentioned.
Reply to this email directly, view it on GitHub
#9212 (comment),
or mute the thread
https://github.com/notifications/unsubscribe/ABG_pw941HN-0mhdey1zk3Qfv7trzxAeks5qJyj-gaJpZM4IweSz
.

bparees · 2016-06-08T21:39:13Z

pkg/build/builder/sti.go

@@ -265,7 +265,7 @@ func (s *S2IBuilder) Build() error {
 		} else {
 			glog.V(2).Infof("No push secret provided")
 		}
-		glog.V(1).Infof("Pushing %s image ...", pushTag)
+		glog.V(0).Infof("Pushing image %s ...", pushTag)


would like to see this loglevel issue sorted out before merging because ideally i'd like to reserve "0" for warnings/errors and "1" for info we always want to show.

I'll switch it back to 1 and open an issue to investigate "oc cluster up"

Opened issue #9247

csrwng · 2016-06-09T14:27:26Z

Addressed comments, latest output, thx @liggitt for your suggestions:

oc cluster up:

-- Checking for openshift/origin:latest image ...
   Pulling image openshift/origin:latest
   Pulled 1/4 layers, 25% complete
   Pulled 2/4 layers, 78% complete
   Pulled 3/4 layers, 91% complete
   Pulled 4/4 layers, 100% complete
   Extracting
   Image pull complete

build:

Pushing image 172.30.111.27:5000/myproject/simple-ruby:latest ...
Pushed 0/10 layers, 0% complete
Pushed 1/10 layers, 39% complete
Pushed 2/10 layers, 43% complete
Pushed 3/10 layers, 46% complete
Pushed 4/10 layers, 49% complete
Pushed 5/10 layers, 51% complete
Pushed 6/10 layers, 60% complete
Pushed 7/10 layers, 70% complete
Pushed 8/10 layers, 86% complete
Pushed 9/10 layers, 99% complete
Pushed 10/10 layers, 100% complete
Push successful

dockerbuild:

--> Image openshift/origin was not found, pulling ...
--> Pulled 1/4 layers, 26% complete
--> Pulled 2/4 layers, 61% complete
--> Pulled 3/4 layers, 91% complete
--> Pulled 4/4 layers, 100% complete
--> Extracting
--> FROM openshift/origin
...

bparees · 2016-06-09T14:58:11Z

pkg/bootstrap/docker/dockerhelper/helper.go

@@ -118,31 +118,11 @@ func (h *Helper) CheckAndPull(image string, out io.Writer) error {
 	}
 	glog.V(5).Infof("Image %q not found. Pulling", image)
 	fmt.Fprintf(out, "Pulling image %s\n", image)


when you go to resolve the logging issue in oc cluster up, you should change this to a glog call also.

(and all the other fmt statements in this file)

The output stream in cluster up is doing indenting for me. I also don't want the output to be log-like output since it's just a regular cli cmd. Only if you turn up the loglevel you get the glog output.

bparees · 2016-06-09T15:02:44Z

Pushed 1/10 layers, 39% complete

?

csrwng · 2016-06-09T15:05:34Z

So it's the % complete is calculated by taking the portion of completed layers + the percent progress of pulling/pushing layers.

In this case, you likely have multiple layers that are getting actively pushed with various levels of progress.

bparees · 2016-06-09T15:09:51Z

ok. lgtm.
[merge]

openshift-bot · 2016-06-09T15:40:43Z

Evaluated for origin test up to 1497ef6

openshift-bot · 2016-06-09T18:45:39Z

continuous-integration/openshift-jenkins/test ABORTED (https://ci.openshift.redhat.com/jenkins/job/test_pr_origin/4666/)

csrwng · 2016-06-10T02:52:53Z

[merge]

csrwng · 2016-06-10T15:34:30Z

[merge]

openshift-bot · 2016-06-10T18:40:24Z

continuous-integration/openshift-jenkins/merge SUCCESS (https://ci.openshift.redhat.com/jenkins/job/test_pr_origin/4728/) (Image: devenv-rhel7_4349)

smarterclayton · 2016-06-10T21:06:06Z

[merge]

On Fri, Jun 10, 2016 at 2:40 PM, OpenShift Bot [email protected]
wrote:

continuous-integration/openshift-jenkins/merge ABORTED (
https://ci.openshift.redhat.com/jenkins/job/test_pr_origin/4712/)

—
You are receiving this because you were mentioned.
Reply to this email directly, view it on GitHub
#9212 (comment),
or mute the thread
https://github.com/notifications/unsubscribe/ABG_p6nkgaIsxhMLaFG496v49F9dpSkEks5qKa-agaJpZM4IweSz
.

openshift-bot · 2016-06-10T21:10:25Z

Evaluated for origin merge up to 1497ef6

bparees reviewed Jun 8, 2016
View reviewed changes

csrwng force-pushed the image_progress branch from d16c512 to fd2a53e Compare June 8, 2016 16:34

csrwng force-pushed the image_progress branch from fd2a53e to e68933d Compare June 8, 2016 16:46

bparees reviewed Jun 8, 2016
View reviewed changes

csrwng force-pushed the image_progress branch from e68933d to 44500a9 Compare June 8, 2016 18:26

smarterclayton reviewed Jun 8, 2016
View reviewed changes

csrwng force-pushed the image_progress branch from 44500a9 to aca3c1b Compare June 8, 2016 20:38

bparees reviewed Jun 8, 2016
View reviewed changes

csrwng force-pushed the image_progress branch from aca3c1b to 65a00e3 Compare June 9, 2016 14:20

builders: simplified image progress reporting

1497ef6

csrwng force-pushed the image_progress branch from 65a00e3 to 1497ef6 Compare June 9, 2016 14:26

bparees reviewed Jun 9, 2016
View reviewed changes

openshift-bot merged commit aa31f13 into openshift:master Jun 10, 2016

csrwng deleted the image_progress branch July 19, 2016 15:34

builders: simplified image progress reporting #9212

builders: simplified image progress reporting #9212

Conversation

csrwng commented Jun 7, 2016

csrwng commented Jun 7, 2016

bparees commented Jun 8, 2016

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

csrwng commented Jun 8, 2016

csrwng commented Jun 8, 2016

bparees commented Jun 8, 2016

csrwng commented Jun 8, 2016

bparees commented Jun 8, 2016

csrwng commented Jun 8, 2016 • edited Loading

Choose a reason for hiding this comment

bparees commented Jun 8, 2016

csrwng commented Jun 8, 2016

liggitt commented Jun 8, 2016

csrwng commented Jun 8, 2016

csrwng commented Jun 8, 2016

csrwng commented Jun 8, 2016

smarterclayton commented Jun 8, 2016

Choose a reason for hiding this comment

Choose a reason for hiding this comment

csrwng commented Jun 8, 2016 • edited Loading

smarterclayton commented Jun 8, 2016

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

csrwng commented Jun 9, 2016

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

bparees commented Jun 9, 2016

csrwng commented Jun 9, 2016

bparees commented Jun 9, 2016

openshift-bot commented Jun 9, 2016

openshift-bot commented Jun 9, 2016

csrwng commented Jun 10, 2016

csrwng commented Jun 10, 2016

openshift-bot commented Jun 10, 2016 • edited Loading

smarterclayton commented Jun 10, 2016

openshift-bot commented Jun 10, 2016

csrwng commented Jun 8, 2016 •

edited

Loading

csrwng commented Jun 8, 2016 •

edited

Loading

openshift-bot commented Jun 10, 2016 •

edited

Loading