testenv: Remove klog init flags #148

darkowlzz · 2021-09-16T15:17:00Z

This change allows test environments with glog to work with testenv.

Background

image-reflector-controller uses badger for database. dgraph-io/badger go package depends on dgraph-io/ristretto, which depends on glog. When glog is used, it sets log_dir flag, refer .
Due to the glog transitive dependency of badger, when badger is used in testenv based tests, the testenv package init() initialization of the klog flags and badger set the glog flags conflict, resulting in some redefined flags.

This can be reproduced by adding the following in TestMain():

    badgerDir, err := ioutil.TempDir(os.TempDir(), "badger")
    if err != nil {
        panic(fmt.Sprintf("Failed to create temporary directory for badger: %v", err))
    }

    badgerDB, err := badger.Open(badger.DefaultOptions(badgerDir))
    if err != nil {
        panic(fmt.Sprintf("Failed to create new Badger database: %v", err))
    }

with "github.com/dgraph-io/badger/v3" import.

Failure output:

/tmp/go-build1837318169/b001/controllers.test flag redefined: log_dir
panic: /tmp/go-build1837318169/b001/controllers.test flag redefined: log_dir

goroutine 1 [running]:
flag.(*FlagSet).Var(0xc00003c240, {0x19d5ad8, 0x26f5090}, {0x17b67fd, 0x7}, {0x17f2153, 0x2f})
        ~/.gimme/versions/go1.17.1.linux.amd64/src/flag/flag.go:879 +0x2f4
flag.(*FlagSet).StringVar(...)
        ~/.gimme/versions/go1.17.1.linux.amd64/src/flag/flag.go:762
k8s.io/klog/v2.InitFlags(0x1494a27)
        ~/go/pkg/mod/k8s.io/klog/v2@v2.8.0/klog.go:427 +0x55
github.com/fluxcd/pkg/runtime/testenv.init.0()
        ~/go/pkg/mod/github.com/fluxcd/pkg/runtime@v0.13.0-rc.2/testenv/testenv.go:56 +0x1b
FAIL    github.com/fluxcd/image-reflector-controller/controllers        0.027s
FAIL

Based on an example in klog repo, glog and klog can coexist with separate FlagSets.

With this change, the image-reflector-controller is able to use testenv.

squaremo · 2021-09-16T15:34:15Z

runtime/testenv/testenv.go

+	// uses it to initializes klog.
+	// Refer: https://github.com/kubernetes/klog/blob/f8e668dbaa5f6f0e6a5c24ffd7667263840d79ae/examples/coexist_glog/coexist_glog.go
+	klogFlags := flag.NewFlagSet("klog", flag.ExitOnError)
+	klog.InitFlags(klogFlags)


Do you need to tell klogr about the flags?

I thought so too and was trying to find a way to do that but there doesn't seem to be a way to do that.
Concluded that since this is a test, it's okay for the defaults. A user should be able to override the logger that's passed to the controllers.

OK; I think it is worth pointing out in the signpost comment that it's effectively throwing away the flag values, so that future readers will not skip through and assume they are passed. Since we're talking about global variables here, it would be a reasonable assumption given the comment that say, klog.InitFlags(...) assigns the flagset to be used by klogr. (Or does it actually do this? There you go, I'm already confused ...)

😄 yes, it is a bit confusing. I spent some more time going through the klog repo and understanding how it's supposed to be used. It looks like klog.InitFlags() is independent of klogr. There's a private variable called logging that's used for setting the flag values on the given FlagSet to InitFlags().
klogr just imports klog and uses the global klog. There's no API to pass a klog instance. If any values are set on the global klog using the global flagset, it'll be available to klogr. No way to pass a different klog.

The problem in this case is that since the testenv's init gets called at the very beginning, there's nothing that can be done in testenv package from preventing someone trying to register another flag later. In the case of badger, since they use glog, even they don't have a way to not do this without dropping the glog dependency. The only way around this that I can think of is to avoid filling the global flags with klog init flags for this particular situation.

I'll update the comment to mention that the klog flags are not passed to the klogr that's set as the controller runtime logger. It can be manually passed by creating a custom klog and klogr, and overwriting the set controller-runtime logger.

I've looked at the klog code now too. The flag values aren't thrown away as I speculated, they are used to populate a global struct, as you say. And klogr is just an adapter that uses the global. So that's all fine from our point of view, since all we want to do is avoid using the same flagset as glog.

darkowlzz · 2021-09-21T22:27:42Z

I spent more time validating the idea of overriding the controller-runtime(c-n) logger set by the testenv init() and found that the c-n deferred logger can only be set once. Importing testenv package sets the c-n logger in its init(), subsequent calls to ctrl.SetLogger() becomes no-op. Since this is a library, I think it'll be better to not hijack the logger by just importing the package and allow the users to set their own logger. To enable that, I've moved the logger initialization code into a new function initLogger(), which is called when a new testenv Environment is created. This enables the users to set their custom logger before creating testenv. The testenv's attempt to set the c-n logger becomes no-op if it's already set.

Also, added godoc example to show how a custom logger can be set before creating testenv.

runtime/testenv/testenv.go

hiddeco

Reasoning seems to make sense, thanks for getting to the bottom of it, and for including an example 🥇

squaremo · 2021-09-23T09:12:06Z

runtime/testenv/testenv.go

+	// redeclaration of the same flags.
+	// This is based on klog's coexist with glog example, refer:
+	// https://github.com/kubernetes/klog/blob/f8e668dbaa5f6f0e6a5c24ffd7667263840d79ae/examples/coexist_glog/coexist_glog.go
+	// The klog flags set below are not available to the klogr logger below


This, we have discovered, is not correct. klogr uses the public API of klog, which in turn makes use of the flagset to set itself up.

Replaced it with a statement about how to override this logger setup.

squaremo · 2021-09-23T09:37:58Z

runtime/testenv/testenv.go

+	// assigned to the controller-runtime logger explicitly before creating
+	// testenv Environment.
+	klogFlags := flag.NewFlagSet("klog", flag.ExitOnError)
+	klog.InitFlags(klogFlags)


Do you need to call klogFlags.Parse()? I don't think klog calls it.

Searching for Parse() in klog repo, I only see them in the example code. So, yes, you're probably right about that.

I tried setting a parse here klogFlags.Parse(os.Args[1:]) , but it results in the following error :

flag provided but not defined: -test.paniconexit0 Usage of klog: -add_dir_header If true, adds the file directory to the header of the log messages -alsologtostderr log to standard error as well as files ...

Because some extra flags get set in the test run that klog flagset isn't aware of.
I can't think of a way to remove unknown flag args before passing to this Parse() in a library. Maybe this is the reason it's not parsed here in the first place.
This leaves it up to the user to construct their own flagset and configure their logger. The library only does the minimum default setup.

So that makes me feel like dropping klog.InitFlags() completely since the flags are not parsed and used at all.

And if we do that, we can remove all the extra comments about coexisting with glog. It'll just work with glog without doing anything.

I thought that might be the case. And if it can't be done here, I don't think a user of the library has much of a chance either. It worked before because the test environment didn't mandate using klogr; could this package go back to that arrangement?

I think it did mandate klogr before but didn't care to parse the flags and left no way to change it because of running the logger setup in the init.
I can just remove the separate flagset code and klog.InitFlags(). That will be equivalent to the previous behavior.

Removes klog.InitFlags() because the klog flags aren't parsed before using klog. To avoid conflicting with other flags, it's better to not populate the global flagset. This results in default klogr to be set as the default controller-runtime logger if not set in the test already. The logger setup not being in init() allows users to set their own logger before creating testenv Environment. Signed-off-by: Sunny <darkowlzz@protonmail.com>

darkowlzz · 2021-09-23T11:27:09Z

Renamed the title of the PR and changed the details in the commit message because it no longer has to do with glog directly.

squaremo · 2021-09-23T14:38:12Z

runtime/testenv/testenv.go

 func New(o ...Option) *Environment {
+	// Set a default logger if not set already.
+	log.SetLogger(klogr.New())


Given this is equivalent to ctrl.SetLogger, it'd be better to use the same in both the example given and the code, otherwise people might wonder why they differ. Also worth explaining that subsequent calls to ctrl.SetLogger have no effect (the comment implies this, but pays to be explicit)

squaremo

I think this is the right way to go now, and I'm down to nit picks, so ✅
Thanks for your patience Sunny!

darkowlzz force-pushed the testenv-klog-init-flags branch from b22bf27 to 7c6d0e3 Compare September 16, 2021 15:17

squaremo reviewed Sep 16, 2021

View reviewed changes

darkowlzz force-pushed the testenv-klog-init-flags branch 3 times, most recently from 2576e9e to 402a588 Compare September 16, 2021 20:01

darkowlzz mentioned this pull request Sep 17, 2021

Testenv test refactor fluxcd/image-reflector-controller#170

Merged

darkowlzz force-pushed the testenv-klog-init-flags branch from 402a588 to bb1064d Compare September 21, 2021 22:18

darkowlzz commented Sep 21, 2021

View reviewed changes

runtime/testenv/testenv.go Show resolved Hide resolved

darkowlzz force-pushed the testenv-klog-init-flags branch 2 times, most recently from 0d1ea32 to 51132d8 Compare September 21, 2021 22:42

hiddeco approved these changes Sep 23, 2021

View reviewed changes

squaremo reviewed Sep 23, 2021

View reviewed changes

darkowlzz force-pushed the testenv-klog-init-flags branch from 51132d8 to 6089e4d Compare September 23, 2021 09:24

squaremo reviewed Sep 23, 2021

View reviewed changes

darkowlzz force-pushed the testenv-klog-init-flags branch from 6089e4d to c5a17be Compare September 23, 2021 11:25

darkowlzz changed the title ~~testenv: Allow klog and glog to coexist~~ testenv: Remove klog init flags Sep 23, 2021

squaremo reviewed Sep 23, 2021

View reviewed changes

squaremo approved these changes Sep 23, 2021

View reviewed changes

hiddeco merged commit ed06eb8 into fluxcd:main Sep 23, 2021

hiddeco added area/runtime Controller runtime related issues and pull requests bug Something isn't working labels Sep 23, 2021

darkowlzz deleted the testenv-klog-init-flags branch September 23, 2021 19:30

darkowlzz mentioned this pull request Oct 20, 2021

REQUEST: New membership for @darkowlzz fluxcd/community#128

Closed

5 tasks

darkowlzz mentioned this pull request May 26, 2023

Set logger for controller-runtime warnings fluxcd/test-infra#10

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

testenv: Remove klog init flags #148

testenv: Remove klog init flags #148

darkowlzz commented Sep 16, 2021 •

edited

Loading

squaremo Sep 16, 2021

darkowlzz Sep 16, 2021

squaremo Sep 16, 2021

darkowlzz Sep 16, 2021

squaremo Sep 22, 2021

darkowlzz commented Sep 21, 2021

hiddeco left a comment

squaremo Sep 23, 2021

darkowlzz Sep 23, 2021 •

edited

Loading

squaremo Sep 23, 2021

darkowlzz Sep 23, 2021

darkowlzz Sep 23, 2021

darkowlzz Sep 23, 2021

darkowlzz Sep 23, 2021

squaremo Sep 23, 2021

darkowlzz Sep 23, 2021

darkowlzz commented Sep 23, 2021 •

edited

Loading

squaremo Sep 23, 2021 •

edited

Loading

squaremo left a comment

testenv: Remove klog init flags #148

testenv: Remove klog init flags #148

Conversation

darkowlzz commented Sep 16, 2021 • edited Loading

Background

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

darkowlzz commented Sep 21, 2021

hiddeco left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

darkowlzz Sep 23, 2021 • edited Loading

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

darkowlzz commented Sep 23, 2021 • edited Loading

squaremo Sep 23, 2021 • edited Loading

Choose a reason for hiding this comment

squaremo left a comment

Choose a reason for hiding this comment

darkowlzz commented Sep 16, 2021 •

edited

Loading

darkowlzz Sep 23, 2021 •

edited

Loading

darkowlzz commented Sep 23, 2021 •

edited

Loading

squaremo Sep 23, 2021 •

edited

Loading