Data Race in Hooks #1233
Comments
|
Indeed, adding hook concurrently while using the logger can led to a race. |
|
We can find a non-performance impacting fix though. |
|
We add a hook for each concurrent test, if a test fails, we read |
|
What I'm arguing about is the need to add concurrently the same hook on the global logger while firing at it at the same time from different threads. We can do a fix which will both meets the performance needs and your use case, but I wonder how your test case is significant regarding a real usage of the logger. Most of the time the pattern is:
|
|
I'll try to clarify our use case a bit more: We run each test concurrently, on these test threads we add a new hook and do some logic to check for a failed test at the test cleanup stage. If the test failed, we get all the entries that were logged to that test thread's hook and log them to the testing framework's log. This way we can easily see the debug log output of failed tests, while suppressing the logs of passed tests. I appreciate that this usage pattern is out of the norm, but it greatly improves the test verbosity on our large test suite. |
|
@Tiernan-Stapleton you may want to try the last version on master, let me know if that fixes your issue. |
|
Unfortunately still getting a data race on master: I've included a small code snippet of our usage in another test that reproduces the data race, it'll help to highlight our use case package main_test
import (
"fmt"
"io/ioutil"
"os"
"testing"
"github.com/sirupsen/logrus"
"github.com/sirupsen/logrus/hooks/test"
)
func OutputLogsIfFailed(t *testing.T, logHook *test.Hook, previousLevel logrus.Level) {
t.Helper()
if t.Failed() {
for _, entry := range logHook.AllEntries() {
t.Log(entry.String())
}
}
logHook.Reset()
logrus.SetLevel(previousLevel)
logrus.SetOutput(os.Stdout)
}
func RegisterOutputLogsOnFailure(t *testing.T) *test.Hook {
t.Helper()
logHook := test.NewGlobal()
logrus.SetOutput(ioutil.Discard)
previousLevel := logrus.GetLevel()
logrus.SetLevel(logrus.DebugLevel)
t.Cleanup(func() {
t.Helper()
OutputLogsIfFailed(t, logHook, previousLevel)
})
return logHook
}
func TestLog2(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()
RegisterOutputLogsOnFailure(t)
// rest of the test code...
logrus.Debugln(testname)
})
}
} |
|
Event if we add a mutex to protect the Logger field, the outcome will not be predictable because you are modifying in different thread a global logger. You should really use a different logger per thread to be consistent in your run. |
|
as a workaround you can force a trace a single time to ensure the text formatter is completely initialized before starting other test. |
|
the fix is quite easy for this one, the logger level mutex should be used there Line 103 in 6cff360 |
|
I'll take a look at changing to use a logger per thread as suggested, might save the two of us a bit of a headache |
|
@dgsb Any chance of a new release? |
|
@Tiernan-Stapleton new release available https://github.com/sirupsen/logrus/releases/tag/v1.8.1 |
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:
I've isolated a minimum test that reproduces the race condition
The race condition appears to be arising from the removal of thread locking here https://github.com/sirupsen/logrus/pull/1229/files#diff-47281dd13b9d34dcb3eb865613c38b837aeef5e4c29287654d1989fa5e84ed98L258
The text was updated successfully, but these errors were encountered: