initialize logging after flag parsing + refactor commands #105076

pohly · 2021-09-16T17:37:26Z

What type of PR is this?

/kind bug

What this PR does / why we need it:

It wasn't documented that InitLogs already uses the log flush frequency, so
some commands have called it before parsing (for example, kubectl in the
original code for logs.go). The --log-flush-frequency flag never had an effect
in such commands.

Other fixes:

Print usage text before error to keep the error visible in the console when the
usage text is long, but only print the usage text if the error actually was for
flag parsing.
More commands use hyphens instead of underscores in their command line.
Parameters with underscores are still accepted.
The validation error for kube-apiserver --logging-format=json --add-dir-header now references add-dir-header instead of add_dir_header.
--log-flush-frequency is not listed anymore in the --logging-format flag's
non-default formats don't honor these flags usage text because it will also
work for non-default formats once it is needed.
cmd/kubelet: the description of --logging-format uses hyphens instead of
underscores for the flags, which now matches what the command is using.
staging/src/k8s.io/component-base/logs/example/cmd: added logging flags.
apiextensions-apiserver, kube-aggregator, sample-apiserver: they no longer
print useless stack traces for main and goroutines when command line parsing fails;
however, they also don't do that for other errors

Which issue(s) this PR fixes:

There's no bug open for this as far as I know. I found the problem while refactoring the code.

It fixes some things discovered while working the code:

Fixes: #105244

Special notes for your reviewer:

This turned into a major refactoring. Future changes for deprecating klog flags should become simpler.

Does this PR introduce a user-facing change?

`--log-flush-frequency` had no effect in several commands or was missing. Help and warning texts were not always using the right format for a command (`add_dir_header` instead of `add-dir-header`). Fixing this included cleaning up flag handling in component-base/logs: that package no longer adds flags to the global flag sets. Commands which want the klog and --log-flush-frequency flags must explicitly call logs.AddFlags; the new cli.Run does that for commands. That helper function also covers flag normalization and printing of usage and errors in a consistent way (print usage text first if parsing failed, then the error).

pohly · 2021-09-16T17:37:55Z

/sig instrumentation

caesarxuchao · 2021-09-16T20:12:38Z

/remove-sig api-machinery

dashpole · 2021-09-20T17:20:12Z

staging/src/k8s.io/component-base/logs/logs.go

+	go flushForever()
+}
+
+func flushForever() {


how does this differ from wait.Forever?

wait.Forever is passed the period once and value changes don't have an effect. This new code looks at the current period each time it needs to decide how long to sleep, therefore changes in that value have an effect.

Oh, now I get what you are doing. Can you add something to that effect to the description of flushForever?

For my knowledge, why/how would someone re-configure a flag? Aren't flags only set once?

Usually yes, although that isn't required. The same flag set could also be used multiple times. The main reason for this change is that the logging is initialized in main() (which makes sense - the sooner the better) and flag parsing happens at a later time when the goroutine is already running.

I've added a comment explaining this.

Should we just require InitLogs to be called after flag parsing? We can recommend calling defer logs.FlushLogs() in main() ASAP to capture logs for cases where logging isn't setup yet.

I had considered that, but came to the conclusion that enhancing the implementation is going to be simpler than checking and modifying all places where InitLogs is called.

I mean... I lean towards the flush frequency not being configurable after startup. How many places would we have to change?

I just counted 19, in various parts of the code base. Simply from a practical point of view I don't look forward to modify all of those.

But it's not just that. I think the current API with InitLogs being called as early as possible makes sense. It's easy to use and review in commands ("InitLogs and FlushLogs called in main()? Okay, done."). In the package, it gives us an opportunity to make some changes before log messages are emitted.

dashpole · 2021-09-20T17:26:07Z

staging/src/k8s.io/component-base/logs/logs.go

+	return g.duration.String()
+}
+
+func (g *guardedDuration) Set(value string) error {


Does this implement a particular interface? Or why are these functions needed?

They implement flag.Value resp. pflag.Value methods. There's a type assertion further down (var _ pflag.Value = &guardedDuration{}). Shall I call that out already as method comment ("Set implements flag.Value.Set", etc.)?

Ah. I just missed it.

pohly

Thanks for looking at this. 👍

pohly · 2021-09-20T18:07:15Z

staging/src/k8s.io/component-base/logs/logs.go

+	go flushForever()
+}
+
+func flushForever() {


wait.Forever is passed the period once and value changes don't have an effect. This new code looks at the current period each time it needs to decide how long to sleep, therefore changes in that value have an effect.

pohly · 2021-09-20T18:07:19Z

staging/src/k8s.io/component-base/logs/logs.go

+	return g.duration.String()
+}
+
+func (g *guardedDuration) Set(value string) error {


They implement flag.Value resp. pflag.Value methods. There's a type assertion further down (var _ pflag.Value = &guardedDuration{}). Shall I call that out already as method comment ("Set implements flag.Value.Set", etc.)?

pohly · 2021-09-21T11:18:21Z

/retest

pohly · 2021-09-21T19:24:15Z

Or another alternative: considering that the --log-flush-frequency flag hasn't worked (ever?) without anyone noticing, perhaps we can deprecate it together with the klog flags? I consider it useful, but not useful enough to justify changing how InitLogs works.

@serathius @thockin: any comments?

thockin · 2021-09-21T19:43:15Z

I think that flag was added for completeness but never exercised (obv.).

Logging before flag parsing is problematic for a million reasons.

My feeling is that this is now bordering on overly-encapsulated. This flag doesn't mean anything for many log impls so "less is more". We should push the configuration of logging toward main() and if we want to offer a default impl, do that in a distinct pkg.

serathius · 2021-09-30T17:31:26Z

We historically merged such changes, but we need to make sure that we have enough time in release cycle to detect such any issues that arise and fix. This means that we need to merge this change early or wait for tests.

So you think it is too late for 1.23?

Don't know, we should ask root level approvers for that (assuming that you prefer to go through one approver vs approver per binary). @dims what's your opinion on this?

serathius · 2021-09-30T17:33:47Z

Thanks for running manual tests, my main worry was about about human error, but included script should really help with that. It should allow reviewers/approver verify results on their own.

pohly · 2021-09-30T18:17:32Z

/test pull-kubernetes-node-e2e-containerd

thockin · 2021-09-30T23:15:52Z

Can we do a followup issue/PR(s) to add automated tests? I don't feel like this is THAT dangerous (famous last words?) to warrant abandoning it, given that we've NEVER had tests on this...

pohly · 2021-10-01T06:12:06Z

Can we do a followup issue/PR(s) to add automated tests?

I can't commit to working on that. For now I've filed #105392.

pohly · 2021-10-01T06:12:42Z

/test pull-kubernetes-node-e2e-containerd

thockin · 2021-10-01T19:01:21Z

I'll go ahead and approve this but leave a hold - @serathius if you want to discuss more, we can, but @pohly I think we can call for lazy-consensus. If no major objections before @pohly EOD Tuesday, (Europe time, I think) you (@pohly) can drop the hold.

Fair?

Thanks!

/lgtm
/approve
/hold

k8s-ci-robot · 2021-10-01T19:04:56Z

[APPROVALNOTIFIER] This PR is APPROVED

This pull-request has been approved by: pohly, thockin

The full list of commands accepted by this bot can be found here.

The pull request process is described here

Needs approval from an approver in each of these files:

~~cmd/cloud-controller-manager/OWNERS~~ [thockin]
~~cmd/kube-apiserver/OWNERS~~ [thockin]
~~cmd/kube-controller-manager/OWNERS~~ [thockin]
~~cmd/kube-proxy/OWNERS~~ [thockin]
~~cmd/kube-scheduler/OWNERS~~ [thockin]
~~cmd/kubectl/OWNERS~~ [thockin]
~~cmd/kubectl-convert/OWNERS~~ [thockin]
~~cmd/kubelet/OWNERS~~ [thockin]
~~cmd/kubemark/OWNERS~~ [thockin]
~~staging/publishing/OWNERS~~ [thockin]
~~staging/src/k8s.io/apiextensions-apiserver/OWNERS~~ [thockin]
~~staging/src/k8s.io/cloud-provider/OWNERS~~ [thockin]
~~staging/src/k8s.io/component-base/cli/OWNERS~~ [thockin]
~~staging/src/k8s.io/component-base/logs/OWNERS~~ [thockin]
~~staging/src/k8s.io/kube-aggregator/OWNERS~~ [thockin]
~~staging/src/k8s.io/kubectl/OWNERS~~ [thockin]
~~staging/src/k8s.io/pod-security-admission/OWNERS~~ [thockin]
~~staging/src/k8s.io/sample-apiserver/OWNERS~~ [thockin]
~~test/OWNERS~~ [thockin]
~~vendor/OWNERS~~ [thockin]

Approvers can indicate their approval by writing /approve in a comment
Approvers can cancel approval by writing /approve cancel in a comment

serathius · 2021-10-01T19:24:47Z

I think that we should be ok with validating this using the script, hope that noone will break us before this is merged. I think we are good to go.
This is an awesome improvement! @pohly
/unhold

k8s-ci-robot · 2021-10-01T20:27:27Z

@pohly: The following test failed, say /retest to rerun all failed tests or /retest-required to rerun all mandatory failed tests:

Test name	Commit	Details	Required	Rerun command
pull-kubernetes-node-kubelet-serial	e6940ea312999cc231512bbed9e94d7aea8f9331	link	false	`/test pull-kubernetes-node-kubelet-serial`

Full PR test history. Your PR dashboard. Please help us cut down on flakes by linking to an open issue when you hit one in your PR.

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.

pohly · 2021-10-01T20:27:50Z

/retest

k8s-ci-robot added sig/instrumentation Categorizes an issue or PR as relevant to SIG Instrumentation. and removed do-not-merge/needs-sig Indicates an issue or PR lacks a `sig/foo` label and requires one. labels Sep 16, 2021

k8s-ci-robot requested review from dashpole and dixudx September 16, 2021 17:38

pohly force-pushed the log-flush-frequency-bug branch from 1ee0c2f to 12e55cf Compare September 16, 2021 17:58

pohly mentioned this pull request Sep 16, 2021

deprecate klog flags #105042

Merged

pohly force-pushed the log-flush-frequency-bug branch from 12e55cf to 3dbb7a4 Compare September 16, 2021 19:16

k8s-ci-robot removed the sig/api-machinery Categorizes an issue or PR as relevant to SIG API Machinery. label Sep 16, 2021

dashpole reviewed Sep 20, 2021

View reviewed changes

pohly commented Sep 20, 2021

View reviewed changes

pohly force-pushed the log-flush-frequency-bug branch from 3dbb7a4 to b5719b0 Compare September 20, 2021 19:38

k8s-ci-robot added the sig/api-machinery Categorizes an issue or PR as relevant to SIG API Machinery. label Sep 20, 2021

pohly mentioned this pull request Oct 1, 2021

automated testing of command line interfaces #105392

Closed

k8s-ci-robot added the do-not-merge/hold Indicates that a PR should not merge because someone has issued a /hold command. label Oct 1, 2021

k8s-ci-robot assigned thockin Oct 1, 2021

k8s-ci-robot added the lgtm "Looks good to me", indicates that a PR is ready to be merged. label Oct 1, 2021

k8s-ci-robot added the approved Indicates a PR has been approved by an approver from all required OWNERS files. label Oct 1, 2021

k8s-ci-robot removed the do-not-merge/hold Indicates that a PR should not merge because someone has issued a /hold command. label Oct 1, 2021

k8s-ci-robot merged commit 82da9bd into kubernetes:master Oct 1, 2021

SIG Node PR Triage automation moved this from Needs Reviewer to Done Oct 1, 2021

k8s-ci-robot added this to the v1.23 milestone Oct 1, 2021

SIG Auth Old automation moved this from Needs Triage to Closed / Done Oct 1, 2021

This was referenced Oct 3, 2021

replace klog.Fatal and os.Exit for defer funcs #102231

Open

Fix(kube-apiserver): return error instead of os.Exit when something goes wrong #104751

Closed

Fix(cloud-controller-manager): return error instead of os.Exit when something goes wrong #104752

Closed

serathius mentioned this pull request Nov 1, 2021

Remove klog specific command line arguments from Kubernetes components kubernetes/enhancements#2845

Closed

20 tasks

pohly mentioned this pull request Nov 2, 2021

component-base: move v/vmodule/log-flush-frequency into LoggingConfiguration #106090

Merged

MadhavJivrajani mentioned this pull request Dec 14, 2021

Malformed error messages #107012

Closed

mandre mentioned this pull request Jan 10, 2022

update kubernetes dependency to v1.23 kubernetes/cloud-provider-openstack#1716

Merged

zhiweiyin318 mentioned this pull request Mar 3, 2022

Klog flags disppeared because of component-base updates. open-cluster-management-io/ocm#31

Closed

SataQiu mentioned this pull request May 23, 2022

Scheduler: refactor command to use the new component-base cli framework kubernetes-sigs/scheduler-plugins#378

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

initialize logging after flag parsing + refactor commands #105076

initialize logging after flag parsing + refactor commands #105076

pohly commented Sep 16, 2021 •

edited

pohly commented Sep 16, 2021

caesarxuchao commented Sep 16, 2021

dashpole Sep 20, 2021

pohly Sep 20, 2021

dashpole Sep 20, 2021

pohly Sep 20, 2021

dashpole Sep 20, 2021

pohly Sep 20, 2021

dashpole Sep 21, 2021

pohly Sep 21, 2021

dashpole Sep 20, 2021

pohly Sep 20, 2021

dashpole Sep 20, 2021

pohly left a comment

pohly Sep 20, 2021

pohly Sep 20, 2021

pohly commented Sep 21, 2021

pohly commented Sep 21, 2021

thockin commented Sep 21, 2021

serathius commented Sep 30, 2021

serathius commented Sep 30, 2021

pohly commented Sep 30, 2021

thockin commented Sep 30, 2021

pohly commented Oct 1, 2021

pohly commented Oct 1, 2021

thockin commented Oct 1, 2021

k8s-ci-robot commented Oct 1, 2021

serathius commented Oct 1, 2021

k8s-ci-robot commented Oct 1, 2021 •

edited

pohly commented Oct 1, 2021

initialize logging after flag parsing + refactor commands #105076

initialize logging after flag parsing + refactor commands #105076

Conversation

pohly commented Sep 16, 2021 • edited

What type of PR is this?

What this PR does / why we need it:

Which issue(s) this PR fixes:

Special notes for your reviewer:

Does this PR introduce a user-facing change?

pohly commented Sep 16, 2021

caesarxuchao commented Sep 16, 2021

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

Choose a reason for hiding this comment

Choose a reason for hiding this comment

pohly left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

pohly commented Sep 21, 2021

pohly commented Sep 21, 2021

thockin commented Sep 21, 2021

serathius commented Sep 30, 2021

serathius commented Sep 30, 2021

pohly commented Sep 30, 2021

thockin commented Sep 30, 2021

pohly commented Oct 1, 2021

pohly commented Oct 1, 2021

thockin commented Oct 1, 2021

k8s-ci-robot commented Oct 1, 2021

serathius commented Oct 1, 2021

k8s-ci-robot commented Oct 1, 2021 • edited

pohly commented Oct 1, 2021

pohly commented Sep 16, 2021 •

edited

k8s-ci-robot commented Oct 1, 2021 •

edited