Re-use logger instance

[vikasmb]

What type of PR is this?
bug-fix

Which issue does this PR fix:

• Existing logger initialization constructed different logger
  instances upon call to Get() method.
• Fixed the initialization logic to re-use the logger instance.

What does this PR do / Why do we need it:

• Logger instances were holding references to ipamd.log file even after rotation leading to leaked file handles.

If an issue # is not available please add repro steps and logs from IPAMD/CNI showing the issue:

Testing done on this change:

Deployed this fix on a cluster and verified that leaked file handles for ipamd log file are no longer present.
Automation added to e2e:

Will this PR introduce any new dependencies?:

No
Will this break upgrades or downgrades. Has updating a running cluster been tested?:
No

Does this change require updates to the CNI daemonset config files to work?:

No
Does this PR introduce any user-facing change?:

No

By submitting this pull request, I confirm that my contribution is made under the terms of the Apache 2.0 license.

[orsenthil]

Excellent Fix.

[orsenthil]

Why are we removing this structuredLogger reference? and isEmpty() call?

[jayanthvn]

Here logf will always be empty, hence it was removed.

But I am thinking should we instead implement isEmpty() for the global variable and assign the local variable to global variable if the global is empty. Just to keep the code readable.

[orsenthil]

Wont be isEmpty() be handled by the library itself? I was curious both by the presence and now is removal.

• The single place initialization is one change, that looks good to me.
• Removal of this logger property seems a different change than single place initialization.

[vikasmb]

Existing logic was

var logf = &structuredLogger{}
	if logf.isEmpty() {

func (logf *structuredLogger) isEmpty() bool {
	return logf.zapLogger == nil
}

Through log messages, it was confirmed that each package was obtaining it's own logger instance:
Test execution logs (prior to the change)

"level":"info","ts":"2022-07-07T23:02:41.525Z","caller":"eniconfig/eniconfig.go:61","msg":"******** : Initialized new logger"}
{"level":"info","ts":"2022-07-07T23:02:41.526Z","caller":"networkutils/network.go:128","msg":"******** : Initialized new logger"}
{"level":"info","ts":"2022-07-07T23:02:41.531Z","caller":"awssession/session.go:39","msg":"******** : Initialized new logger"}
{"level":"info","ts":"2022-07-07T23:02:41.531Z","caller":"ec2wrapper/ec2wrapper.go:21","msg":"******** : Initialized new logger"}
{"level":"info","ts":"2022-07-07T23:02:41.537Z","caller":"k8sapi/k8sutils.go:23","msg":"******** : Initialized new logger"}
{"level":"info","ts":"2022-07-07T23:02:41.537Z","caller":"eventrecorder/eventrecorder.go:33","msg":"******** : Initialized new logger"}
{"level":"info","ts":"2022-07-07T23:02:41.538Z","caller":"awsutils/awsutils.go:81","msg":"******** : Initialized new logger"}

Thus, the extra method was removed and nil check was moved in-line, keeping the code simple and easy to read.

[orsenthil]

Understood, and that was the only place it was used, so helps to remove it.

Thank you.

[orsenthil]

I have a question on the change too.

[achevuru]

Since, we go through this only during initial bootup - the leaked file handles show up only if the aws-node pod on the node goes through a restart for some reason? I thought we've a known issue in the upstream logger lib and so curious why we are not running in to that? Would be good to expand on this in the PR description.

[vikasmb]

the leaked file handles show up only if the aws-node pod on the node goes through a restart for some reason?
No, leaked file handles show up with the long running aws-node ipamd daemon. If it is restarted, leaked file handles would disappear.
Core of the issue is that different packages used to obtain different logger instances (pointing to the same underlying file) and upon rotation, file reference would be updated in one logger but not in others, leading to leaked file handle. This change fixes the situation by ensuring that a single logger instance is ever created and the rotation logic within lumberjack ensures that rotation and file closure is properly handled. Unit-test with a single logger instance doing file rotation correctly was confirmed by using delve debugger.

Regarding the upstream issue of natefinch/lumberjack#81, it is not directly applicable in case of ipamd as transient goroutines holding on to logger instances were not observed (using dlv).

[jayanthvn]

Also can we add the UT which you tried? Using that as base commit we can start adding more UTs as follow up.

[orsenthil]

LGTM, Vikas. All my comments are addressed.

[orsenthil]

LGTM, again.

[jayanthvn]

lgtm