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.

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

Fix race conditions in logging package functions and enable race detection in tests #1101

Merged
merged 1 commit into from
Aug 11, 2023

Conversation

AlinaSecret
Copy link
Contributor

This PR addresses the race conditions discovered during local testing using the Go race command. The race command detected potential data race conditions in the logging package's SetLogOptions and SetLogFile functions when multiple goroutines accessed and modified the shared logger struct concurrently.

Before applying the fix, the race detector logs indicated conflicting accesses as can be seen here:

WARNING: DATA RACE
Write at 0x00c000040d38 by goroutine 35:
  [gopkg.in/k8snetworkplumbingwg/multus-cni.v4/pkg/logging.SetLogOptions()](http://gopkg.in/k8snetworkplumbingwg/multus-cni.v4/pkg/logging.SetLogOptions())
      /home/asudakov/go/src/github.com/AlinaSecret/multus-cni/pkg/logging/logging.go:61 +0x6e4
  [gopkg.in/k8snetworkplumbingwg/multus-cni.v4/pkg/types.LoadNetConf()](http://gopkg.in/k8snetworkplumbingwg/multus-cni.v4/pkg/types.LoadNetConf())
      /home/asudakov/go/src/github.com/AlinaSecret/multus-cni/pkg/types/conf.go:353 +0x652
  [gopkg.in/k8snetworkplumbingwg/multus-cni.v4/pkg/types.glob](http://gopkg.in/k8snetworkplumbingwg/multus-cni.v4/pkg/types.glob)..func1.6()
      /home/asudakov/go/src/github.com/AlinaSecret/multus-cni/pkg/types/conf_test.go:155 +0x4a
  [github.com/onsi/ginkgo/v2/internal.extractBodyFunction.func3()](http://github.com/onsi/ginkgo/v2/internal.extractBodyFunction.func3())
      /home/asudakov/go/src/github.com/AlinaSecret/multus-cni/vendor/github.com/onsi/ginkgo/v2/internal/node.go:445 +0x30
  [github.com/onsi/ginkgo/v2/internal.(*Suite).runNode.func3()](http://github.com/onsi/ginkgo/v2/internal.(*Suite).runNode.func3())
      /home/asudakov/go/src/github.com/AlinaSecret/multus-cni/vendor/github.com/onsi/ginkgo/v2/internal/suite.go:820 +0x114

Previous read at 0x00c000040d38 by goroutine 31:
  [gopkg.in/natefinch/lumberjack%2ev2.(*Logger).millRunOnce()](http://gopkg.in/natefinch/lumberjack.v2.(*Logger).millRunOnce())
      /home/asudakov/go/src/github.com/AlinaSecret/multus-cni/vendor/gopkg.in/natefinch/lumberjack.v2/lumberjack.go:336 +0x5f2
  [gopkg.in/natefinch/lumberjack%2ev2.(*Logger).millRun()](http://gopkg.in/natefinch/lumberjack.v2.(*Logger).millRun())
      /home/asudakov/go/src/github.com/AlinaSecret/multus-cni/vendor/gopkg.in/natefinch/lumberjack.v2/lumberjack.go:381 +0x56
  [gopkg.in/natefinch/lumberjack%2ev2.(*Logger).mill.func1.1()](http://gopkg.in/natefinch/lumberjack.v2.(*Logger).mill.func1.1())
      /home/asudakov/go/src/github.com/AlinaSecret/multus-cni/vendor/gopkg.in/natefinch/lumberjack.v2/lumberjack.go:390 +0x39

Goroutine 35 (running) created at:
  [github.com/onsi/ginkgo/v2/internal.(*Suite).runNode()](http://github.com/onsi/ginkgo/v2/internal.(*Suite).runNode())
      /home/asudakov/go/src/github.com/AlinaSecret/multus-cni/vendor/github.com/onsi/ginkgo/v2/internal/suite.go:807 +0x1359
  [github.com/onsi/ginkgo/v2/internal.(*group).attemptSpec()](http://github.com/onsi/ginkgo/v2/internal.(*group).attemptSpec())
      /home/asudakov/go/src/github.com/AlinaSecret/multus-cni/vendor/github.com/onsi/ginkgo/v2/internal/group.go:190 +0x1124
  [github.com/onsi/ginkgo/v2/internal.(*group).run()](http://github.com/onsi/ginkgo/v2/internal.(*group).run())
      /home/asudakov/go/src/github.com/AlinaSecret/multus-cni/vendor/github.com/onsi/ginkgo/v2/internal/group.go:330 +0xf67
  [github.com/onsi/ginkgo/v2/internal.(*Suite).runSpecs()](http://github.com/onsi/ginkgo/v2/internal.(*Suite).runSpecs())
      /home/asudakov/go/src/github.com/AlinaSecret/multus-cni/vendor/github.com/onsi/ginkgo/v2/internal/suite.go:441 +0x1146
  [github.com/onsi/ginkgo/v2/internal.(*Suite).Run()](http://github.com/onsi/ginkgo/v2/internal.(*Suite).Run())
      /home/asudakov/go/src/github.com/AlinaSecret/multus-cni/vendor/github.com/onsi/ginkgo/v2/internal/suite.go:110 +0x5f5
  [github.com/onsi/ginkgo/v2.RunSpecs()](http://github.com/onsi/ginkgo/v2.RunSpecs())
      /home/asudakov/go/src/github.com/AlinaSecret/multus-cni/vendor/github.com/onsi/ginkgo/v2/core_dsl.go:296 +0x16ca
  [gopkg.in/k8snetworkplumbingwg/multus-cni.v4/pkg/types.TestConf()](http://gopkg.in/k8snetworkplumbingwg/multus-cni.v4/pkg/types.TestConf())
      /home/asudakov/go/src/github.com/AlinaSecret/multus-cni/pkg/types/conf_test.go:37 +0x55
  testing.tRunner()
      /usr/local/go/src/testing/testing.go:1576 +0x216
  testing.(*T).Run.func1()
      /usr/local/go/src/testing/testing.go:1629 +0x47

Goroutine 31 (running) created at:
  [gopkg.in/natefinch/lumberjack%2ev2.(*Logger).mill.func1()](http://gopkg.in/natefinch/lumberjack.v2.(*Logger).mill.func1())
      /home/asudakov/go/src/github.com/AlinaSecret/multus-cni/vendor/gopkg.in/natefinch/lumberjack.v2/lumberjack.go:390 +0xee
  sync.(*Once).doSlow()
      /usr/local/go/src/sync/once.go:74 +0x101
  sync.(*Once).Do()
      /usr/local/go/src/sync/once.go:65 +0x46
  [gopkg.in/natefinch/lumberjack%2ev2.(*Logger).mill()](http://gopkg.in/natefinch/lumberjack.v2.(*Logger).mill())
      /home/asudakov/go/src/github.com/AlinaSecret/multus-cni/vendor/gopkg.in/natefinch/lumberjack.v2/lumberjack.go:388 +0x55
  [gopkg.in/natefinch/lumberjack%2ev2.(*Logger).openExistingOrNew()](http://gopkg.in/natefinch/lumberjack.v2.(*Logger).openExistingOrNew())
      /home/asudakov/go/src/github.com/AlinaSecret/multus-cni/vendor/gopkg.in/natefinch/lumberjack.v2/lumberjack.go:265 +0x51
  [gopkg.in/natefinch/lumberjack%2ev2.(*Logger).Write()](http://gopkg.in/natefinch/lumberjack.v2.(*Logger).Write())
      /home/asudakov/go/src/github.com/AlinaSecret/multus-cni/vendor/gopkg.in/natefinch/lumberjack.v2/lumberjack.go:147 +0x2d2
  fmt.Fprintf()
      /usr/local/go/src/fmt/print.go:225 +0xb1
  [gopkg.in/k8snetworkplumbingwg/multus-cni.v4/pkg/logging.printf()](http://gopkg.in/k8snetworkplumbingwg/multus-cni.v4/pkg/logging.printf())
      /home/asudakov/go/src/github.com/AlinaSecret/multus-cni/pkg/logging/logging.go:109 +0x271
  [gopkg.in/k8snetworkplumbingwg/multus-cni.v4/pkg/logging.Debugf()](http://gopkg.in/k8snetworkplumbingwg/multus-cni.v4/pkg/logging.Debugf())
      /home/asudakov/go/src/github.com/AlinaSecret/multus-cni/pkg/logging/logging.go:117 +0x179
  [gopkg.in/k8snetworkplumbingwg/multus-cni.v4/pkg/types.LoadDelegateNetConf()](http://gopkg.in/k8snetworkplumbingwg/multus-cni.v4/pkg/types.LoadDelegateNetConf())
      /home/asudakov/go/src/github.com/AlinaSecret/multus-cni/pkg/types/conf.go:69 +0xbb
  [gopkg.in/k8snetworkplumbingwg/multus-cni.v4/pkg/types.LoadNetConf()](http://gopkg.in/k8snetworkplumbingwg/multus-cni.v4/pkg/types.LoadNetConf())
      /home/asudakov/go/src/github.com/AlinaSecret/multus-cni/pkg/types/conf.go:410 +0x1444
  [gopkg.in/k8snetworkplumbingwg/multus-cni.v4/pkg/types.glob](http://gopkg.in/k8snetworkplumbingwg/multus-cni.v4/pkg/types.glob)..func1.5()
      /home/asudakov/go/src/github.com/AlinaSecret/multus-cni/pkg/types/conf_test.go:129 +0x3c
  [github.com/onsi/ginkgo/v2/internal.extractBodyFunction.func3()](http://github.com/onsi/ginkgo/v2/internal.extractBodyFunction.func3())
      /home/asudakov/go/src/github.com/AlinaSecret/multus-cni/vendor/github.com/onsi/ginkgo/v2/internal/node.go:445 +0x30
  [github.com/onsi/ginkgo/v2/internal.(*Suite).runNode.func3()](http://github.com/onsi/ginkgo/v2/internal.(*Suite).runNode.func3())
      /home/asudakov/go/src/github.com/AlinaSecret/multus-cni/vendor/github.com/onsi/ginkgo/v2/internal/suite.go:820 +0x114
==================
==================

To resolve these race conditions, a copy of the logger struct is now created within each function.

This PR enables race detection in unit tests by modifying the the test-go.sh script . The test configuration is updated to include the '-race' flag, allowing thorough race detection during testing.

for further reference about race detection view: https://go.dev/doc/articles/race_detector)

Copy link
Collaborator

@maiqueb maiqueb left a comment

Choose a reason for hiding this comment

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

just a minor nit.

}

func init() {
loggingStderr = true
loggingW = nil
loggingLevel = PanicLevel
logger = &lumberjack.Logger{}

Copy link
Collaborator

Choose a reason for hiding this comment

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

No need for this, right ?

Copy link
Contributor Author

Choose a reason for hiding this comment

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

my bad missed it :) i removed it

Comment on lines 60 to 61
var updatedLogger lumberjack.Logger = lumberjack.Logger{Filename: logger.Filename, MaxAge: logger.MaxAge, MaxBackups: logger.MaxBackups,
Compress: logger.Compress, MaxSize: logger.MaxSize, LocalTime: logger.LocalTime}
Copy link
Collaborator

Choose a reason for hiding this comment

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

sorry for not raising it before, but do you really need to initialize these ? You're over-writing the defaults just below.

I mean, couldn't you just:

var updatedLogger lumberjack.Logger = lumberjack.Logger{
    Filename: logger.Filename, 
    MaxAge: 5,
    MaxBackups: 5,
    Compress: true,
    MaxSize: 100,
    LocalTime: logger.LocalTime
}
if options != nil {
...
}
...

Copy link
Contributor Author

Choose a reason for hiding this comment

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

glad you raised it, changed as you suggested :)

Comment on lines 180 to 181
var updatedLogger lumberjack.Logger = lumberjack.Logger{Filename: filename, MaxAge: logger.MaxAge, MaxBackups: logger.MaxBackups,
Compress: logger.Compress, MaxSize: logger.MaxSize, LocalTime: logger.LocalTime}
Copy link
Collaborator

Choose a reason for hiding this comment

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

please use one attribute per line

Copy link
Contributor Author

Choose a reason for hiding this comment

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

Done

Copy link
Collaborator

@maiqueb maiqueb left a comment

Choose a reason for hiding this comment

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

@dougbtv can you approve running the tests ?...

I don't know why, but it seems I can't trigger those manually.

@maiqueb
Copy link
Collaborator

maiqueb commented Jun 8, 2023

Oh and thanks for the PR! @AlinaSecret

Good catch :)

The logging package contains two functions, SetLogOptions and SetLogFile, that could experience race conditions when multiple goroutines access and modify the logger struct concurrently. 
To address these issues, a copy of the logger struct is now created in each function to eliminate data races.

In addition, the test-go.sh script is updated to include the '-race' flag, enabling race detection during testing. This change helps prevent future race conditions by activating the Go race detector.

Signed-off-by: Alina Sudakov <[email protected]>
Copy link
Member

@dougbtv dougbtv left a comment

Choose a reason for hiding this comment

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

LGTM! Thanks for the contribution.

@dougbtv dougbtv merged commit 8d8aa80 into k8snetworkplumbingwg:master Aug 11, 2023
24 checks passed
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.

3 participants