Skip to content

Data Race in Hooks #1233

New issue
New issue
Closed
Closed
Data Race in Hooks#1233
Labels
help-wanted
@Tiernan-Stapleton

Description

@Tiernan-Stapleton
Tiernan-Stapleton
opened on Feb 17, 2021

I work with a service that uses logrus extensively.
Our test suite has encountered a race condition in the latest version of logrus (v1.7.1)

The test output is as follows:

$ go test -race ./...
==================
WARNING: DATA RACE
Write at 0x00c000012240 by goroutine 11:
  runtime.mapassign_fast32()
      /usr/local/go/src/runtime/map_fast32.go:92 +0x0
  github.com/sirupsen/logrus.LevelHooks.Add()
      /home/tiernan/code/go-logrus-hook/vendor/github.com/sirupsen/logrus/hooks.go:20 +0x195
  github.com/sirupsen/logrus.(*Logger).AddHook()
      /home/tiernan/code/go-logrus-hook/vendor/github.com/sirupsen/logrus/logger.go:369 +0xbe
  github.com/sirupsen/logrus.AddHook()
      /home/tiernan/code/go-logrus-hook/vendor/github.com/sirupsen/logrus/exported.go:51 +0xaa
  github.com/sirupsen/logrus/hooks/test.NewGlobal()
      /home/tiernan/code/go-logrus-hook/vendor/github.com/sirupsen/logrus/hooks/test/test.go:25 +0x74
  github.com/hpe-hcss/go-logrus-hook/pkg/main_test.TestLog.func1()
      /home/tiernan/code/go-logrus-hook/pkg/main/log_output_test.go:19 +0x59
  testing.tRunner()
      /usr/local/go/src/testing/testing.go:1054 +0x1eb

Previous read at 0x00c000012240 by goroutine 10:
  runtime.mapaccess1_fast32()
      /usr/local/go/src/runtime/map_fast32.go:12 +0x0
  github.com/sirupsen/logrus.LevelHooks.Fire()
      /home/tiernan/code/go-logrus-hook/vendor/github.com/sirupsen/logrus/hooks.go:27 +0x50
  github.com/sirupsen/logrus.(*Entry).fireHooks()
      /home/tiernan/code/go-logrus-hook/vendor/github.com/sirupsen/logrus/entry.go:270 +0xb6
  github.com/sirupsen/logrus.(*Entry).log()
      /home/tiernan/code/go-logrus-hook/vendor/github.com/sirupsen/logrus/entry.go:247 +0x24a
  github.com/sirupsen/logrus.(*Entry).Log()
      /home/tiernan/code/go-logrus-hook/vendor/github.com/sirupsen/logrus/entry.go:293 +0xba
  github.com/sirupsen/logrus.(*Logger).Log()
      /home/tiernan/code/go-logrus-hook/vendor/github.com/sirupsen/logrus/logger.go:198 +0xa2
  github.com/sirupsen/logrus.(*Logger).Info()
      /home/tiernan/code/go-logrus-hook/vendor/github.com/sirupsen/logrus/logger.go:220 +0x124
  github.com/sirupsen/logrus.Info()
      /home/tiernan/code/go-logrus-hook/vendor/github.com/sirupsen/logrus/exported.go:109 +0xe1
  github.com/hpe-hcss/go-logrus-hook/pkg/main_test.TestLog.func1()
      /home/tiernan/code/go-logrus-hook/pkg/main/log_output_test.go:20 +0xab
  testing.tRunner()
      /usr/local/go/src/testing/testing.go:1054 +0x1eb

Goroutine 11 (running) created at:
  testing.(*T).Run()
      /usr/local/go/src/testing/testing.go:1105 +0x700
  github.com/hpe-hcss/go-logrus-hook/pkg/main_test.TestLog()
      /home/tiernan/code/go-logrus-hook/pkg/main/log_output_test.go:16 +0x63
  testing.tRunner()
      /usr/local/go/src/testing/testing.go:1054 +0x1eb

Goroutine 10 (running) created at:
  testing.(*T).Run()
      /usr/local/go/src/testing/testing.go:1105 +0x700
  github.com/hpe-hcss/go-logrus-hook/pkg/main_test.TestLog()
      /home/tiernan/code/go-logrus-hook/pkg/main/log_output_test.go:16 +0x63
  testing.tRunner()
      /usr/local/go/src/testing/testing.go:1054 +0x1eb
==================
==================
WARNING: DATA RACE
Write at 0x00c00019c088 by goroutine 11:
  github.com/sirupsen/logrus.LevelHooks.Add()
      /home/tiernan/code/go-logrus-hook/vendor/github.com/sirupsen/logrus/hooks.go:20 +0x1aa
  github.com/sirupsen/logrus.(*Logger).AddHook()
      /home/tiernan/code/go-logrus-hook/vendor/github.com/sirupsen/logrus/logger.go:369 +0xbe
  github.com/sirupsen/logrus.AddHook()
      /home/tiernan/code/go-logrus-hook/vendor/github.com/sirupsen/logrus/exported.go:51 +0xaa
  github.com/sirupsen/logrus/hooks/test.NewGlobal()
      /home/tiernan/code/go-logrus-hook/vendor/github.com/sirupsen/logrus/hooks/test/test.go:25 +0x74
  github.com/hpe-hcss/go-logrus-hook/pkg/main_test.TestLog.func1()
      /home/tiernan/code/go-logrus-hook/pkg/main/log_output_test.go:19 +0x59
  testing.tRunner()
      /usr/local/go/src/testing/testing.go:1054 +0x1eb

Previous read at 0x00c00019c088 by goroutine 10:
  github.com/sirupsen/logrus.LevelHooks.Fire()
      /home/tiernan/code/go-logrus-hook/vendor/github.com/sirupsen/logrus/hooks.go:27 +0x63
  github.com/sirupsen/logrus.(*Entry).fireHooks()
      /home/tiernan/code/go-logrus-hook/vendor/github.com/sirupsen/logrus/entry.go:270 +0xb6
  github.com/sirupsen/logrus.(*Entry).log()
      /home/tiernan/code/go-logrus-hook/vendor/github.com/sirupsen/logrus/entry.go:247 +0x24a
  github.com/sirupsen/logrus.(*Entry).Log()
      /home/tiernan/code/go-logrus-hook/vendor/github.com/sirupsen/logrus/entry.go:293 +0xba
  github.com/sirupsen/logrus.(*Logger).Log()
      /home/tiernan/code/go-logrus-hook/vendor/github.com/sirupsen/logrus/logger.go:198 +0xa2
  github.com/sirupsen/logrus.(*Logger).Info()
      /home/tiernan/code/go-logrus-hook/vendor/github.com/sirupsen/logrus/logger.go:220 +0x124
  github.com/sirupsen/logrus.Info()
      /home/tiernan/code/go-logrus-hook/vendor/github.com/sirupsen/logrus/exported.go:109 +0xe1
  github.com/hpe-hcss/go-logrus-hook/pkg/main_test.TestLog.func1()
      /home/tiernan/code/go-logrus-hook/pkg/main/log_output_test.go:20 +0xab
  testing.tRunner()
      /usr/local/go/src/testing/testing.go:1054 +0x1eb

Goroutine 11 (running) created at:
  testing.(*T).Run()
      /usr/local/go/src/testing/testing.go:1105 +0x700
  github.com/hpe-hcss/go-logrus-hook/pkg/main_test.TestLog()
      /home/tiernan/code/go-logrus-hook/pkg/main/log_output_test.go:16 +0x63
  testing.tRunner()
      /usr/local/go/src/testing/testing.go:1054 +0x1eb

Goroutine 10 (running) created at:
  testing.(*T).Run()
      /usr/local/go/src/testing/testing.go:1105 +0x700
  github.com/hpe-hcss/go-logrus-hook/pkg/main_test.TestLog()
      /home/tiernan/code/go-logrus-hook/pkg/main/log_output_test.go:16 +0x63
  testing.tRunner()
      /usr/local/go/src/testing/testing.go:1054 +0x1eb
==================
time="2021-02-17T12:27:53Z" level=info msg="Test 1"
time="2021-02-17T12:27:53Z" level=info msg="Test 0"
time="2021-02-17T12:27:53Z" level=info msg="Test 2"
--- FAIL: TestLog (0.00s)
    --- FAIL: TestLog/Test_1 (0.00s)
        testing.go:969: race detected during execution of test
    --- FAIL: TestLog/Test_0 (0.00s)
        testing.go:969: race detected during execution of test
    --- FAIL: TestLog/Test_2 (0.00s)
        testing.go:969: race detected during execution of test
FAIL
FAIL    github.com/hpe-hcss/go-logrus-hook/pkg/main     0.019s
FAIL

I've isolated a minimum test that reproduces the race condition

package main_test

import (
	"fmt"
	"testing"

	"github.com/sirupsen/logrus"
	"github.com/sirupsen/logrus/hooks/test"
)

func TestLog(t *testing.T) {
	t.Parallel()

	for i := 0; i < 3; i++ {
		testname := fmt.Sprintf("Test %d", i)
		t.Run(testname, func(t *testing.T) {
			t.Parallel()

			_ = test.NewGlobal()
			logrus.Info(testname)
		})
	}
}

The race condition appears to be arising from the removal of thread locking here https://github.com/sirupsen/logrus/pull/1229/files#diff-47281dd13b9d34dcb3eb865613c38b837aeef5e4c29287654d1989fa5e84ed98L258

Metadata

Metadata

Assignees

No one assigned

    Labels

    help-wanted

    Projects

    No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions