Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Re-use logger instance #2029

Merged
merged 3 commits into from
Jul 12, 2022
Merged

Re-use logger instance #2029

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
3 commits
Select commit Hold shift + click to select a range
6234c46
Re-use logger instance
vikasmb Jul 11, 2022
b186b76
Added unit tests for logger initialization fix
vikasmb Jul 12, 2022
6a1f353
Merge branch 'master' into master
vikasmb Jul 12, 2022
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
6 changes: 1 addition & 5 deletions cmd/aws-k8s-agent/main.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -30,11 +30,7 @@ func main() {

func _main() int {
//Do not add anything before initializing logger
logConfig := logger.Configuration{
LogLevel: logger.GetLogLevel(),
LogLocation: logger.GetLogLocation(),
}
log := logger.New(&logConfig)
log := logger.Get()
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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).


log.Infof("Starting L-IPAMD %s ...", version.Version)
version.RegisterMetric()
Expand Down
11 changes: 3 additions & 8 deletions pkg/utils/logger/logger.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -47,22 +47,17 @@ type Logger interface {

// Get returns an default instance of the zap logger
func Get() Logger {
var logf = &structuredLogger{}
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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

Thank you.

if logf.isEmpty() {
if log == nil {
logConfig := LoadLogConfig()
log = New(logConfig)
return log
log.Info("Initialized new logger as an existing instance was not found")
}
log = logf
return log
}

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

//New logger initializes logger
func New(inputLogConfig *Configuration) Logger {
log = inputLogConfig.newZapLogger()
log.Info("Constructed new logger instance")
return log
}
15 changes: 15 additions & 0 deletions pkg/utils/logger/logger_test.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -30,6 +30,21 @@ func TestEnvLogFilePath(t *testing.T) {
assert.Equal(t, path, GetLogLocation())
}

func TestLoggerGetSameInstance(t *testing.T) {
log1 := Get()
log2 := Get()

assert.True(t, log1 == log2)
}

func TestLoggerNewAndGetSameInstance(t *testing.T) {
logConfig := LoadLogConfig()
log1 := New(logConfig)
log2 := Get()

assert.True(t, log1 == log2)
}

func TestGetLogFileLocationReturnsDefaultPath(t *testing.T) {
defaultPath := "/host/var/log/aws-routed-eni/ipamd.log"
assert.Equal(t, defaultPath, GetLogLocation())
Expand Down