InitFlags does not reset klog configuration if application already did logging

[losipiuk]

/kind bug

What steps did you take and what happened:

1. Application uses klog.Infof()
2. Logging happens based on klog default configuration.
3. Application calls klog.InitFlags(nil) and flag.Parse(). Flags specify log file.
4. Application uses klog.Infof() again.
5. Logs are NOT appended to output file specified by flags

What did you expect to happen:

Ideally klog should properly reinitialize itself to configuration specified via flags on (4) and log from (5) should be appended to the log file.

Alternatively klog could disallows calling InitFlag() after logging was done before (panic?).
Yet this is suboptimal as one not always can prevent logging from happening before InitFlags. As logging can occur in init function of some dependent module.

Anything else you would like to add:

The source of described problem lies in behavior of createFiles (https://github.com/kubernetes/klog/blob/master/klog.go#L968). This method is called on first logging and log appenders are created then and put in logging.files array. Those are not reset later even if configuration changes.

Actually the situation is even more confusing than that. As appenders are created only for log levels up to requested one, we end up in inconsistent state of klog in following sequence of events:

1. klog.Infof
2. InitFlags
3. klog.ErrorF

Then the appenders for DEBUG and INFO will be based on default configuration. And appender for ERROR will take configuration changes from flags into account.

I spotted the problem when playing with flag related to log file but possibly one can run into issues with other flags too.

[vincepri]

Unless I'm mistaken logs.InitFlags() should always be called first, before any logging happens. I do agree that the behavior you describe is a little confusing though.

[DirectXMan12]

yeah, initflags should always be one of the first things you call in your program.

[losipiuk]

yeah, initflags should always be one of the first things you call in your program.

Yeah - and it was in my case - the logging was done deep in the stack in the function called from one of the module Init() funs (which are called before main() entrypoint).

[DirectXMan12]

ah, hmm... that's problematic

[fejta-bot]

Issues go stale after 90d of inactivity.
Mark the issue as fresh with /remove-lifecycle stale.
Stale issues rot after an additional 30d of inactivity and eventually close.

If this issue is safe to close now please do so with /close.

Send feedback to sig-testing, kubernetes/test-infra and/or fejta.
/lifecycle stale

[losipiuk]

/remove-lifecycle stale

Unless fixed this is still problematic issue.

[fejta-bot]

Issues go stale after 90d of inactivity.
Mark the issue as fresh with /remove-lifecycle stale.
Stale issues rot after an additional 30d of inactivity and eventually close.

If this issue is safe to close now please do so with /close.

Send feedback to sig-testing, kubernetes/test-infra and/or fejta.
/lifecycle stale

[fejta-bot]

Stale issues rot after 30d of inactivity.
Mark the issue as fresh with /remove-lifecycle rotten.
Rotten issues close after an additional 30d of inactivity.

If this issue is safe to close now please do so with /close.

Send feedback to sig-testing, kubernetes/test-infra and/or fejta.
/lifecycle rotten

[neolit123]

/lifecycle frozen

[neolit123]

/priority important-longterm

[zwpaper]

I have tested the v2.9.0, logging in init, it printed in stdout, then use initFlags and flag.Parse, it could be logging into the target file with --log_file option.

Double-check in source code,

klog/klog.go

Line 930 in 02ca14b

if logging.logFile != "" {

seems we could close this issue now.

@neolit123 @losipiuk