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/v2@v2.1.4/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/v2@v2.1.4/internal/suite.go:584 +0x935
  github.com/onsi/ginkgo/v2/internal.(*group).attemptSpec()
      /home/akaris/development/go/pkg/mod/github.com/onsi/ginkgo/v2@v2.1.4/internal/group.go:181 +0xfd8
  github.com/onsi/ginkgo/v2/internal.(*group).run()
      /home/akaris/development/go/pkg/mod/github.com/onsi/ginkgo/v2@v2.1.4/internal/group.go:303 +0xe64
  github.com/onsi/ginkgo/v2/internal.(*Suite).runSpecs()
      /home/akaris/development/go/pkg/mod/github.com/onsi/ginkgo/v2@v2.1.4/internal/suite.go:304 +0xe86
  github.com/onsi/ginkgo/v2/internal.(*Suite).Run()
      /home/akaris/development/go/pkg/mod/github.com/onsi/ginkgo/v2@v2.1.4/internal/suite.go:83 +0x444
  github.com/onsi/ginkgo/v2.RunSpecs()
      /home/akaris/development/go/pkg/mod/github.com/onsi/ginkgo/v2@v2.1.4/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/v2@v2.1.4/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/lumberjack.v2@v2.0.0/lumberjack.go:293 +0x49
  gopkg.in/natefinch/lumberjack%2ev2.(*Logger).openExistingOrNew()
      /home/akaris/development/go/pkg/mod/gopkg.in/natefinch/lumberjack.v2@v2.0.0/lumberjack.go:267 +0x5e
  gopkg.in/natefinch/lumberjack%2ev2.(*Logger).Write()
      /home/akaris/development/go/pkg/mod/gopkg.in/natefinch/lumberjack.v2@v2.0.0/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/v2@v2.1.4/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/v2@v2.1.4/internal/suite.go:584 +0x935
  github.com/onsi/ginkgo/v2/internal.(*group).attemptSpec()
      /home/akaris/development/go/pkg/mod/github.com/onsi/ginkgo/v2@v2.1.4/internal/group.go:181 +0xfd8
  github.com/onsi/ginkgo/v2/internal.(*group).run()
      /home/akaris/development/go/pkg/mod/github.com/onsi/ginkgo/v2@v2.1.4/internal/group.go:303 +0xe64
  github.com/onsi/ginkgo/v2/internal.(*Suite).runSpecs()
      /home/akaris/development/go/pkg/mod/github.com/onsi/ginkgo/v2@v2.1.4/internal/suite.go:304 +0xe86
  github.com/onsi/ginkgo/v2/internal.(*Suite).Run()
      /home/akaris/development/go/pkg/mod/github.com/onsi/ginkgo/v2@v2.1.4/internal/suite.go:83 +0x444
  github.com/onsi/ginkgo/v2.RunSpecs()
      /home/akaris/development/go/pkg/mod/github.com/onsi/ginkgo/v2@v2.1.4/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/v2@v2.1.4/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