implement "--log_file" and "--log_dir" for klog

[prezha]

fixes: #9521

as described in the original issue #9521, --log_file and --log_dir command line arguments were not parsed from the flags

when all else fails, follow instructions
― Anne Lamott

so, after going through a bunch of source code and understanding how the things (suppose to) work, i'm sharing the outcomes:

• because we are using subcommands as the first argument to minikube and:

Flag parsing stops just before the first non-flag argument
(ref: https://pkg.go.dev/flag#hdr-Command_line_flag_syntax)

=> externally defined 'global' flags (like klog's --log_file and --log_dir) never got parsed and therefore always ignored

• to fix these 'limitations' in our context, in main():

  • use pflag instead of flag package
  • set pflag.CommandLine.ParseErrorsWhitelist.UnknownFlags to true
  • use pflag.CommandLine.AddGoFlagSet(flag.CommandLine) to pickup all flags set in command line
  • pflag.Parse() flags

• important to note: flags should be defined and/or initialised but never parsed in init() funcs - parse in (the beginning of) the main() func, after all init() funcs were processed

• aob (already reflected in this pr):

  • for logging to file/dir to work as expected, both --logtostderr and --alsologtostderr should be set to false, but don't override user's preferences - if any: now checked/set in main(), but autoset for test runs
  • make sure that directory defined by --log_dir actually exists
  • k8s.io/minikube/pkg/initflag / pkg/initflag/initflag.go not needed/used anymore

details (debugging)

❯ minikube status --log_file "mqb.log" --profile "pro"

in main(), values of go flag and pflag (incl. klog flags) before setFlags() was called:

main/flag:      &{Usage:0x516960 name:minikube parsed:false actual:map[] formal:map[add_dir_header:0xc00024fbc0 alsologtostderr:0xc00024fb40 log_backtrace_at:0xc00024fd00 log_dir:0xc00024fa40 log_file:0xc00024fa80 log_file_max_size:0xc00024fac0 logtostderr:0xc00024fb00 skip_headers:0xc00024fc00 skip_log_headers:0xc00024fc40 stderrthreshold:0xc00024fc80 v:0xc00024fb80 vmodule:0xc00024fcc0] args:[] errorHandling:1 output:<nil>}

main/flag:      &{Name:log_file Usage:If non-empty, use this log file Value: DefValue:}

        add_dir_header  false
        alsologtostderr false
        log_backtrace_at        :0
        log_dir
        log_file
        log_file_max_size       1800
        logtostderr     true
        skip_headers    false
        skip_log_headers        false
        stderrthreshold 2
        v       0
        vmodule

main/pflag:     &{Usage:<nil> SortFlags:true ParseErrorsWhitelist:{UnknownFlags:false} name:minikube parsed:false actual:map[] orderedActual:[] sortedActual:[] formal:map[add_dir_header:0xc000c0a8c0 alsologtostderr:0xc000c0a960 log_backtrace_at:0xc000c0aa00 log_dir:0xc000c0aaa0 log_file:0xc000c0ab40 log_file_max_size:0xc000c0abe0 logtostderr:0xc000c0ac80 skip_headers:0xc000c0ad20 skip_log_headers:0xc000c0adc0 stderrthreshold:0xc000c0ae60 v:0xc000c0af00 vmodule:0xc000c0afa0] orderedFormal:[0xc000c0a8c0 0xc000c0a960 0xc000c0aa00 0xc000c0aaa0 0xc000c0ab40 0xc000c0abe0 0xc000c0ac80 0xc000c0ad20 0xc000c0adc0 0xc000c0ae60 0xc000c0af00 0xc000c0afa0] sortedFormal:[] shorthands:map[118:0xc000c0af00] args:[] argsLenAtDash:-1 errorHandling:1 output:<nil> interspersed:true normalizeNameFunc:<nil> addedGoFlagSets:[0xc000136180]}

main/pflag:     &{Name:log_file Shorthand: Usage:If non-empty, use this log file Value: DefValue: Changed:false NoOptDefVal: Deprecated: Hidden:false ShorthandDeprecated: Annotations:map[]}

        add_dir_header  false
        alsologtostderr false
        log_backtrace_at        :0
        log_dir
        log_file
        log_file_max_size       1800
        logtostderr     true
        skip_headers    false
        skip_log_headers        false
        stderrthreshold 2
        v       0
        vmodule

after setFlags() was called:

main/flag:      &{Usage:0x516960 name:minikube parsed:true actual:map[] formal:map[add_dir_header:0xc00024fbc0 alsologtostderr:0xc00024fb40 log_backtrace_at:0xc00024fd00 log_dir:0xc00024fa40 log_file:0xc00024fa80 log_file_max_size:0xc00024fac0 logtostderr:0xc00024fb00 skip_headers:0xc00024fc00 skip_log_headers:0xc00024fc40 stderrthreshold:0xc00024fc80 v:0xc00024fb80 vmodule:0xc00024fcc0] args:[] errorHandling:1 output:<nil>}

main/flag:      &{Name:log_file Usage:If non-empty, use this log file Value:mqb.log DefValue:}

        add_dir_header  false
        alsologtostderr false
        log_backtrace_at        :0
        log_dir
        log_file        mqb.log
        log_file_max_size       1800
        logtostderr     false
        skip_headers    false
        skip_log_headers        false
        stderrthreshold 2
        v       0
        vmodule


main/pflag:     &{Usage:<nil> SortFlags:true ParseErrorsWhitelist:{UnknownFlags:true} name:minikube parsed:true actual:map[alsologtostderr:0xc000c0a960 log_file:0xc000c0ab40 logtostderr:0xc000c0ac80] orderedActual:[0xc000c0ab40 0xc000c0ac80 0xc000c0a960] sortedActual:[] formal:map[add_dir_header:0xc000c0a8c0 alsologtostderr:0xc000c0a960 log_backtrace_at:0xc000c0aa00 log_dir:0xc000c0aaa0 log_file:0xc000c0ab40 log_file_max_size:0xc000c0abe0 logtostderr:0xc000c0ac80 skip_headers:0xc000c0ad20 skip_log_headers:0xc000c0adc0 stderrthreshold:0xc000c0ae60 v:0xc000c0af00 vmodule:0xc000c0afa0] orderedFormal:[0xc000c0a8c0 0xc000c0a960 0xc000c0aa00 0xc000c0aaa0 0xc000c0ab40 0xc000c0abe0 0xc000c0ac80 0xc000c0ad20 0xc000c0adc0 0xc000c0ae60 0xc000c0af00 0xc000c0afa0] sortedFormal:[0xc000c0a8c0 0xc000c0a960 0xc000c0aa00 0xc000c0aaa0 0xc000c0ab40 0xc000c0abe0 0xc000c0ac80 0xc000c0ad20 0xc000c0adc0 0xc000c0ae60 0xc000c0af00 0xc000c0afa0] shorthands:map[118:0xc000c0af00] args:[status] argsLenAtDash:-1 errorHandling:1 output:<nil> interspersed:true normalizeNameFunc:<nil> addedGoFlagSets:[0xc000136180 0xc000136180]}

main/pflag:     &{Name:log_file Shorthand: Usage:If non-empty, use this log file Value:mqb.log DefValue: Changed:true NoOptDefVal: Deprecated: Hidden:false ShorthandDeprecated: Annotations:map[]}

        add_dir_header  false
        alsologtostderr false
        log_backtrace_at        :0
        log_dir
        log_file        mqb.log
        log_file_max_size       1800
        logtostderr     false
        skip_headers    false
        skip_log_headers        false
        stderrthreshold 2
        v       0
        vmodule

[k8s-ci-robot]

Hi @prezha. 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 /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.

Once the patch is verified, the new status will be reflected by the ok-to-test label.

I understand the commands that are listed here.

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.

[minikube-bot]

Can one of the admins verify this patch?

[codecov-io]

Codecov Report

Merging #9592 into master will increase coverage by 0.42%.
The diff coverage is 50.00%.

@@            Coverage Diff             @@
##           master    #9592      +/-   ##
==========================================
+ Coverage   29.05%   29.47%   +0.42%     
==========================================
  Files         172      173       +1     
  Lines       10506    10736     +230     
==========================================
+ Hits         3052     3164     +112     
- Misses       7029     7123      +94     
- Partials      425      449      +24     

Impacted Files	Coverage Δ
pkg/minikube/extract/extract.go	48.47% <ø> (ø)
cmd/minikube/cmd/root.go	43.97% <42.85%> (+0.40%)	⬆️
pkg/minikube/translate/translate.go	38.29% <100.00%> (ø)

[medyagh]

/ok-to-test

[minikube-pr-bot]

kvm2 Driver
error collecting results for kvm2 driver: timing run 0 with Minikube (PR 9592): timing cmd: [/home/performance-monitor/.minikube/minikube-binaries/9592/minikube start --driver=kvm2]: starting cmd: fork/exec /home/performance-monitor/.minikube/minikube-binaries/9592/minikube: exec format error
docker Driver
error collecting results for docker driver: timing run 0 with Minikube (PR 9592): timing cmd: [/home/performance-monitor/.minikube/minikube-binaries/9592/minikube start --driver=docker]: starting cmd: fork/exec /home/performance-monitor/.minikube/minikube-binaries/9592/minikube: exec format error

[medyagh]

Thank you very much for fixing this ! I find this bug one of the most difficult to debug.

good job !

do you mind verifiying the other flags of "minikube options" is also supported?

for example
      --log_file_max_size=1800: Defines the maximum size a log file can grow to. Unit is megabytes. If the value is 0, the maximum file size is unlimited.

minikube options
      --add_dir_header=false: If true, adds the file directory to the header of the log messages
      --alsologtostderr=false: log to standard error as well as files
  -b, --bootstrapper='kubeadm': The name of the cluster bootstrapper that will set up the Kubernetes cluster.
      --log_backtrace_at=:0: when logging hits line file:N, emit a stack trace
      --log_dir='': If non-empty, write log files in this directory
      --log_file='': If non-empty, use this log file
      --log_file_max_size=1800: Defines the maximum size a log file can grow to. Unit is megabytes. If the value is 0, the maximum file size is unlimited.
      --logtostderr=true: log to standard error instead of files
  -p, --profile='minikube': The name of the minikube VM being used. This can be set to allow having multiple instances of minikube independently.
      --skip_headers=false: If true, avoid header prefixes in the log messages
      --skip_log_headers=false: If true, avoid headers when opening log files
      --stderrthreshold=2: logs at or above this threshold go to stderr
  -v, --v=0: number for the log level verbosity
      --vmodule=: comma-separated list of pattern=N settings for file-filtered logging

[prezha]

thank you @medyagh, much appreciated! yeah, it was an interesting one

yes, i'll also check if it supports the other "minikube options" flags and feedback

[prezha]

glad that you've asked this @medyagh, as we should probably upgrade to klog v2.4.0 (we're currently using v2.3.0), but that is a separate issue (#9596 & pr #9597); reasoning:

i got stuck at the very beginning - with testing --log_file_max_size finding a bug where it is ignored in klog package v2.3.0 (ie, the current actual filesize was never checked, but the value representing it [sb.nbytes] was, leading to the false-negative condition check that rotation does not have to happen), just to find out that this bug was fixed in v2.4.0 (four months ago in commit d2c1c11, pr #172, re: issue #171)

after upgrade to klog v2.4.0, i've confirmed --log_file_max_size flag working as expected

in addition to fixing this bug, v2.4.0 introduced 2 new things:

• one_output flag:

If true, only write logs to their native severity level (vs also writing to each lower severity level

• LogFilter capabilities:

LogFilter is a collection of functions that can filter all logging calls, e.g. for sanitization of arguments and prevent accidental leaking of secrets.

and no other major changes

another interesting reason for upgrading to v2.4.0 is the release comment: Prepare release for Kubernetes v1.20

i haven't tested klog v2.3.0/v2.4.0 further, but, from our side, yes, all of the minikube options flags get picked up by changes in this pr - example:

❯ minikube status --log_dir='mqb' --log_file='mqb.log' --log_file_max_size=3 --add_dir_header=true --alsologtostderr=true --bootstrapper='kubeadmin' --log_backtrace_at='gopherflakes.go:234' --logtostderr=false --profile='mqb' --skip_headers=true --skip_log_headers=true --stderrthreshold=1 --v=1 --vmodule=mapreduce=2

in main(), values of go flag and pflag (incl. klog flags) before setFlags() was called:

main/flag:      &{Usage:0x516960 name:minikube parsed:false actual:map[] formal:map[add_dir_header:0xc00085f400 alsologtostderr:0xc00085f380 log_backtrace_at:0xc00085f540 log_dir:0xc00085f280 log_file:0xc00085f2c0 log_file_max_size:0xc00085f300 logtostderr:0xc00085f340 skip_headers:0xc00085f440 skip_log_headers:0xc00085f480 stderrthreshold:0xc00085f4c0 v:0xc00085f3c0 vmodule:0xc00085f500] args:[] errorHandling:1 output:<nil>}

main/flag:      &{Name:log_file Usage:If non-empty, use this log file Value: DefValue:}

        add_dir_header  false
        alsologtostderr false
        log_backtrace_at        :0
        log_dir
        log_file
        log_file_max_size       1800
        logtostderr     true
        skip_headers    false
        skip_log_headers        false
        stderrthreshold 2
        v       0
        vmodule

main/pflag:     &{Usage:<nil> SortFlags:true ParseErrorsWhitelist:{UnknownFlags:false} name:minikube parsed:false actual:map[] orderedActual:[] sortedActual:[] formal:map[add_dir_header:0xc000b89680 alsologtostderr:0xc000b89720 log_backtrace_at:0xc000b897c0 log_dir:0xc000b89860 log_file:0xc000b89900 log_file_max_size:0xc000b899a0 logtostderr:0xc000b89a40 skip_headers:0xc000b89ae0 skip_log_headers:0xc000b89b80 stderrthreshold:0xc000b89c20 v:0xc000b89cc0 vmodule:0xc000b89d60] orderedFormal:[0xc000b89680 0xc000b89720 0xc000b897c0 0xc000b89860 0xc000b89900 0xc000b899a0 0xc000b89a40 0xc000b89ae0 0xc000b89b80 0xc000b89c20 0xc000b89cc0 0xc000b89d60] sortedFormal:[] shorthands:map[118:0xc000b89cc0] args:[] argsLenAtDash:-1 errorHandling:1 output:<nil> interspersed:true normalizeNameFunc:<nil> addedGoFlagSets:[0xc0000ae180]}

main/pflag:     &{Name:log_file Shorthand: Usage:If non-empty, use this log file Value: DefValue: Changed:false NoOptDefVal: Deprecated: Hidden:false ShorthandDeprecated: Annotations:map[]}

        add_dir_header  false
        alsologtostderr false
        log_backtrace_at        :0
        log_dir
        log_file
        log_file_max_size       1800
        logtostderr     true
        skip_headers    false
        skip_log_headers        false
        stderrthreshold 2
        v       0
        vmodule

after setFlags() was called:

main/flag:      &{Usage:0x516960 name:minikube parsed:true actual:map[] formal:map[add_dir_header:0xc00085f400 alsologtostderr:0xc00085f380 log_backtrace_at:0xc00085f540 log_dir:0xc00085f280 log_file:0xc00085f2c0 log_file_max_size:0xc00085f300 logtostderr:0xc00085f340 skip_headers:0xc00085f440 skip_log_headers:0xc00085f480 stderrthreshold:0xc00085f4c0 v:0xc00085f3c0 vmodule:0xc00085f500] args:[] errorHandling:1 output:<nil>}

main/flag:      &{Name:log_file Usage:If non-empty, use this log file Value:mqb.log DefValue:}

        add_dir_header  true
        alsologtostderr true
        log_backtrace_at        gopherflakes.go:234
        log_dir mqb
        log_file        mqb.log
        log_file_max_size       3
        logtostderr     false
        skip_headers    true
        skip_log_headers        true
        stderrthreshold 1
        v       1
        vmodule mapreduce=2

main/pflag:     &{Usage:<nil> SortFlags:true ParseErrorsWhitelist:{UnknownFlags:true} name:minikube parsed:true actual:map[add_dir_header:0xc000b89680 alsologtostderr:0xc000b89720 log_backtrace_at:0xc000b897c0 log_dir:0xc000b89860 log_file:0xc000b89900 log_file_max_size:0xc000b899a0 logtostderr:0xc000b89a40 skip_headers:0xc000b89ae0 skip_log_headers:0xc000b89b80 stderrthreshold:0xc000b89c20 v:0xc000b89cc0 vmodule:0xc000b89d60] orderedActual:[0xc000b89860 0xc000b89900 0xc000b899a0 0xc000b89680 0xc000b89720 0xc000b897c0 0xc000b89a40 0xc000b89ae0 0xc000b89b80 0xc000b89c20 0xc000b89cc0 0xc000b89d60] sortedActual:[] formal:map[add_dir_header:0xc000b89680 alsologtostderr:0xc000b89720 log_backtrace_at:0xc000b897c0 log_dir:0xc000b89860 log_file:0xc000b89900 log_file_max_size:0xc000b899a0 logtostderr:0xc000b89a40 skip_headers:0xc000b89ae0 skip_log_headers:0xc000b89b80 stderrthreshold:0xc000b89c20 v:0xc000b89cc0 vmodule:0xc000b89d60] orderedFormal:[0xc000b89680 0xc000b89720 0xc000b897c0 0xc000b89860 0xc000b89900 0xc000b899a0 0xc000b89a40 0xc000b89ae0 0xc000b89b80 0xc000b89c20 0xc000b89cc0 0xc000b89d60] sortedFormal:[0xc000b89680 0xc000b89720 0xc000b897c0 0xc000b89860 0xc000b89900 0xc000b899a0 0xc000b89a40 0xc000b89ae0 0xc000b89b80 0xc000b89c20 0xc000b89cc0 0xc000b89d60] shorthands:map[118:0xc000b89cc0] args:[status] argsLenAtDash:-1 errorHandling:1 output:<nil> interspersed:true normalizeNameFunc:<nil> addedGoFlagSets:[0xc0000ae180 0xc0000ae180]}

main/pflag:     &{Name:log_file Shorthand: Usage:If non-empty, use this log file Value:mqb.log DefValue: Changed:true NoOptDefVal: Deprecated: Hidden:false ShorthandDeprecated: Annotations:map[]}

        add_dir_header  true
        alsologtostderr true
        log_backtrace_at        gopherflakes.go:234
        log_dir mqb
        log_file        mqb.log
        log_file_max_size       3
        logtostderr     false
        skip_headers    true
        skip_log_headers        true
        stderrthreshold 1
        v       1
        vmodule mapreduce=2

Setting OutFile to fd 1 ...
isatty.IsTerminal(1) = true
Setting ErrFile to fd 2...
isatty.IsTerminal(2) = true
Updating PATH: /home/prezha/.minikube/bin
Error reading config file at /home/prezha/.minikube/config/config.json: open /home/prezha/.minikube/config/config.json: no such file or directory
Loading cluster: mqb
🤷  There is no local cluster named "mqb"
🤷  There is no local cluster named "mqb"
👉  To fix this, run: "minikube start -p mqb"
👉  To fix this, run: "minikube start -p mqb"

[k8s-ci-robot]

[APPROVALNOTIFIER] This PR is APPROVED

This pull-request has been approved by: medyagh, prezha

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:

• OWNERS [medyagh]

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