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

Jump to bottom

Data race in cni-log #15

Open
andreaskaris opened this issue Sep 26, 2023 · 0 comments · May be fixed by #17
Open

Data race in cni-log #15

andreaskaris opened this issue Sep 26, 2023 · 0 comments · May be fixed by #17

Comments

@andreaskaris
Copy link
Contributor

Can be triggered by the following unit test:

+       Context("Logging from different go routines", Ordered, func() {
+               var logFile2 string
+
+               BeforeEach(func() {
+                       tempDir := os.TempDir()
+                       logFile2 = path.Join(tempDir, "test2.log")
+
+                       SetLogFile(logFile)
+                       SetLogStderr(false)
+               })
 
+               AfterEach(func() {
+                       Expect(os.RemoveAll(logFile2)).To(Succeed())
+               })
+
+               When("another go routine manipulates the logger", func() {
+                       It("does not cause a race condition", func() {
+                               go func() {
+                                       SetLogFile(logFile2)
+                               }()
+                               // expected := fmt.Sprintf(`time=".*" level=%q msg=%q`, infoStr, infoMsg)
+                               errStr := captureStdErrEvent(InfoStructured, infoMsg)
+                               Expect(errStr).To(BeEmpty())
+                               // Expect(logFileContainsRegex(logFile, expected)).To(BeTrue())
+                       })
+               })

And by running:

go test -v -race ./... .

Result:

$ go test -count=1 -race ./... --ginkgo.focus='Logging from different go routines'
Running Suite: CNI-LOG Test Suite - /home/akaris/development/cni-log
====================================================================
Random Seed: 1695739922

Will run 1 of 41 specs
SSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSS==================
WARNING: DATA RACE
Read at 0x000000d65450 by goroutine 34:
  github.com/k8snetworkplumbingwg/cni-log.isFileLoggingEnabled()
      /home/akaris/development/cni-log/logging.go:262 +0x84
  github.com/k8snetworkplumbingwg/cni-log.printWithPrefixf()
      /home/akaris/development/cni-log/logging.go:428 +0x8d
  github.com/k8snetworkplumbingwg/cni-log.InfoStructured()
      /home/akaris/development/cni-log/logging.go:367 +0x73
  github.com/k8snetworkplumbingwg/cni-log.captureStdErrEvent()
      /home/akaris/development/cni-log/logging_test.go:722 +0x86
  github.com/k8snetworkplumbingwg/cni-log.glob..func1.11.3.1()
      /home/akaris/development/cni-log/logging_test.go:584 +0xb5
  github.com/onsi/ginkgo/v2/internal.(*Suite).runNode.func2()
      /home/akaris/development/go/pkg/mod/github.com/onsi/ginkgo/[email protected]/internal/suite.go:596 +0xea

Previous write at 0x000000d65450 by goroutine 35:
  github.com/k8snetworkplumbingwg/cni-log.SetLogFile()
      /home/akaris/development/cni-log/logging.go:251 +0x25c
  github.com/k8snetworkplumbingwg/cni-log.glob..func1.11.3.1.1()
      /home/akaris/development/cni-log/logging_test.go:581 +0x44

Goroutine 34 (running) created at:
  github.com/onsi/ginkgo/v2/internal.(*Suite).runNode()
      /home/akaris/development/go/pkg/mod/github.com/onsi/ginkgo/[email protected]/internal/suite.go:584 +0x935
  github.com/onsi/ginkgo/v2/internal.(*group).attemptSpec()
      /home/akaris/development/go/pkg/mod/github.com/onsi/ginkgo/[email protected]/internal/group.go:181 +0xfd8
  github.com/onsi/ginkgo/v2/internal.(*group).run()
      /home/akaris/development/go/pkg/mod/github.com/onsi/ginkgo/[email protected]/internal/group.go:303 +0xe64
  github.com/onsi/ginkgo/v2/internal.(*Suite).runSpecs()
      /home/akaris/development/go/pkg/mod/github.com/onsi/ginkgo/[email protected]/internal/suite.go:304 +0xe86
  github.com/onsi/ginkgo/v2/internal.(*Suite).Run()
      /home/akaris/development/go/pkg/mod/github.com/onsi/ginkgo/[email protected]/internal/suite.go:83 +0x444
  github.com/onsi/ginkgo/v2.RunSpecs()
      /home/akaris/development/go/pkg/mod/github.com/onsi/ginkgo/[email protected]/core_dsl.go:280 +0x16a4
  github.com/k8snetworkplumbingwg/cni-log.TestLogging()
      /home/akaris/development/cni-log/logging_test.go:45 +0x55
  testing.tRunner()
      /usr/lib/golang/src/testing/testing.go:1576 +0x216
  testing.(*T).Run.func1()
      /usr/lib/golang/src/testing/testing.go:1629 +0x47

Goroutine 35 (finished) created at:
  github.com/k8snetworkplumbingwg/cni-log.glob..func1.11.3.1()
      /home/akaris/development/cni-log/logging_test.go:580 +0x96
  github.com/onsi/ginkgo/v2/internal.(*Suite).runNode.func2()
      /home/akaris/development/go/pkg/mod/github.com/onsi/ginkgo/[email protected]/internal/suite.go:596 +0xea
==================
==================
WARNING: DATA RACE
Read at 0x00c000196120 by goroutine 34:
  gopkg.in/natefinch/lumberjack%2ev2.(*Logger).filename()
      /home/akaris/development/go/pkg/mod/gopkg.in/natefinch/[email protected]/lumberjack.go:293 +0x49
  gopkg.in/natefinch/lumberjack%2ev2.(*Logger).openExistingOrNew()
      /home/akaris/development/go/pkg/mod/gopkg.in/natefinch/[email protected]/lumberjack.go:267 +0x5e
  gopkg.in/natefinch/lumberjack%2ev2.(*Logger).Write()
      /home/akaris/development/go/pkg/mod/gopkg.in/natefinch/[email protected]/lumberjack.go:147 +0x2d2
  fmt.Fprintf()
      /usr/lib/golang/src/fmt/print.go:225 +0xb1
  github.com/k8snetworkplumbingwg/cni-log.doWritef()
      /home/akaris/development/cni-log/logging.go:412 +0x6c
  github.com/k8snetworkplumbingwg/cni-log.printWithPrefixf()
      /home/akaris/development/cni-log/logging.go:441 +0x1c5
  github.com/k8snetworkplumbingwg/cni-log.InfoStructured()
      /home/akaris/development/cni-log/logging.go:367 +0x73
  github.com/k8snetworkplumbingwg/cni-log.captureStdErrEvent()
      /home/akaris/development/cni-log/logging_test.go:722 +0x86
  github.com/k8snetworkplumbingwg/cni-log.glob..func1.11.3.1()
      /home/akaris/development/cni-log/logging_test.go:584 +0xb5
  github.com/onsi/ginkgo/v2/internal.(*Suite).runNode.func2()
      /home/akaris/development/go/pkg/mod/github.com/onsi/ginkgo/[email protected]/internal/suite.go:596 +0xea

Previous write at 0x00c000196120 by goroutine 35:
  github.com/k8snetworkplumbingwg/cni-log.SetLogFile()
      /home/akaris/development/cni-log/logging.go:250 +0x206
  github.com/k8snetworkplumbingwg/cni-log.glob..func1.11.3.1.1()
      /home/akaris/development/cni-log/logging_test.go:581 +0x44

Goroutine 34 (running) created at:
  github.com/onsi/ginkgo/v2/internal.(*Suite).runNode()
      /home/akaris/development/go/pkg/mod/github.com/onsi/ginkgo/[email protected]/internal/suite.go:584 +0x935
  github.com/onsi/ginkgo/v2/internal.(*group).attemptSpec()
      /home/akaris/development/go/pkg/mod/github.com/onsi/ginkgo/[email protected]/internal/group.go:181 +0xfd8
  github.com/onsi/ginkgo/v2/internal.(*group).run()
      /home/akaris/development/go/pkg/mod/github.com/onsi/ginkgo/[email protected]/internal/group.go:303 +0xe64
  github.com/onsi/ginkgo/v2/internal.(*Suite).runSpecs()
      /home/akaris/development/go/pkg/mod/github.com/onsi/ginkgo/[email protected]/internal/suite.go:304 +0xe86
  github.com/onsi/ginkgo/v2/internal.(*Suite).Run()
      /home/akaris/development/go/pkg/mod/github.com/onsi/ginkgo/[email protected]/internal/suite.go:83 +0x444
  github.com/onsi/ginkgo/v2.RunSpecs()
      /home/akaris/development/go/pkg/mod/github.com/onsi/ginkgo/[email protected]/core_dsl.go:280 +0x16a4
  github.com/k8snetworkplumbingwg/cni-log.TestLogging()
      /home/akaris/development/cni-log/logging_test.go:45 +0x55
  testing.tRunner()
      /usr/lib/golang/src/testing/testing.go:1576 +0x216
  testing.(*T).Run.func1()
      /usr/lib/golang/src/testing/testing.go:1629 +0x47

Goroutine 35 (finished) created at:
  github.com/k8snetworkplumbingwg/cni-log.glob..func1.11.3.1()
      /home/akaris/development/cni-log/logging_test.go:580 +0x96
  github.com/onsi/ginkgo/v2/internal.(*Suite).runNode.func2()
      /home/akaris/development/go/pkg/mod/github.com/onsi/ginkgo/[email protected]/internal/suite.go:596 +0xea
==================
•

Ran 1 of 41 Specs in 0.004 seconds
SUCCESS! -- 1 Passed | 0 Failed | 0 Pending | 40 Skipped
--- FAIL: TestLogging (0.01s)
    testing.go:1446: race detected during execution of test
FAIL
FAIL	github.com/k8snetworkplumbingwg/cni-log	0.017s
FAIL
This was referenced Sep 26, 2023
Closed
Open
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

Successfully merging a pull request may close this issue.

Make logger threadsafe andreaskaris/cni-log
[wip] Make logger threadsafe andreaskaris/cni-log
1 participant
@andreaskaris