[Federation] Print out status updates while `kubefed init` is running #41849

perotinus · 2017-02-21T23:55:28Z

This is not an ideal final state–it does not address the appearance of hanging during long-running commands, for example–but it provides some level of information when the operations are successful.

See #41725.

Release note:

Prints out status updates when running `kubefed init`

k8s-ci-robot · 2017-02-21T23:55:28Z

Hi @perotinus. Thanks for your PR.

I'm waiting for a kubernetes member to verify that this patch is reasonable to test. If it is, they should reply with @k8s-bot ok to test on its own line. Until that is done, I will not automatically test new commits in this PR, but the usual testing commands by org members will still work. Regular contributors should join the org to skip this step.

Instructions for interacting with me using PR comments are available here. If you have questions or suggestions related to my behavior, please file an issue against the kubernetes/test-infra repository. I understand the commands that are listed here.

k8s-reviewable · 2017-02-21T23:55:34Z

This change is

madhusudancs · 2017-02-22T20:23:30Z

General comment for the overall change. I was thinking about doing something less verbose than this since these are user facing messages. Example:

"Creating a namespace for federation system components..."

you wait until the operation is done and then on the same line say "Ok" or "Done".

"Creating a namespace for federation system components...Done"

Something like that.

Also, don't you need linebreaks at the end of each fmt.Fprintf() string?

Review status: 0 of 2 files reviewed at latest revision, all discussions resolved.

Comments from Reviewable

irfanurrehman · 2017-02-24T13:39:51Z

a discussion (no related file):
I dont think the user really needs to know all the steps explicitly under the hood. The problem was that there was no indication of progress, at all, whatsoever.
My suggestion (since you have already added these prints) would be to just change the verbosity level of minor steps (might be useful for debugging) , to skip the minor steps at default verbosity. So by default following would be printed:
1 - created namespace . . Done
2 - created service . . Done
3 - deployed api server . . Done
4 - deployed controller manager . .Done
The above are not time consuming and would happen almost immediately (seconds).

The last message could be
Waiting for the control plane to come up . . . . . . . . . . Done!
The ". . . " as Madhu suggested could be timed prints (for example 2 seconds)

Comments from Reviewable

perotinus · 2017-02-24T22:52:58Z

Review status: 0 of 2 files reviewed at latest revision, 1 unresolved discussion.

a discussion (no related file):

Previously, irfanurrehman wrote…

I dont think the user really needs to know all the steps explicitly under the hood. The problem was that there was no indication of progress, at all, whatsoever.
My suggestion (since you have already added these prints) would be to just change the verbosity level of minor steps (might be useful for debugging) , to skip the minor steps at default verbosity. So by default following would be printed:
1 - created namespace . . Done
2 - created service . . Done
3 - deployed api server . . Done
4 - deployed controller manager . .Done
The above are not time consuming and would happen almost immediately (seconds).

The last message could be
Waiting for the control plane to come up . . . . . . . . . . Done!
The ". . . " as Madhu suggested could be timed prints (for example 2 seconds)

Thanks for the feedback! Yes, that makes a lot of sense. I've created some simpler messages that will always print (and fixed the line breaks), and moved some of the more-detailed messages to verbose logs. WDYT?

Comments from Reviewable

perotinus · 2017-02-24T22:53:15Z

Ok, I've made these updates. Thanks!

Review status: 0 of 2 files reviewed at latest revision, 1 unresolved discussion.

Comments from Reviewable

perotinus · 2017-02-25T00:03:26Z

@madhusudancs @irfanurrehman PTAL?

madhusudancs · 2017-02-25T20:53:12Z

Reviewed 2 of 2 files at r2.
Review status: all files reviewed at latest revision, 11 unresolved discussions.

a discussion (no related file):

Previously, perotinus (Jonathan MacMillan) wrote…

Thanks for the feedback! Yes, that makes a lot of sense. I've created some simpler messages that will always print (and fixed the line breaks), and moved some of the more-detailed messages to verbose logs. WDYT?

I have left a few comments. None of those are critical or urgent. So I would recommend making all those changes in a separate follow up PR.

In the cases where you print the messages to STDOUT, you skip logging them. I think it is worth adding an INFO log for those creating ... steps too. I understand why you are doing this, but if you don't have these INFO logs, people who grep for "INFO" don't see the messages printed to STDOUT.

It looks good to me otherwise. However, I would like @irfanurrehman to make another pass and add the LGTM label when he is satisfied.

federation/pkg/kubefed/init/init.go, line 241 at r2 (raw file):

	// 1.
	fmt.Fprint(cmdOut, "Creating a namespace for federation system components... ")

Print the namespace in the message Creating namespace "federation-system" for federation system components...

federation/pkg/kubefed/init/init.go, line 246 at r2 (raw file):

		return err
	}
	fmt.Fprint(cmdOut, "done\n")

Use fmt.Fprintln()(https://golang.org/pkg/fmt/#Fprintln) instead. It's more readable. Also change all other occurrences.

federation/pkg/kubefed/init/init.go, line 249 at r2 (raw file):

	// 2.
	fmt.Fprint(cmdOut, "Creating federation control plane objects (service, credentials, persistent volume claim)... ")

I like this simplification a lot. However, I think service deserves its own message. It is one of the slowest operations in the entire init command, probably as slow as or slower than waiting for the control plane pods to come up.

federation/pkg/kubefed/init/init.go, line 270 at r2 (raw file):

	// 4.
	glog.V(4).Info("Creating an entry in the kubeconfig file with the certificate and credential data")

What's happening here is creation of kubeconfig data to be populated in a secret. While your message is correct if one reads it very carefully, it might also cause some confusion. I would just write this as Creating credentials secret for federation controller manager

federation/pkg/kubefed/init/init.go, line 275 at r2 (raw file):

		return err
	}
	glog.V(4).Info("kubeconfig successfully updated")

Same as above.

federation/pkg/kubefed/init/init.go, line 298 at r2 (raw file):

	// 6.
	fmt.Fprint(cmdOut, "Creating federation component deployments...")

I would just say Creating federation control plane components...

federation/pkg/kubefed/init/init.go, line 332 at r2 (raw file):

	// 8.
	fmt.Fprint(cmdOut, "Updating kubeconfig... ")

No log here?

federation/pkg/kubefed/init/init.go, line 349 at r2 (raw file):

	if err != nil {
		return err
	}

Log here?

federation/pkg/kubefed/init/init.go, line 353 at r2 (raw file):

	if !i.options.dryRun {
		fmt.Fprint(cmdOut, "Waiting for federation control plane to come up... ")

No log here?

federation/pkg/kubefed/init/init.go, line 360 at r2 (raw file):

		}
		err = waitSrvHealthy(config, i.commonOptions.Name, i.commonOptions.Kubeconfig)
		fmt.Fprint(cmdOut, "done\n")

log here?

Comments from Reviewable

irfanurrehman · 2017-02-26T08:58:41Z

/lgtm

Except one thing (add it as part of follow up PR) I think everything is covered. (provided you would take the additional comments from @madhusudancs in a follow up PR).
About printing ". . ", I mentioned them to be timed prints (for example with a wait of 2 seconds each), rather then they being part of the original print.
The intention is, if the step is taking long, it will sort of give a notion of a console status bar moving .. :)
You can have a common function (or a goroutine with some channel to flag when to start and when to stop) and call it at all steps.

irfanurrehman · 2017-02-26T09:08:45Z

@perotinus, please run hack/update-bazel.sh to update the bazel build files and update the commit, I will lgtm it again.

madhusudancs · 2017-02-26T09:32:05Z

/approve

Review status: all files reviewed at latest revision, 11 unresolved discussions, some commit checks failed.

Comments from Reviewable

madhusudancs · 2017-02-27T20:39:17Z

/lgtm

perotinus · 2017-02-27T21:45:11Z

@madhusudancs I ran hack/update-bazel.sh and need approval again. Can you oblige?

Thanks!

perotinus · 2017-02-27T22:10:28Z

@madhusudancs Can you poke the robot again? The failures look like they were related to the BUILD file issue.

perotinus · 2017-03-02T18:39:19Z

Review status: 0 of 3 files reviewed at latest revision, 11 unresolved discussions.

a discussion (no related file):