From bd9dcdb286f4224c9b87fb7196b67cf684228a18 Mon Sep 17 00:00:00 2001 From: Mura Li Date: Tue, 17 Sep 2019 10:19:59 +0800 Subject: [PATCH 1/6] Fix data race --- integrations/testlogger.go | 17 ++++++++++++++--- 1 file changed, 14 insertions(+), 3 deletions(-) diff --git a/integrations/testlogger.go b/integrations/testlogger.go index 43a1471f6604..91b94ac9f3ca 100644 --- a/integrations/testlogger.go +++ b/integrations/testlogger.go @@ -10,6 +10,7 @@ import ( "os" "runtime" "strings" + "sync" "testing" "code.gitea.io/gitea/modules/log" @@ -25,11 +26,21 @@ type TestLogger struct { var writerCloser = &testLoggerWriterCloser{} type testLoggerWriterCloser struct { + sync.RWMutex t testing.TB } +func (w *testLoggerWriterCloser) setT(t *testing.TB) { + w.Lock() + w.t = *t + w.Unlock() +} + func (w *testLoggerWriterCloser) Write(p []byte) (int, error) { - if w.t != nil { + w.RLock() + t := w.t + w.RUnlock() + if t != nil { if len(p) > 0 && p[len(p)-1] == '\n' { p = p[:len(p)-1] } @@ -54,7 +65,7 @@ func (w *testLoggerWriterCloser) Write(p []byte) (int, error) { } }() - w.t.Log(string(p)) + t.Log(string(p)) return len(p), nil } return len(p), nil @@ -77,7 +88,7 @@ func PrintCurrentTest(t testing.TB, skip ...int) { } else { fmt.Fprintf(os.Stdout, "=== %s (%s:%d)\n", t.Name(), strings.TrimPrefix(filename, prefix), line) } - writerCloser.t = t + writerCloser.setT(&t) } // Printf takes a format and args and prints the string to os.Stdout From 58186f369fbaaf2d1a2b392407a96ed61872a092 Mon Sep 17 00:00:00 2001 From: Mura Li Date: Tue, 17 Sep 2019 11:39:29 +0800 Subject: [PATCH 2/6] Fix data race in modules/log --- modules/log/log.go | 30 +++++++++++++++++++++++++++++- 1 file changed, 29 insertions(+), 1 deletion(-) diff --git a/modules/log/log.go b/modules/log/log.go index 0ca0f3adc5af..5e5ca6390c74 100644 --- a/modules/log/log.go +++ b/modules/log/log.go @@ -8,6 +8,7 @@ import ( "os" "runtime" "strings" + "sync" ) var ( @@ -16,6 +17,7 @@ var ( // NamedLoggers map of named loggers NamedLoggers = make(map[string]*Logger) prefix string + mu sync.RWMutex ) // NewLogger create a logger for the default logger @@ -25,11 +27,17 @@ func NewLogger(bufLen int64, name, provider, config string) *Logger { CriticalWithSkip(1, "Unable to create default logger: %v", err) panic(err) } - return NamedLoggers[DEFAULT] + mu.RLock() + l := NamedLoggers[DEFAULT] + mu.RUnlock() + return l } // NewNamedLogger creates a new named logger for a given configuration func NewNamedLogger(name string, bufLen int64, subname, provider, config string) error { + mu.Lock() + defer mu.Unlock() + logger, ok := NamedLoggers[name] if !ok { logger = newLogger(name, bufLen) @@ -42,6 +50,9 @@ func NewNamedLogger(name string, bufLen int64, subname, provider, config string) // DelNamedLogger closes and deletes the named logger func DelNamedLogger(name string) { + mu.Lock() + defer mu.Unlock() + l, ok := NamedLoggers[name] if ok { delete(NamedLoggers, name) @@ -51,7 +62,9 @@ func DelNamedLogger(name string) { // DelLogger removes the named sublogger from the default logger func DelLogger(name string) error { + mu.RLock() logger := NamedLoggers[DEFAULT] + mu.RUnlock() found, err := logger.DelLogger(name) if !found { Trace("Log %s not found, no need to delete", name) @@ -61,6 +74,9 @@ func DelLogger(name string) error { // GetLogger returns either a named logger or the default logger func GetLogger(name string) *Logger { + mu.RLock() + defer mu.RUnlock() + logger, ok := NamedLoggers[name] if ok { return logger @@ -70,11 +86,15 @@ func GetLogger(name string) *Logger { // GetLevel returns the minimum logger level func GetLevel() Level { + mu.RLock() + defer mu.RUnlock() return NamedLoggers[DEFAULT].GetLevel() } // GetStacktraceLevel returns the minimum logger level func GetStacktraceLevel() Level { + mu.RLock() + defer mu.RUnlock() return NamedLoggers[DEFAULT].GetStacktraceLevel() } @@ -169,6 +189,9 @@ func IsFatal() bool { // Close closes all the loggers func Close() { + mu.Lock() + defer mu.Unlock() + l, ok := NamedLoggers[DEFAULT] if !ok { return @@ -180,6 +203,9 @@ func Close() { // Log a message with defined skip and at logging level // A skip of 0 refers to the caller of this command func Log(skip int, level Level, format string, v ...interface{}) { + mu.RLock() + defer mu.RUnlock() + l, ok := NamedLoggers[DEFAULT] if ok { l.Log(skip+1, level, format, v...) @@ -195,7 +221,9 @@ type LoggerAsWriter struct { // NewLoggerAsWriter creates a Writer representation of the logger with setable log level func NewLoggerAsWriter(level string, ourLoggers ...*Logger) *LoggerAsWriter { if len(ourLoggers) == 0 { + mu.RLock() ourLoggers = []*Logger{NamedLoggers[DEFAULT]} + mu.RUnlock() } l := &LoggerAsWriter{ ourLoggers: ourLoggers, From 3ae6187a6db98efc1962c7e4b0ad18d4d165a0df Mon Sep 17 00:00:00 2001 From: Mura Li Date: Tue, 17 Sep 2019 13:26:37 +0800 Subject: [PATCH 3/6] Make the scope of lock finner-grained --- modules/log/log.go | 3 +-- 1 file changed, 1 insertion(+), 2 deletions(-) diff --git a/modules/log/log.go b/modules/log/log.go index 5e5ca6390c74..8a9e1f45cedf 100644 --- a/modules/log/log.go +++ b/modules/log/log.go @@ -204,9 +204,8 @@ func Close() { // A skip of 0 refers to the caller of this command func Log(skip int, level Level, format string, v ...interface{}) { mu.RLock() - defer mu.RUnlock() - l, ok := NamedLoggers[DEFAULT] + mu.RUnlock() if ok { l.Log(skip+1, level, format, v...) } From 309ac9119c3210e24a7e140264537cec9840f555 Mon Sep 17 00:00:00 2001 From: Mura Li Date: Tue, 17 Sep 2019 13:58:54 +0800 Subject: [PATCH 4/6] Use syc.Map --- modules/log/log.go | 81 +++++++++++++++++++++++----------------------- 1 file changed, 40 insertions(+), 41 deletions(-) diff --git a/modules/log/log.go b/modules/log/log.go index 8a9e1f45cedf..b76e45f448c8 100644 --- a/modules/log/log.go +++ b/modules/log/log.go @@ -11,13 +11,33 @@ import ( "sync" ) +type LoggerMap struct { + sync.Map +} + +func (m *LoggerMap) Load(k string) (*Logger, bool) { + v, ok := m.Map.Load(k) + if !ok { + return nil, false + } + l, ok := v.(*Logger) + return l, ok +} + +func (m *LoggerMap) Store(k string, v *Logger) { + m.Map.Store(k, v) +} + +func (m *LoggerMap) Delete(k string) { + m.Map.Delete(k) +} + var ( // DEFAULT is the name of the default logger DEFAULT = "default" // NamedLoggers map of named loggers - NamedLoggers = make(map[string]*Logger) + NamedLoggers LoggerMap prefix string - mu sync.RWMutex ) // NewLogger create a logger for the default logger @@ -27,22 +47,16 @@ func NewLogger(bufLen int64, name, provider, config string) *Logger { CriticalWithSkip(1, "Unable to create default logger: %v", err) panic(err) } - mu.RLock() - l := NamedLoggers[DEFAULT] - mu.RUnlock() + l, _ := NamedLoggers.Load(DEFAULT) return l } // NewNamedLogger creates a new named logger for a given configuration func NewNamedLogger(name string, bufLen int64, subname, provider, config string) error { - mu.Lock() - defer mu.Unlock() - - logger, ok := NamedLoggers[name] + logger, ok := NamedLoggers.Load(name) if !ok { logger = newLogger(name, bufLen) - - NamedLoggers[name] = logger + NamedLoggers.Store(name, logger) } return logger.SetLogger(subname, provider, config) @@ -50,21 +64,16 @@ func NewNamedLogger(name string, bufLen int64, subname, provider, config string) // DelNamedLogger closes and deletes the named logger func DelNamedLogger(name string) { - mu.Lock() - defer mu.Unlock() - - l, ok := NamedLoggers[name] + l, ok := NamedLoggers.Load(name) if ok { - delete(NamedLoggers, name) + NamedLoggers.Delete(name) l.Close() } } // DelLogger removes the named sublogger from the default logger func DelLogger(name string) error { - mu.RLock() - logger := NamedLoggers[DEFAULT] - mu.RUnlock() + logger, _ := NamedLoggers.Load(DEFAULT) found, err := logger.DelLogger(name) if !found { Trace("Log %s not found, no need to delete", name) @@ -74,28 +83,24 @@ func DelLogger(name string) error { // GetLogger returns either a named logger or the default logger func GetLogger(name string) *Logger { - mu.RLock() - defer mu.RUnlock() - - logger, ok := NamedLoggers[name] + logger, ok := NamedLoggers.Load(name) if ok { return logger } - return NamedLoggers[DEFAULT] + logger, _ = NamedLoggers.Load(DEFAULT) + return logger } // GetLevel returns the minimum logger level func GetLevel() Level { - mu.RLock() - defer mu.RUnlock() - return NamedLoggers[DEFAULT].GetLevel() + l, _ := NamedLoggers.Load(DEFAULT) + return l.GetLevel() } // GetStacktraceLevel returns the minimum logger level func GetStacktraceLevel() Level { - mu.RLock() - defer mu.RUnlock() - return NamedLoggers[DEFAULT].GetStacktraceLevel() + l, _ := NamedLoggers.Load(DEFAULT) + return l.GetStacktraceLevel() } // Trace records trace log @@ -189,23 +194,18 @@ func IsFatal() bool { // Close closes all the loggers func Close() { - mu.Lock() - defer mu.Unlock() - - l, ok := NamedLoggers[DEFAULT] + l, ok := NamedLoggers.Load(DEFAULT) if !ok { return } - delete(NamedLoggers, DEFAULT) + NamedLoggers.Delete(DEFAULT) l.Close() } // Log a message with defined skip and at logging level // A skip of 0 refers to the caller of this command func Log(skip int, level Level, format string, v ...interface{}) { - mu.RLock() - l, ok := NamedLoggers[DEFAULT] - mu.RUnlock() + l, ok := NamedLoggers.Load(DEFAULT) if ok { l.Log(skip+1, level, format, v...) } @@ -220,9 +220,8 @@ type LoggerAsWriter struct { // NewLoggerAsWriter creates a Writer representation of the logger with setable log level func NewLoggerAsWriter(level string, ourLoggers ...*Logger) *LoggerAsWriter { if len(ourLoggers) == 0 { - mu.RLock() - ourLoggers = []*Logger{NamedLoggers[DEFAULT]} - mu.RUnlock() + l, _ := NamedLoggers.Load(DEFAULT) + ourLoggers = []*Logger{l} } l := &LoggerAsWriter{ ourLoggers: ourLoggers, From 4389ed4e301fa88d276803e9609ee6037b01451f Mon Sep 17 00:00:00 2001 From: Mura Li Date: Tue, 17 Sep 2019 14:27:46 +0800 Subject: [PATCH 5/6] Fix missing change in the test --- modules/log/log_test.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/modules/log/log_test.go b/modules/log/log_test.go index 9e3d7527b23d..0e7583081cec 100644 --- a/modules/log/log_test.go +++ b/modules/log/log_test.go @@ -143,7 +143,7 @@ func TestNewNamedLogger(t *testing.T) { level := INFO err := NewNamedLogger("test", 0, "console", "console", fmt.Sprintf(`{"level":"%s"}`, level.String())) assert.NoError(t, err) - logger := NamedLoggers["test"] + logger, _ := NamedLoggers.Load("test") assert.Equal(t, level, logger.GetLevel()) written, closed := baseConsoleTest(t, logger) From e5f7937979a1f8966afa6b0e6a97e821c9f99626 Mon Sep 17 00:00:00 2001 From: Mura Li Date: Tue, 17 Sep 2019 14:33:06 +0800 Subject: [PATCH 6/6] Do not export LoggerMap --- modules/log/log.go | 10 +++++----- 1 file changed, 5 insertions(+), 5 deletions(-) diff --git a/modules/log/log.go b/modules/log/log.go index b76e45f448c8..71e88491f146 100644 --- a/modules/log/log.go +++ b/modules/log/log.go @@ -11,11 +11,11 @@ import ( "sync" ) -type LoggerMap struct { +type loggerMap struct { sync.Map } -func (m *LoggerMap) Load(k string) (*Logger, bool) { +func (m *loggerMap) Load(k string) (*Logger, bool) { v, ok := m.Map.Load(k) if !ok { return nil, false @@ -24,11 +24,11 @@ func (m *LoggerMap) Load(k string) (*Logger, bool) { return l, ok } -func (m *LoggerMap) Store(k string, v *Logger) { +func (m *loggerMap) Store(k string, v *Logger) { m.Map.Store(k, v) } -func (m *LoggerMap) Delete(k string) { +func (m *loggerMap) Delete(k string) { m.Map.Delete(k) } @@ -36,7 +36,7 @@ var ( // DEFAULT is the name of the default logger DEFAULT = "default" // NamedLoggers map of named loggers - NamedLoggers LoggerMap + NamedLoggers loggerMap prefix string )