Skip to content

plugin factory: remove useless RegisterPlugin log output#3778

Merged
dims merged 1 commit intogoogle:masterfrom
pohly:plugin-factory-logging
Dec 10, 2025
Merged

plugin factory: remove useless RegisterPlugin log output#3778
dims merged 1 commit intogoogle:masterfrom
pohly:plugin-factory-logging

Conversation

@pohly
Copy link
Contributor

@pohly pohly commented Dec 10, 2025

RegisterPlugin gets called during the init phase of programs using this package. During init, klog verbosity is usually zero (making the log call redundant because it doesn't print anything).

This could be ignored, but it gets worse when some package increases verbosity during init:

  • plugin "systemd" gets registered: no output

  • verbosity gets changed

  • plugin "containerd" gets registered:

    I1210 14:05:15.799869 126449 factory.go:195] Registered Plugin "containerd"

As a general rule, init code should not log because logging cannot be properly initialized until after the program had a chance to parse command line parameters.

Fixes: #3707

RegisterPlugin gets called during the init phase of programs using this
package. During init, klog verbosity is usually zero (making the log call
redundant because it doesn't print anything).

This could be ignored, but it gets worse when some package increases
verbosity during init:

- plugin "systemd" gets registered: no output
- verbosity gets changed
- plugin "containerd" gets registered:

    I1210 14:05:15.799869  126449 factory.go:195] Registered Plugin "containerd"

As a general rule, init code should not log because logging cannot be properly
initialized until after the program had a chance to parse command line
parameters.
@pohly
Copy link
Contributor Author

pohly commented Dec 10, 2025

Reproducer from Kubernetes (but with log output only in kubernetes/kubernetes#133844 so far):

kubernetes$ dlv test ./test/e2e -- -test.v -list-tests
Type 'help' for list of commands.
(dlv) b RegisterPlugin
Breakpoint 1 set at 0x4eb7596 for github.com/google/cadvisor/container.RegisterPlugin() ./vendor/github.com/google/cadvisor/container/factory.go:189
(dlv) c
> [Breakpoint 1] github.com/google/cadvisor/container.RegisterPlugin() ./vendor/github.com/google/cadvisor/container/factory.go:189 (hits goroutine(1):1 total:1) (PC: 0x4eb7596)
   184:		// Register is invoked when starting a manager. It can optionally return a container watcher.
   185:		// A returned error is logged, but is not fatal.
   186:		Register(factory info.MachineInfoFactory, fsInfo fs.FsInfo, includedMetrics MetricSet) (watcher.ContainerWatcher, error)
   187:	}
   188:	
=> 189:	func RegisterPlugin(name string, plugin Plugin) error {
   190:		pluginsLock.Lock()
   191:		defer pluginsLock.Unlock()
   192:		if _, found := plugins[name]; found {
   193:			return fmt.Errorf("Plugin %q was registered twice", name)
   194:		}
(dlv) p name
"systemd"
(dlv) bt
0  0x0000000004eb7596 in github.com/google/cadvisor/container.RegisterPlugin
   at ./vendor/github.com/google/cadvisor/container/factory.go:189
1  0x0000000004f8cb7d in github.com/google/cadvisor/container/systemd/install.init.0
   at ./vendor/github.com/google/cadvisor/container/systemd/install/install.go:26
2  0x0000000001bd38f4 in runtime.doInit1
   at /nvme/gopath/go-1.25.2/src/runtime/proc.go:7670
3  0x0000000001bfe1aa in runtime.doInit
   at /nvme/gopath/go-1.25.2/src/runtime/proc.go:7637
4  0x0000000001bc4e9e in runtime.main
   at /nvme/gopath/go-1.25.2/src/runtime/proc.go:256
5  0x0000000001c05a41 in runtime.goexit
   at /nvme/gopath/go-1.25.2/src/runtime/asm_amd64.s:1693
(dlv) c

> [Breakpoint 1] github.com/google/cadvisor/container.RegisterPlugin() ./vendor/github.com/google/cadvisor/container/factory.go:189 (hits goroutine(1):2 total:2) (PC: 0x4eb7596)
   184:		// Register is invoked when starting a manager. It can optionally return a container watcher.
   185:		// A returned error is logged, but is not fatal.
   186:		Register(factory info.MachineInfoFactory, fsInfo fs.FsInfo, includedMetrics MetricSet) (watcher.ContainerWatcher, error)
   187:	}
   188:	
=> 189:	func RegisterPlugin(name string, plugin Plugin) error {
   190:		pluginsLock.Lock()
   191:		defer pluginsLock.Unlock()
   192:		if _, found := plugins[name]; found {
   193:			return fmt.Errorf("Plugin %q was registered twice", name)
   194:		}
(dlv) p name
"crio"
(dlv) c

> [Breakpoint 1] github.com/google/cadvisor/container.RegisterPlugin() ./vendor/github.com/google/cadvisor/container/factory.go:189 (hits goroutine(1):3 total:3) (PC: 0x4eb7596)
   184:		// Register is invoked when starting a manager. It can optionally return a container watcher.
   185:		// A returned error is logged, but is not fatal.
   186:		Register(factory info.MachineInfoFactory, fsInfo fs.FsInfo, includedMetrics MetricSet) (watcher.ContainerWatcher, error)
   187:	}
   188:	
=> 189:	func RegisterPlugin(name string, plugin Plugin) error {
   190:		pluginsLock.Lock()
   191:		defer pluginsLock.Unlock()
   192:		if _, found := plugins[name]; found {
   193:			return fmt.Errorf("Plugin %q was registered twice", name)
   194:		}
(dlv) p name
"containerd"
(dlv) so
I1210 15:45:58.259803  396947 factory.go:195] Registered Plugin "containerd"
> github.com/google/cadvisor/container/containerd/install.init.0() ./vendor/github.com/google/cadvisor/container/containerd/install/install.go:26 (PC: 0x4f8675d)

Only "containerd" is logged.

The output is also distracting:

kubernetes$ go test -v ./test/e2e -args -list-tests
I1210 15:48:13.482534  399943 factory.go:195] Registered Plugin "containerd"
The following spec names can be used with 'ginkgo run --focus/skip':
    apimachinery/watchlist.go:258: [sig-api-machinery] API Streaming (aka. WatchList) [FeatureGate:WatchList] [Beta] reflector doesn't support receiving resources as Tables
...

cc @dims

pohly added a commit to pohly/kubernetes that referenced this pull request Dec 10, 2025
klog calls during init are becoming a problem because now test/e2e/framework
depends in test/utils/ktesting which bumps up the default verbosity during init
to make test output more complete when there is no argument parsing.

For cadvisor, an upstream fix is
needed (google/cadvisor#3778). For kubectl we can make
it silently accept the valid (!) LC_ALL=C.
@pohly pohly mentioned this pull request Dec 10, 2025
@dims dims enabled auto-merge December 10, 2025 16:50
@dims dims added this pull request to the merge queue Dec 10, 2025
Merged via the queue into google:master with commit 958b9e0 Dec 10, 2025
7 checks passed
pohly added a commit to pohly/kubernetes that referenced this pull request Dec 16, 2025
klog calls during init are becoming a problem because now test/e2e/framework
depends in test/utils/ktesting which bumps up the default verbosity during init
to make test output more complete when there is no argument parsing.

For cadvisor, an upstream fix is
needed (google/cadvisor#3778). For kubectl we can make
it silently accept the valid (!) LC_ALL=C.
pohly added a commit to pohly/kubernetes that referenced this pull request Dec 18, 2025
klog calls during init are becoming a problem because now test/e2e/framework
depends in test/utils/ktesting which bumps up the default verbosity during init
to make test output more complete when there is no argument parsing.

For cadvisor, an upstream fix is
needed (google/cadvisor#3778). For kubectl we can make
it silently accept the valid (!) LC_ALL=C.
pohly added a commit to pohly/kubernetes that referenced this pull request Dec 18, 2025
klog calls during init are becoming a problem because now test/e2e/framework
depends in test/utils/ktesting which bumps up the default verbosity during init
to make test output more complete when there is no argument parsing.

For cadvisor, an upstream fix is
needed (google/cadvisor#3778). For kubectl we can make
it silently accept the valid (!) LC_ALL=C.
pohly added a commit to pohly/kubernetes that referenced this pull request Dec 18, 2025
klog calls during init are becoming a problem because now test/e2e/framework
depends in test/utils/ktesting which bumps up the default verbosity during init
to make test output more complete when there is no argument parsing.

For cadvisor, an upstream fix is
needed (google/cadvisor#3778). For kubectl we can make
it silently accept the valid (!) LC_ALL=C.
pohly added a commit to pohly/kubernetes that referenced this pull request Jan 5, 2026
klog calls during init are becoming a problem because now test/e2e/framework
depends in test/utils/ktesting which bumps up the default verbosity during init
to make test output more complete when there is no argument parsing.

For cadvisor, an upstream fix is
needed (google/cadvisor#3778). For kubectl we can make
it silently accept the valid (!) LC_ALL=C.
pohly added a commit to pohly/kubernetes that referenced this pull request Jan 5, 2026
klog calls during init are becoming a problem because now test/e2e/framework
depends in test/utils/ktesting which bumps up the default verbosity during init
to make test output more complete when there is no argument parsing.

For cadvisor, an upstream fix is
needed (google/cadvisor#3778). For kubectl we can make
it silently accept the valid (!) LC_ALL=C.
pohly added a commit to pohly/kubernetes that referenced this pull request Jan 5, 2026
klog calls during init are becoming a problem because now test/e2e/framework
depends in test/utils/ktesting which bumps up the default verbosity during init
to make test output more complete when there is no argument parsing.

For cadvisor, an upstream fix is
needed (google/cadvisor#3778). For kubectl we can make
it silently accept the valid (!) LC_ALL=C.
pohly added a commit to pohly/kubernetes that referenced this pull request Jan 5, 2026
klog calls during init are becoming a problem because now test/e2e/framework
depends in test/utils/ktesting which bumps up the default verbosity during init
to make test output more complete when there is no argument parsing.

For cadvisor, an upstream fix is
needed (google/cadvisor#3778). For kubectl we can make
it silently accept the valid (!) LC_ALL=C.
pohly added a commit to pohly/kubernetes that referenced this pull request Jan 7, 2026
klog calls during init are becoming a problem because now test/e2e/framework
depends in test/utils/ktesting which bumps up the default verbosity during init
to make test output more complete when there is no argument parsing.

For cadvisor, an upstream fix is
needed (google/cadvisor#3778). For kubectl we can make
it silently accept the valid (!) LC_ALL=C.
k8s-publishing-bot pushed a commit to kubernetes/kubectl that referenced this pull request Jan 8, 2026
klog calls during init are becoming a problem because now test/e2e/framework
depends in test/utils/ktesting which bumps up the default verbosity during init
to make test output more complete when there is no argument parsing.

For cadvisor, an upstream fix is
needed (google/cadvisor#3778). For kubectl we can make
it silently accept the valid (!) LC_ALL=C.

Kubernetes-commit: d17aaf5e29f209ca71047078650e9dcd266e47a4
richabanker pushed a commit to richabanker/kubernetes that referenced this pull request Jan 16, 2026
klog calls during init are becoming a problem because now test/e2e/framework
depends in test/utils/ktesting which bumps up the default verbosity during init
to make test output more complete when there is no argument parsing.

For cadvisor, an upstream fix is
needed (google/cadvisor#3778). For kubectl we can make
it silently accept the valid (!) LC_ALL=C.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

logging during init

2 participants