From 3ba540d15d85dcbe7167c1522f9a8521da7dcc69 Mon Sep 17 00:00:00 2001 From: Akshay Shah Date: Mon, 20 Feb 2017 11:00:49 -0800 Subject: [PATCH 1/2] Make global loggers safe for concurrent use I'd originally intended zap's global loggers to be a consenting-adults sort of API in which easily-avoided data races are okay. After just a few migrations, it's become clear just how naive that plan was. This PR adds tests to verify that the global loggers are safe to use and reconfigure concurrently, and it converts the global variables to (short) functions. --- global.go | 54 +++++++++++++++++++++++++++++++++----------------- global_test.go | 48 ++++++++++++++++++++++++++++++++++++-------- 2 files changed, 76 insertions(+), 26 deletions(-) diff --git a/global.go b/global.go index cef613347..d5c5f3f25 100644 --- a/global.go +++ b/global.go @@ -24,31 +24,49 @@ import ( "bytes" "log" "os" + "sync" ) var ( - // L is a global Logger. It defaults to a no-op implementation but can be - // replaced using ReplaceGlobals. - // - // Both L and S are unsynchronized, so replacing them while they're in - // use isn't safe. - L = NewNop() - // S is a global SugaredLogger, similar to L. It also defaults to a no-op - // implementation. - S = L.Sugar() + _globalMu sync.RWMutex + _globalL = NewNop() + _globalS = _globalL.Sugar() ) -// ReplaceGlobals replaces the global Logger L and the global SugaredLogger S, -// and returns a function to restore the original values. +// L returns the global Logger, which can be reconfigured with ReplaceGlobals. // -// Note that replacing the global loggers isn't safe while they're being used; -// in practice, this means that only the owner of the application's main -// function should use this method. +// It's safe for concurrent use. +func L() *Logger { + _globalMu.RLock() + l := _globalL + _globalMu.RUnlock() + return l +} + +// S returns the global SugaredLogger, which can be reconfigured with +// ReplaceGlobals. +// +// It's safe for concurrent use. +func S() *SugaredLogger { + _globalMu.RLock() + s := _globalS + _globalMu.RUnlock() + return s +} + +// ReplaceGlobals replaces the global Logger and the SugaredLogger, and returns +// a function to restore the original values. +// +// It's safe for concurrent use. func ReplaceGlobals(logger *Logger) func() { - prev := *L - L = logger - S = logger.Sugar() - return func() { ReplaceGlobals(&prev) } + // This doesn't require synchronization to be safe, since pointers are a + // single word. + _globalMu.Lock() + prev := _globalL + _globalL = logger + _globalS = logger.Sugar() + _globalMu.Unlock() + return func() { ReplaceGlobals(prev) } } // RedirectStdLog redirects output from the standard library's "log" package to diff --git a/global_test.go b/global_test.go index d6e0713bd..f851759cd 100644 --- a/global_test.go +++ b/global_test.go @@ -22,28 +22,32 @@ package zap import ( "log" + "sync" "testing" + "time" "github.com/stretchr/testify/assert" "github.com/stretchr/testify/require" + "go.uber.org/atomic" "go.uber.org/zap/internal/observer" + "go.uber.org/zap/testutils" "go.uber.org/zap/zapcore" ) func TestReplaceGlobals(t *testing.T) { - initialL := *L - initialS := *S + initialL := *L() + initialS := *S() withLogger(t, DebugLevel, nil, func(l *Logger, logs *observer.ObservedLogs) { - L.Info("no-op") - S.Info("no-op") + L().Info("no-op") + S().Info("no-op") assert.Equal(t, 0, logs.Len(), "Expected initial logs to go to default no-op global.") defer ReplaceGlobals(l)() - L.Info("captured") - S.Info("captured") + L().Info("captured") + S().Info("captured") expected := observer.LoggedEntry{ Entry: zapcore.Entry{Message: "captured"}, Context: []zapcore.Field{}, @@ -56,8 +60,36 @@ func TestReplaceGlobals(t *testing.T) { ) }) - assert.Equal(t, initialL, *L, "Expected func returned from ReplaceGlobals to restore initial L.") - assert.Equal(t, initialS, *S, "Expected func returned from ReplaceGlobals to restore initial S.") + assert.Equal(t, initialL, *L(), "Expected func returned from ReplaceGlobals to restore initial L.") + assert.Equal(t, initialS, *S(), "Expected func returned from ReplaceGlobals to restore initial S.") +} + +func TestGlobalsConcurrentUse(t *testing.T) { + var ( + stop atomic.Bool + wg sync.WaitGroup + ) + + for i := 0; i < 100; i++ { + wg.Add(2) + go func() { + for !stop.Load() { + ReplaceGlobals(NewNop()) + } + wg.Done() + }() + go func() { + for !stop.Load() { + L().With(Int("foo", 42)).Named("main").WithOptions(Development()).Info("") + S().Info("") + } + wg.Done() + }() + } + + testutils.Sleep(100 * time.Millisecond) + stop.Toggle() + wg.Wait() } func TestRedirectStdLog(t *testing.T) { From 1e69a292403e098e4766eca249418fb6b8126d1e Mon Sep 17 00:00:00 2001 From: Akshay Shah Date: Mon, 20 Feb 2017 19:11:16 -0800 Subject: [PATCH 2/2] Last cleanups from CR --- global.go | 2 -- global_test.go | 8 ++++---- 2 files changed, 4 insertions(+), 6 deletions(-) diff --git a/global.go b/global.go index d5c5f3f25..2b8a10c3e 100644 --- a/global.go +++ b/global.go @@ -59,8 +59,6 @@ func S() *SugaredLogger { // // It's safe for concurrent use. func ReplaceGlobals(logger *Logger) func() { - // This doesn't require synchronization to be safe, since pointers are a - // single word. _globalMu.Lock() prev := _globalL _globalL = logger diff --git a/global_test.go b/global_test.go index f851759cd..f14f17533 100644 --- a/global_test.go +++ b/global_test.go @@ -26,13 +26,13 @@ import ( "testing" "time" - "github.com/stretchr/testify/assert" - "github.com/stretchr/testify/require" - "go.uber.org/atomic" - "go.uber.org/zap/internal/observer" "go.uber.org/zap/testutils" "go.uber.org/zap/zapcore" + + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" + "go.uber.org/atomic" ) func TestReplaceGlobals(t *testing.T) {