From c1e68d732670ab934a290f9961fc25bda1256877 Mon Sep 17 00:00:00 2001 From: hnlq715 Date: Sat, 8 Feb 2020 17:08:00 +0800 Subject: [PATCH 01/74] add buffer sync --- zapcore/write_syncer.go | 49 ++++++++++++++++++++++++++++ zapcore/write_syncer_bench_test.go | 52 ++++++++++++++++++++++++++++-- zapcore/write_syncer_test.go | 11 +++++++ 3 files changed, 110 insertions(+), 2 deletions(-) diff --git a/zapcore/write_syncer.go b/zapcore/write_syncer.go index d4a1af3d0..0389ecbe6 100644 --- a/zapcore/write_syncer.go +++ b/zapcore/write_syncer.go @@ -21,8 +21,10 @@ package zapcore import ( + "bufio" "io" "sync" + "time" "go.uber.org/multierr" ) @@ -75,6 +77,53 @@ func (s *lockedWriteSyncer) Sync() error { return err } +type bufferWriterSyncer struct { + bufferWriter *bufio.Writer + ws WriteSyncer +} + +// bufferSize sizes the buffer associated with each log file. It's large +// so that log records can accumulate without the logging thread blocking +// on disk I/O. The flushDaemon will block instead. +const bufferSize = 256 * 1024 + +// flushInterval means the default flush interval +const flushInterval = 30 * time.Second + +// Buffer wraps a WriteSyncer in a buffer to improve performance, +// which is implemented in https://github.com/golang/glog. +func Buffer(ws WriteSyncer) WriteSyncer { + if _, ok := ws.(*bufferWriterSyncer); ok { + // no need to layer on another buffer + return ws + } + + // bufio is not goroutine safe, so add lock writer here + ws = Lock(&bufferWriterSyncer{ + bufferWriter: bufio.NewWriterSize(ws, bufferSize), + }) + + // flush buffer every interval + // we do not need exit this goroutine explicitly + go func() { + for range time.NewTicker(flushInterval).C { + if err := ws.Sync(); err != nil { + return + } + } + }() + + return ws +} + +func (s *bufferWriterSyncer) Write(bs []byte) (int, error) { + return s.bufferWriter.Write(bs) +} + +func (s *bufferWriterSyncer) Sync() error { + return s.bufferWriter.Flush() +} + type writerWrapper struct { io.Writer } diff --git a/zapcore/write_syncer_bench_test.go b/zapcore/write_syncer_bench_test.go index 0209d0f61..ad552684b 100644 --- a/zapcore/write_syncer_bench_test.go +++ b/zapcore/write_syncer_bench_test.go @@ -21,13 +21,16 @@ package zapcore import ( + "io/ioutil" + "os" "testing" + "github.com/stretchr/testify/assert" "go.uber.org/zap/internal/ztest" ) func BenchmarkMultiWriteSyncer(b *testing.B) { - b.Run("2", func(b *testing.B) { + b.Run("2 discarder", func(b *testing.B) { w := NewMultiWriteSyncer( &ztest.Discarder{}, &ztest.Discarder{}, @@ -39,7 +42,7 @@ func BenchmarkMultiWriteSyncer(b *testing.B) { } }) }) - b.Run("4", func(b *testing.B) { + b.Run("4 discarder", func(b *testing.B) { w := NewMultiWriteSyncer( &ztest.Discarder{}, &ztest.Discarder{}, @@ -53,4 +56,49 @@ func BenchmarkMultiWriteSyncer(b *testing.B) { } }) }) + b.Run("4 discarder with buffer", func(b *testing.B) { + w := Buffer(NewMultiWriteSyncer( + &ztest.Discarder{}, + &ztest.Discarder{}, + &ztest.Discarder{}, + &ztest.Discarder{}, + )) + b.ResetTimer() + b.RunParallel(func(pb *testing.PB) { + for pb.Next() { + w.Write([]byte("foobarbazbabble")) + } + }) + }) +} + +func BenchmarkWriteSyncer(b *testing.B) { + b.Run("write file with no buffer", func(b *testing.B) { + file, err := ioutil.TempFile(".", "*") + assert.Nil(b, err) + defer file.Close() + defer os.Remove(file.Name()) + + w := AddSync(file) + b.ResetTimer() + b.RunParallel(func(pb *testing.PB) { + for pb.Next() { + w.Write([]byte("foobarbazbabble")) + } + }) + }) + b.Run("write file with buffer", func(b *testing.B) { + file, err := ioutil.TempFile(".", "*") + assert.Nil(b, err) + defer file.Close() + defer os.Remove(file.Name()) + + w := Buffer(AddSync(file)) + b.ResetTimer() + b.RunParallel(func(pb *testing.PB) { + for pb.Next() { + w.Write([]byte("foobarbazbabble")) + } + }) + }) } diff --git a/zapcore/write_syncer_test.go b/zapcore/write_syncer_test.go index 3ccb0af24..e5b9159c3 100644 --- a/zapcore/write_syncer_test.go +++ b/zapcore/write_syncer_test.go @@ -65,6 +65,17 @@ func TestAddSyncWriter(t *testing.T) { assert.NoError(t, ws.Sync(), "Unexpected error calling a no-op Sync method.") } +func TestBufferWriter(t *testing.T) { + // If we pass a plain io.Writer, make sure that we still get a WriteSyncer + // with a no-op Sync. + buf := &bytes.Buffer{} + ws := Buffer(AddSync(buf)) + requireWriteWorks(t, ws) + assert.Equal(t, "", buf.String(), "Unexpected log calling a no-op Write method.") + assert.NoError(t, ws.Sync(), "Unexpected error calling a no-op Sync method.") + assert.Equal(t, "foo", buf.String(), "Unexpected log calling a no-op Sync method.") +} + func TestNewMultiWriteSyncerWorksForSingleWriter(t *testing.T) { w := &ztest.Buffer{} From df42521ef3eec1774de436fae0c45edf6581921f Mon Sep 17 00:00:00 2001 From: hnlq715 Date: Tue, 11 Feb 2020 11:16:52 +0800 Subject: [PATCH 02/74] support config bufferSize and flushInterval, improve logic --- zapcore/write_syncer.go | 29 +++++++++++++++++++---------- zapcore/write_syncer_bench_test.go | 4 ++-- zapcore/write_syncer_test.go | 8 +++++--- 3 files changed, 26 insertions(+), 15 deletions(-) diff --git a/zapcore/write_syncer.go b/zapcore/write_syncer.go index 0389ecbe6..b95607294 100644 --- a/zapcore/write_syncer.go +++ b/zapcore/write_syncer.go @@ -82,20 +82,29 @@ type bufferWriterSyncer struct { ws WriteSyncer } -// bufferSize sizes the buffer associated with each log file. It's large +// defaultBufferSize sizes the buffer associated with each log file. It's large // so that log records can accumulate without the logging thread blocking -// on disk I/O. The flushDaemon will block instead. -const bufferSize = 256 * 1024 +// on disk I/O untill buffer fills up. The flushDaemon will block instead. +const defaultBufferSize = 256 * 1024 -// flushInterval means the default flush interval -const flushInterval = 30 * time.Second +// defaultFlushInterval means the default flush interval +const defaultFlushInterval = 30 * time.Second // Buffer wraps a WriteSyncer in a buffer to improve performance, -// which is implemented in https://github.com/golang/glog. -func Buffer(ws WriteSyncer) WriteSyncer { - if _, ok := ws.(*bufferWriterSyncer); ok { - // no need to layer on another buffer - return ws +func Buffer(ws WriteSyncer, bufferSize int, flushInterval time.Duration) WriteSyncer { + if lws, ok := ws.(*lockedWriteSyncer); ok { + if _, ok := lws.ws.(*bufferWriterSyncer); ok { + // no need to layer on another buffer + return ws + } + } + + if bufferSize == 0 { + bufferSize = defaultBufferSize + } + + if flushInterval == 0 { + flushInterval = defaultFlushInterval } // bufio is not goroutine safe, so add lock writer here diff --git a/zapcore/write_syncer_bench_test.go b/zapcore/write_syncer_bench_test.go index ad552684b..65626802e 100644 --- a/zapcore/write_syncer_bench_test.go +++ b/zapcore/write_syncer_bench_test.go @@ -62,7 +62,7 @@ func BenchmarkMultiWriteSyncer(b *testing.B) { &ztest.Discarder{}, &ztest.Discarder{}, &ztest.Discarder{}, - )) + ), 0, 0) b.ResetTimer() b.RunParallel(func(pb *testing.PB) { for pb.Next() { @@ -93,7 +93,7 @@ func BenchmarkWriteSyncer(b *testing.B) { defer file.Close() defer os.Remove(file.Name()) - w := Buffer(AddSync(file)) + w := Buffer(AddSync(file), 0, 0) b.ResetTimer() b.RunParallel(func(pb *testing.PB) { for pb.Next() { diff --git a/zapcore/write_syncer_test.go b/zapcore/write_syncer_test.go index e5b9159c3..845635738 100644 --- a/zapcore/write_syncer_test.go +++ b/zapcore/write_syncer_test.go @@ -24,6 +24,7 @@ import ( "bytes" "errors" "testing" + "time" "io" @@ -69,11 +70,12 @@ func TestBufferWriter(t *testing.T) { // If we pass a plain io.Writer, make sure that we still get a WriteSyncer // with a no-op Sync. buf := &bytes.Buffer{} - ws := Buffer(AddSync(buf)) + ws := Buffer(Buffer(AddSync(buf), 0, time.Millisecond), 0, 0) requireWriteWorks(t, ws) assert.Equal(t, "", buf.String(), "Unexpected log calling a no-op Write method.") - assert.NoError(t, ws.Sync(), "Unexpected error calling a no-op Sync method.") - assert.Equal(t, "foo", buf.String(), "Unexpected log calling a no-op Sync method.") + time.Sleep(2 * time.Millisecond) + // assert.NoError(t, ws.Sync(), "Unexpected error calling a no-op Sync method.") + assert.Equal(t, "foo", buf.String(), "Unexpected log string") } func TestNewMultiWriteSyncerWorksForSingleWriter(t *testing.T) { From 7f5e097a6046507dee379e10b6a103e3dd87a10b Mon Sep 17 00:00:00 2001 From: hnlq715 Date: Thu, 13 Feb 2020 19:26:04 +0800 Subject: [PATCH 03/74] improve --- zapcore/write_syncer.go | 15 +++++++++++++++ zapcore/write_syncer_test.go | 25 +++++++++++++++++-------- 2 files changed, 32 insertions(+), 8 deletions(-) diff --git a/zapcore/write_syncer.go b/zapcore/write_syncer.go index b95607294..13d8ce975 100644 --- a/zapcore/write_syncer.go +++ b/zapcore/write_syncer.go @@ -91,6 +91,8 @@ const defaultBufferSize = 256 * 1024 const defaultFlushInterval = 30 * time.Second // Buffer wraps a WriteSyncer in a buffer to improve performance, +// if bufferSize=0, we set it to defaultBufferSize +// if flushInterval=0, we set it to defaultFlushInterval func Buffer(ws WriteSyncer, bufferSize int, flushInterval time.Duration) WriteSyncer { if lws, ok := ws.(*lockedWriteSyncer); ok { if _, ok := lws.ws.(*bufferWriterSyncer); ok { @@ -126,6 +128,19 @@ func Buffer(ws WriteSyncer, bufferSize int, flushInterval time.Duration) WriteSy } func (s *bufferWriterSyncer) Write(bs []byte) (int, error) { + + // there are some logic internal for bufio.Writer here: + // 1. when the buffer is not enough, log would be written to disk directly + // 2. when the buffer is enough, log would not be flushed until the buffer is filled up + // this would lead to log spliting, which is not acceptable for log collector + // so we need to flush bufferWriter before writing the log into bufferWriter + if len(bs) > s.bufferWriter.Available() && s.bufferWriter.Buffered() > 0 { + err := s.bufferWriter.Flush() + if err != nil { + return 0, err + } + } + return s.bufferWriter.Write(bs) } diff --git a/zapcore/write_syncer_test.go b/zapcore/write_syncer_test.go index 845635738..257a0eb74 100644 --- a/zapcore/write_syncer_test.go +++ b/zapcore/write_syncer_test.go @@ -24,7 +24,6 @@ import ( "bytes" "errors" "testing" - "time" "io" @@ -69,13 +68,23 @@ func TestAddSyncWriter(t *testing.T) { func TestBufferWriter(t *testing.T) { // If we pass a plain io.Writer, make sure that we still get a WriteSyncer // with a no-op Sync. - buf := &bytes.Buffer{} - ws := Buffer(Buffer(AddSync(buf), 0, time.Millisecond), 0, 0) - requireWriteWorks(t, ws) - assert.Equal(t, "", buf.String(), "Unexpected log calling a no-op Write method.") - time.Sleep(2 * time.Millisecond) - // assert.NoError(t, ws.Sync(), "Unexpected error calling a no-op Sync method.") - assert.Equal(t, "foo", buf.String(), "Unexpected log string") + t.Run("default", func(t *testing.T) { + buf := &bytes.Buffer{} + ws := Buffer(Buffer(AddSync(buf), 0, 0), 0, 0) + requireWriteWorks(t, ws) + assert.Equal(t, "", buf.String(), "Unexpected log calling a no-op Write method.") + assert.NoError(t, ws.Sync(), "Unexpected error calling a no-op Sync method.") + assert.Equal(t, "foo", buf.String(), "Unexpected log string") + }) + + t.Run("small buffer", func(t *testing.T) { + buf := &bytes.Buffer{} + ws := Buffer(Buffer(AddSync(buf), 5, 0), 5, 0) + requireWriteWorks(t, ws) + assert.Equal(t, "", buf.String(), "Unexpected log calling a no-op Write method.") + requireWriteWorks(t, ws) + assert.Equal(t, "foo", buf.String(), "Unexpected log string") + }) } func TestNewMultiWriteSyncerWorksForSingleWriter(t *testing.T) { From 7eec047ad2ad610eb2e986de01e1d9ea339d827c Mon Sep 17 00:00:00 2001 From: hnlq715 Date: Thu, 13 Feb 2020 19:38:24 +0800 Subject: [PATCH 04/74] update comment --- zapcore/write_syncer.go | 14 ++++++-------- 1 file changed, 6 insertions(+), 8 deletions(-) diff --git a/zapcore/write_syncer.go b/zapcore/write_syncer.go index 13d8ce975..992bd1004 100644 --- a/zapcore/write_syncer.go +++ b/zapcore/write_syncer.go @@ -82,17 +82,15 @@ type bufferWriterSyncer struct { ws WriteSyncer } -// defaultBufferSize sizes the buffer associated with each log file. It's large -// so that log records can accumulate without the logging thread blocking -// on disk I/O untill buffer fills up. The flushDaemon will block instead. +// defaultBufferSize sizes the buffer associated with each WriterSync. const defaultBufferSize = 256 * 1024 // defaultFlushInterval means the default flush interval const defaultFlushInterval = 30 * time.Second // Buffer wraps a WriteSyncer in a buffer to improve performance, -// if bufferSize=0, we set it to defaultBufferSize -// if flushInterval=0, we set it to defaultFlushInterval +// if bufferSize = 0, we set it to defaultBufferSize +// if flushInterval = 0, we set it to defaultFlushInterval func Buffer(ws WriteSyncer, bufferSize int, flushInterval time.Duration) WriteSyncer { if lws, ok := ws.(*lockedWriteSyncer); ok { if _, ok := lws.ws.(*bufferWriterSyncer); ok { @@ -130,10 +128,10 @@ func Buffer(ws WriteSyncer, bufferSize int, flushInterval time.Duration) WriteSy func (s *bufferWriterSyncer) Write(bs []byte) (int, error) { // there are some logic internal for bufio.Writer here: - // 1. when the buffer is not enough, log would be written to disk directly - // 2. when the buffer is enough, log would not be flushed until the buffer is filled up + // 1. when the buffer is enough, data would not be flushed. + // 2. when the buffer is not enough, data would be flushed as soon as the buffer fills up. // this would lead to log spliting, which is not acceptable for log collector - // so we need to flush bufferWriter before writing the log into bufferWriter + // so we need to flush bufferWriter before writing the data into bufferWriter if len(bs) > s.bufferWriter.Available() && s.bufferWriter.Buffered() > 0 { err := s.bufferWriter.Flush() if err != nil { From 3c8ec7b7bcb203e3ab2db1578c808a6fde5facc5 Mon Sep 17 00:00:00 2001 From: hnlq715 Date: Tue, 25 Feb 2020 10:49:19 +0800 Subject: [PATCH 05/74] WriterSyncer support Close method --- internal/ztest/writer.go | 7 +++++++ logger.go | 6 ++++++ sink.go | 2 -- writer_test.go | 4 ++++ zapcore/core.go | 7 +++++++ zapcore/sampler_test.go | 1 + zapcore/tee.go | 8 ++++++++ zapcore/write_syncer.go | 36 ++++++++++++++++++++++++++++++++---- zapcore/write_syncer_test.go | 9 +++++++++ zaptest/logger.go | 4 ++++ zaptest/observer/observer.go | 4 ++++ 11 files changed, 82 insertions(+), 6 deletions(-) diff --git a/internal/ztest/writer.go b/internal/ztest/writer.go index 9fdd5805e..2c1a3fb89 100644 --- a/internal/ztest/writer.go +++ b/internal/ztest/writer.go @@ -45,6 +45,13 @@ func (s *Syncer) Sync() error { return s.err } +// Close records that it was called, then returns the user-supplied error (if +// any). +func (s *Syncer) Close() error { + s.called = true + return s.err +} + // Called reports whether the Sync method was called. func (s *Syncer) Called() bool { return s.called diff --git a/logger.go b/logger.go index c6ab4b0ef..52bece886 100644 --- a/logger.go +++ b/logger.go @@ -247,6 +247,12 @@ func (log *Logger) Sync() error { return log.core.Sync() } +// Close calls the underlying Core's Close method, flushing any buffered log +// entries. Applications should take care to call Close before exiting. +func (log *Logger) Close() error { + return log.core.Close() +} + // Core returns the Logger's underlying zapcore.Core. func (log *Logger) Core() zapcore.Core { return log.core diff --git a/sink.go b/sink.go index df46fa87a..ba9172b17 100644 --- a/sink.go +++ b/sink.go @@ -23,7 +23,6 @@ package zap import ( "errors" "fmt" - "io" "net/url" "os" "strings" @@ -55,7 +54,6 @@ func resetSinkRegistry() { // Sink defines the interface to write to and close logger destinations. type Sink interface { zapcore.WriteSyncer - io.Closer } type nopCloserSink struct{ zapcore.WriteSyncer } diff --git a/writer_test.go b/writer_test.go index b9b5389ca..94e90da76 100644 --- a/writer_test.go +++ b/writer_test.go @@ -152,6 +152,10 @@ func (w *testWriter) Sync() error { return nil } +func (w *testWriter) Close() error { + return nil +} + func TestOpenWithErroringSinkFactory(t *testing.T) { defer resetSinkRegistry() diff --git a/zapcore/core.go b/zapcore/core.go index a1ef8b034..98abc6399 100644 --- a/zapcore/core.go +++ b/zapcore/core.go @@ -42,6 +42,8 @@ type Core interface { Write(Entry, []Field) error // Sync flushes buffered logs (if any). Sync() error + // Close cleans all WriterSync resources (if any). + Close() error } type nopCore struct{} @@ -53,6 +55,7 @@ func (n nopCore) With([]Field) Core { return n } func (nopCore) Check(_ Entry, ce *CheckedEntry) *CheckedEntry { return ce } func (nopCore) Write(Entry, []Field) error { return nil } func (nopCore) Sync() error { return nil } +func (nopCore) Close() error { return nil } // NewCore creates a Core that writes logs to a WriteSyncer. func NewCore(enc Encoder, ws WriteSyncer, enab LevelEnabler) Core { @@ -104,6 +107,10 @@ func (c *ioCore) Sync() error { return c.out.Sync() } +func (c *ioCore) Close() error { + return c.out.Close() +} + func (c *ioCore) clone() *ioCore { return &ioCore{ LevelEnabler: c.LevelEnabler, diff --git a/zapcore/sampler_test.go b/zapcore/sampler_test.go index 71db0f9bd..f0a8328f2 100644 --- a/zapcore/sampler_test.go +++ b/zapcore/sampler_test.go @@ -151,6 +151,7 @@ func (c *countingCore) Write(Entry, []Field) error { func (c *countingCore) With([]Field) Core { return c } func (*countingCore) Enabled(Level) bool { return true } func (*countingCore) Sync() error { return nil } +func (*countingCore) Close() error { return nil } func TestSamplerConcurrent(t *testing.T) { const ( diff --git a/zapcore/tee.go b/zapcore/tee.go index 07a32eef9..93ac0e7dc 100644 --- a/zapcore/tee.go +++ b/zapcore/tee.go @@ -79,3 +79,11 @@ func (mc multiCore) Sync() error { } return err } + +func (mc multiCore) Close() error { + var err error + for i := range mc { + err = multierr.Append(err, mc[i].Close()) + } + return err +} diff --git a/zapcore/write_syncer.go b/zapcore/write_syncer.go index 992bd1004..1263e6f1c 100644 --- a/zapcore/write_syncer.go +++ b/zapcore/write_syncer.go @@ -22,6 +22,7 @@ package zapcore import ( "bufio" + "context" "io" "sync" "time" @@ -33,12 +34,13 @@ import ( // that *os.File (and thus, os.Stderr and os.Stdout) implement WriteSyncer. type WriteSyncer interface { io.Writer + Close() error Sync() error } // AddSync converts an io.Writer to a WriteSyncer. It attempts to be // intelligent: if the concrete type of the io.Writer implements WriteSyncer, -// we'll use the existing Sync method. If it doesn't, we'll add a no-op Sync. +// we'll use the existing Sync and Close method. If it doesn't, we'll add a no-op Sync and Close. func AddSync(w io.Writer) WriteSyncer { switch w := w.(type) { case WriteSyncer: @@ -77,9 +79,17 @@ func (s *lockedWriteSyncer) Sync() error { return err } +func (s *lockedWriteSyncer) Close() error { + s.Lock() + err := s.ws.Close() + s.Unlock() + return err +} + type bufferWriterSyncer struct { - bufferWriter *bufio.Writer ws WriteSyncer + bufferWriter *bufio.Writer + cancel context.CancelFunc } // defaultBufferSize sizes the buffer associated with each WriterSync. @@ -107,18 +117,24 @@ func Buffer(ws WriteSyncer, bufferSize int, flushInterval time.Duration) WriteSy flushInterval = defaultFlushInterval } + ctx, cancel := context.WithCancel(context.Background()) + // bufio is not goroutine safe, so add lock writer here ws = Lock(&bufferWriterSyncer{ bufferWriter: bufio.NewWriterSize(ws, bufferSize), + cancel: cancel, }) // flush buffer every interval // we do not need exit this goroutine explicitly go func() { - for range time.NewTicker(flushInterval).C { + select { + case <-time.NewTicker(flushInterval).C: if err := ws.Sync(); err != nil { return } + case <-ctx.Done(): + return } }() @@ -126,7 +142,6 @@ func Buffer(ws WriteSyncer, bufferSize int, flushInterval time.Duration) WriteSy } func (s *bufferWriterSyncer) Write(bs []byte) (int, error) { - // there are some logic internal for bufio.Writer here: // 1. when the buffer is enough, data would not be flushed. // 2. when the buffer is not enough, data would be flushed as soon as the buffer fills up. @@ -146,6 +161,11 @@ func (s *bufferWriterSyncer) Sync() error { return s.bufferWriter.Flush() } +func (s *bufferWriterSyncer) Close() error { + s.cancel() + return s.Sync() +} + type writerWrapper struct { io.Writer } @@ -154,6 +174,10 @@ func (w writerWrapper) Sync() error { return nil } +func (w writerWrapper) Close() error { + return nil +} + type multiWriteSyncer []WriteSyncer // NewMultiWriteSyncer creates a WriteSyncer that duplicates its writes @@ -191,3 +215,7 @@ func (ws multiWriteSyncer) Sync() error { } return err } + +func (ws multiWriteSyncer) Close() error { + return ws.Sync() +} diff --git a/zapcore/write_syncer_test.go b/zapcore/write_syncer_test.go index 257a0eb74..33f93643a 100644 --- a/zapcore/write_syncer_test.go +++ b/zapcore/write_syncer_test.go @@ -85,6 +85,15 @@ func TestBufferWriter(t *testing.T) { requireWriteWorks(t, ws) assert.Equal(t, "foo", buf.String(), "Unexpected log string") }) + + t.Run("cancel context", func(t *testing.T) { + buf := &bytes.Buffer{} + ws := Buffer(Buffer(AddSync(buf), 0, 0), 0, 0) + requireWriteWorks(t, ws) + assert.Equal(t, "", buf.String(), "Unexpected log calling a no-op Write method.") + assert.NoError(t, ws.Close(), "Unexpected error calling a no-op Sync method.") + assert.Equal(t, "foo", buf.String(), "Unexpected log string") + }) } func TestNewMultiWriteSyncerWorksForSingleWriter(t *testing.T) { diff --git a/zaptest/logger.go b/zaptest/logger.go index 1e2451c26..f95304e4f 100644 --- a/zaptest/logger.go +++ b/zaptest/logger.go @@ -138,3 +138,7 @@ func (w testingWriter) Write(p []byte) (n int, err error) { func (w testingWriter) Sync() error { return nil } + +func (w testingWriter) Close() error { + return nil +} diff --git a/zaptest/observer/observer.go b/zaptest/observer/observer.go index 6ae58f5d6..06ec7ab73 100644 --- a/zaptest/observer/observer.go +++ b/zaptest/observer/observer.go @@ -177,3 +177,7 @@ func (co *contextObserver) Write(ent zapcore.Entry, fields []zapcore.Field) erro func (co *contextObserver) Sync() error { return nil } + +func (co *contextObserver) Close() error { + return nil +} From 046355f4eb0850a8f9eb2d0fb869139605245ca7 Mon Sep 17 00:00:00 2001 From: hnlq715 Date: Tue, 25 Feb 2020 11:12:41 +0800 Subject: [PATCH 06/74] improve --- zapcore/write_syncer_test.go | 15 ++++++++------- 1 file changed, 8 insertions(+), 7 deletions(-) diff --git a/zapcore/write_syncer_test.go b/zapcore/write_syncer_test.go index 33f93643a..eb16465c7 100644 --- a/zapcore/write_syncer_test.go +++ b/zapcore/write_syncer_test.go @@ -68,7 +68,7 @@ func TestAddSyncWriter(t *testing.T) { func TestBufferWriter(t *testing.T) { // If we pass a plain io.Writer, make sure that we still get a WriteSyncer // with a no-op Sync. - t.Run("default", func(t *testing.T) { + t.Run("sync", func(t *testing.T) { buf := &bytes.Buffer{} ws := Buffer(Buffer(AddSync(buf), 0, 0), 0, 0) requireWriteWorks(t, ws) @@ -77,23 +77,24 @@ func TestBufferWriter(t *testing.T) { assert.Equal(t, "foo", buf.String(), "Unexpected log string") }) - t.Run("small buffer", func(t *testing.T) { + t.Run("close", func(t *testing.T) { buf := &bytes.Buffer{} - ws := Buffer(Buffer(AddSync(buf), 5, 0), 5, 0) + ws := Buffer(Buffer(AddSync(buf), 0, 0), 0, 0) requireWriteWorks(t, ws) assert.Equal(t, "", buf.String(), "Unexpected log calling a no-op Write method.") - requireWriteWorks(t, ws) + assert.NoError(t, ws.Close(), "Unexpected error calling a no-op Sync method.") assert.Equal(t, "foo", buf.String(), "Unexpected log string") }) - t.Run("cancel context", func(t *testing.T) { + t.Run("small buffer", func(t *testing.T) { buf := &bytes.Buffer{} - ws := Buffer(Buffer(AddSync(buf), 0, 0), 0, 0) + ws := Buffer(Buffer(AddSync(buf), 5, 0), 5, 0) requireWriteWorks(t, ws) assert.Equal(t, "", buf.String(), "Unexpected log calling a no-op Write method.") - assert.NoError(t, ws.Close(), "Unexpected error calling a no-op Sync method.") + requireWriteWorks(t, ws) assert.Equal(t, "foo", buf.String(), "Unexpected log string") }) + } func TestNewMultiWriteSyncerWorksForSingleWriter(t *testing.T) { From afe872fc1d076c1254ed21a97de06e932400f00d Mon Sep 17 00:00:00 2001 From: hnlq715 Date: Tue, 25 Feb 2020 11:13:18 +0800 Subject: [PATCH 07/74] fix spell --- zapcore/write_syncer_test.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/zapcore/write_syncer_test.go b/zapcore/write_syncer_test.go index eb16465c7..3f068b0c0 100644 --- a/zapcore/write_syncer_test.go +++ b/zapcore/write_syncer_test.go @@ -82,7 +82,7 @@ func TestBufferWriter(t *testing.T) { ws := Buffer(Buffer(AddSync(buf), 0, 0), 0, 0) requireWriteWorks(t, ws) assert.Equal(t, "", buf.String(), "Unexpected log calling a no-op Write method.") - assert.NoError(t, ws.Close(), "Unexpected error calling a no-op Sync method.") + assert.NoError(t, ws.Close(), "Unexpected error calling a no-op Close method.") assert.Equal(t, "foo", buf.String(), "Unexpected log string") }) From cce50b148745aebd1d8fb7a148e67058bae2d88d Mon Sep 17 00:00:00 2001 From: hnlq715 Date: Tue, 3 Mar 2020 15:48:21 +0800 Subject: [PATCH 08/74] improve cancel logic --- internal/ztest/writer.go | 7 ------- logger.go | 6 ------ sink.go | 2 ++ writer_test.go | 4 ---- zapcore/core.go | 7 ------- zapcore/sampler_test.go | 1 - zapcore/tee.go | 8 -------- zapcore/write_syncer.go | 33 ++++++++++++------------------ zapcore/write_syncer_bench_test.go | 6 ++++-- zapcore/write_syncer_test.go | 25 +++++++++++++++++----- 10 files changed, 39 insertions(+), 60 deletions(-) diff --git a/internal/ztest/writer.go b/internal/ztest/writer.go index 2c1a3fb89..9fdd5805e 100644 --- a/internal/ztest/writer.go +++ b/internal/ztest/writer.go @@ -45,13 +45,6 @@ func (s *Syncer) Sync() error { return s.err } -// Close records that it was called, then returns the user-supplied error (if -// any). -func (s *Syncer) Close() error { - s.called = true - return s.err -} - // Called reports whether the Sync method was called. func (s *Syncer) Called() bool { return s.called diff --git a/logger.go b/logger.go index 52bece886..c6ab4b0ef 100644 --- a/logger.go +++ b/logger.go @@ -247,12 +247,6 @@ func (log *Logger) Sync() error { return log.core.Sync() } -// Close calls the underlying Core's Close method, flushing any buffered log -// entries. Applications should take care to call Close before exiting. -func (log *Logger) Close() error { - return log.core.Close() -} - // Core returns the Logger's underlying zapcore.Core. func (log *Logger) Core() zapcore.Core { return log.core diff --git a/sink.go b/sink.go index ba9172b17..df46fa87a 100644 --- a/sink.go +++ b/sink.go @@ -23,6 +23,7 @@ package zap import ( "errors" "fmt" + "io" "net/url" "os" "strings" @@ -54,6 +55,7 @@ func resetSinkRegistry() { // Sink defines the interface to write to and close logger destinations. type Sink interface { zapcore.WriteSyncer + io.Closer } type nopCloserSink struct{ zapcore.WriteSyncer } diff --git a/writer_test.go b/writer_test.go index 94e90da76..b9b5389ca 100644 --- a/writer_test.go +++ b/writer_test.go @@ -152,10 +152,6 @@ func (w *testWriter) Sync() error { return nil } -func (w *testWriter) Close() error { - return nil -} - func TestOpenWithErroringSinkFactory(t *testing.T) { defer resetSinkRegistry() diff --git a/zapcore/core.go b/zapcore/core.go index 98abc6399..a1ef8b034 100644 --- a/zapcore/core.go +++ b/zapcore/core.go @@ -42,8 +42,6 @@ type Core interface { Write(Entry, []Field) error // Sync flushes buffered logs (if any). Sync() error - // Close cleans all WriterSync resources (if any). - Close() error } type nopCore struct{} @@ -55,7 +53,6 @@ func (n nopCore) With([]Field) Core { return n } func (nopCore) Check(_ Entry, ce *CheckedEntry) *CheckedEntry { return ce } func (nopCore) Write(Entry, []Field) error { return nil } func (nopCore) Sync() error { return nil } -func (nopCore) Close() error { return nil } // NewCore creates a Core that writes logs to a WriteSyncer. func NewCore(enc Encoder, ws WriteSyncer, enab LevelEnabler) Core { @@ -107,10 +104,6 @@ func (c *ioCore) Sync() error { return c.out.Sync() } -func (c *ioCore) Close() error { - return c.out.Close() -} - func (c *ioCore) clone() *ioCore { return &ioCore{ LevelEnabler: c.LevelEnabler, diff --git a/zapcore/sampler_test.go b/zapcore/sampler_test.go index f0a8328f2..71db0f9bd 100644 --- a/zapcore/sampler_test.go +++ b/zapcore/sampler_test.go @@ -151,7 +151,6 @@ func (c *countingCore) Write(Entry, []Field) error { func (c *countingCore) With([]Field) Core { return c } func (*countingCore) Enabled(Level) bool { return true } func (*countingCore) Sync() error { return nil } -func (*countingCore) Close() error { return nil } func TestSamplerConcurrent(t *testing.T) { const ( diff --git a/zapcore/tee.go b/zapcore/tee.go index 93ac0e7dc..07a32eef9 100644 --- a/zapcore/tee.go +++ b/zapcore/tee.go @@ -79,11 +79,3 @@ func (mc multiCore) Sync() error { } return err } - -func (mc multiCore) Close() error { - var err error - for i := range mc { - err = multierr.Append(err, mc[i].Close()) - } - return err -} diff --git a/zapcore/write_syncer.go b/zapcore/write_syncer.go index 1263e6f1c..be98da5fe 100644 --- a/zapcore/write_syncer.go +++ b/zapcore/write_syncer.go @@ -34,7 +34,6 @@ import ( // that *os.File (and thus, os.Stderr and os.Stdout) implement WriteSyncer. type WriteSyncer interface { io.Writer - Close() error Sync() error } @@ -79,17 +78,9 @@ func (s *lockedWriteSyncer) Sync() error { return err } -func (s *lockedWriteSyncer) Close() error { - s.Lock() - err := s.ws.Close() - s.Unlock() - return err -} - type bufferWriterSyncer struct { ws WriteSyncer bufferWriter *bufio.Writer - cancel context.CancelFunc } // defaultBufferSize sizes the buffer associated with each WriterSync. @@ -98,14 +89,24 @@ const defaultBufferSize = 256 * 1024 // defaultFlushInterval means the default flush interval const defaultFlushInterval = 30 * time.Second +// CancelFunc should be called when the caller exits to clean up buffers. +type CancelFunc func() error + // Buffer wraps a WriteSyncer in a buffer to improve performance, // if bufferSize = 0, we set it to defaultBufferSize // if flushInterval = 0, we set it to defaultFlushInterval -func Buffer(ws WriteSyncer, bufferSize int, flushInterval time.Duration) WriteSyncer { +func Buffer(ws WriteSyncer, bufferSize int, flushInterval time.Duration) (WriteSyncer, CancelFunc) { + ctx, cancel := context.WithCancel(context.Background()) + + cancelfunc := func() error { + cancel() + return ws.Sync() + } + if lws, ok := ws.(*lockedWriteSyncer); ok { if _, ok := lws.ws.(*bufferWriterSyncer); ok { // no need to layer on another buffer - return ws + return ws, cancelfunc } } @@ -117,12 +118,9 @@ func Buffer(ws WriteSyncer, bufferSize int, flushInterval time.Duration) WriteSy flushInterval = defaultFlushInterval } - ctx, cancel := context.WithCancel(context.Background()) - // bufio is not goroutine safe, so add lock writer here ws = Lock(&bufferWriterSyncer{ bufferWriter: bufio.NewWriterSize(ws, bufferSize), - cancel: cancel, }) // flush buffer every interval @@ -138,7 +136,7 @@ func Buffer(ws WriteSyncer, bufferSize int, flushInterval time.Duration) WriteSy } }() - return ws + return ws, cancelfunc } func (s *bufferWriterSyncer) Write(bs []byte) (int, error) { @@ -161,11 +159,6 @@ func (s *bufferWriterSyncer) Sync() error { return s.bufferWriter.Flush() } -func (s *bufferWriterSyncer) Close() error { - s.cancel() - return s.Sync() -} - type writerWrapper struct { io.Writer } diff --git a/zapcore/write_syncer_bench_test.go b/zapcore/write_syncer_bench_test.go index 65626802e..dc5d40ea1 100644 --- a/zapcore/write_syncer_bench_test.go +++ b/zapcore/write_syncer_bench_test.go @@ -57,12 +57,13 @@ func BenchmarkMultiWriteSyncer(b *testing.B) { }) }) b.Run("4 discarder with buffer", func(b *testing.B) { - w := Buffer(NewMultiWriteSyncer( + w, cancel := Buffer(NewMultiWriteSyncer( &ztest.Discarder{}, &ztest.Discarder{}, &ztest.Discarder{}, &ztest.Discarder{}, ), 0, 0) + defer cancel() b.ResetTimer() b.RunParallel(func(pb *testing.PB) { for pb.Next() { @@ -93,7 +94,8 @@ func BenchmarkWriteSyncer(b *testing.B) { defer file.Close() defer os.Remove(file.Name()) - w := Buffer(AddSync(file), 0, 0) + w, cancel := Buffer(AddSync(file), 0, 0) + defer cancel() b.ResetTimer() b.RunParallel(func(pb *testing.PB) { for pb.Next() { diff --git a/zapcore/write_syncer_test.go b/zapcore/write_syncer_test.go index 3f068b0c0..0fdf85e8a 100644 --- a/zapcore/write_syncer_test.go +++ b/zapcore/write_syncer_test.go @@ -70,25 +70,40 @@ func TestBufferWriter(t *testing.T) { // with a no-op Sync. t.Run("sync", func(t *testing.T) { buf := &bytes.Buffer{} - ws := Buffer(Buffer(AddSync(buf), 0, 0), 0, 0) + ws, cancel := Buffer(AddSync(buf), 0, 0) + defer cancel() requireWriteWorks(t, ws) assert.Equal(t, "", buf.String(), "Unexpected log calling a no-op Write method.") assert.NoError(t, ws.Sync(), "Unexpected error calling a no-op Sync method.") assert.Equal(t, "foo", buf.String(), "Unexpected log string") }) - t.Run("close", func(t *testing.T) { + t.Run("1 cancel", func(t *testing.T) { buf := &bytes.Buffer{} - ws := Buffer(Buffer(AddSync(buf), 0, 0), 0, 0) + ws, cancel := Buffer(AddSync(buf), 0, 0) requireWriteWorks(t, ws) assert.Equal(t, "", buf.String(), "Unexpected log calling a no-op Write method.") - assert.NoError(t, ws.Close(), "Unexpected error calling a no-op Close method.") + cancel() + assert.Equal(t, "foo", buf.String(), "Unexpected log string") + }) + + t.Run("2 cancel", func(t *testing.T) { + buf := &bytes.Buffer{} + bufsync, cancel1 := Buffer(AddSync(buf), 0, 0) + ws, cancel2 := Buffer(bufsync, 0, 0) + requireWriteWorks(t, ws) + assert.Equal(t, "", buf.String(), "Unexpected log calling a no-op Write method.") + cancel2() + cancel1() assert.Equal(t, "foo", buf.String(), "Unexpected log string") }) t.Run("small buffer", func(t *testing.T) { buf := &bytes.Buffer{} - ws := Buffer(Buffer(AddSync(buf), 5, 0), 5, 0) + bufsync, cancel1 := Buffer(AddSync(buf), 5, 0) + ws, cancel2 := Buffer(bufsync, 5, 0) + defer cancel1() + defer cancel2() requireWriteWorks(t, ws) assert.Equal(t, "", buf.String(), "Unexpected log calling a no-op Write method.") requireWriteWorks(t, ws) From ef808a20f4d6ddfe59dc20b4fdbc1f57dc0b72ef Mon Sep 17 00:00:00 2001 From: hnlq715 Date: Tue, 3 Mar 2020 15:50:44 +0800 Subject: [PATCH 09/74] improve --- zapcore/write_syncer.go | 6 +----- 1 file changed, 1 insertion(+), 5 deletions(-) diff --git a/zapcore/write_syncer.go b/zapcore/write_syncer.go index be98da5fe..ff6d81c75 100644 --- a/zapcore/write_syncer.go +++ b/zapcore/write_syncer.go @@ -39,7 +39,7 @@ type WriteSyncer interface { // AddSync converts an io.Writer to a WriteSyncer. It attempts to be // intelligent: if the concrete type of the io.Writer implements WriteSyncer, -// we'll use the existing Sync and Close method. If it doesn't, we'll add a no-op Sync and Close. +// we'll use the existing Sync method. If it doesn't, we'll add a no-op Sync. func AddSync(w io.Writer) WriteSyncer { switch w := w.(type) { case WriteSyncer: @@ -208,7 +208,3 @@ func (ws multiWriteSyncer) Sync() error { } return err } - -func (ws multiWriteSyncer) Close() error { - return ws.Sync() -} From 3af046ab38447e4b64ad20fc88ba38524ad360d1 Mon Sep 17 00:00:00 2001 From: hnlq715 Date: Tue, 3 Mar 2020 15:51:44 +0800 Subject: [PATCH 10/74] remove close --- zapcore/write_syncer.go | 4 ---- zaptest/logger.go | 4 ---- zaptest/observer/observer.go | 4 ---- 3 files changed, 12 deletions(-) diff --git a/zapcore/write_syncer.go b/zapcore/write_syncer.go index ff6d81c75..86c30f7b4 100644 --- a/zapcore/write_syncer.go +++ b/zapcore/write_syncer.go @@ -167,10 +167,6 @@ func (w writerWrapper) Sync() error { return nil } -func (w writerWrapper) Close() error { - return nil -} - type multiWriteSyncer []WriteSyncer // NewMultiWriteSyncer creates a WriteSyncer that duplicates its writes diff --git a/zaptest/logger.go b/zaptest/logger.go index f95304e4f..1e2451c26 100644 --- a/zaptest/logger.go +++ b/zaptest/logger.go @@ -138,7 +138,3 @@ func (w testingWriter) Write(p []byte) (n int, err error) { func (w testingWriter) Sync() error { return nil } - -func (w testingWriter) Close() error { - return nil -} diff --git a/zaptest/observer/observer.go b/zaptest/observer/observer.go index 06ec7ab73..6ae58f5d6 100644 --- a/zaptest/observer/observer.go +++ b/zaptest/observer/observer.go @@ -177,7 +177,3 @@ func (co *contextObserver) Write(ent zapcore.Entry, fields []zapcore.Field) erro func (co *contextObserver) Sync() error { return nil } - -func (co *contextObserver) Close() error { - return nil -} From e0a440db574601556d5466c682d1d6f63ef87f4b Mon Sep 17 00:00:00 2001 From: liqi Date: Fri, 29 May 2020 16:08:24 +0800 Subject: [PATCH 11/74] rename cancel to close and keep syncing --- zapcore/write_syncer.go | 18 +++++++++--------- 1 file changed, 9 insertions(+), 9 deletions(-) diff --git a/zapcore/write_syncer.go b/zapcore/write_syncer.go index 86c30f7b4..27b3a061e 100644 --- a/zapcore/write_syncer.go +++ b/zapcore/write_syncer.go @@ -89,16 +89,16 @@ const defaultBufferSize = 256 * 1024 // defaultFlushInterval means the default flush interval const defaultFlushInterval = 30 * time.Second -// CancelFunc should be called when the caller exits to clean up buffers. -type CancelFunc func() error +// CloseFunc should be called when the caller exits to clean up buffers. +type CloseFunc func() error // Buffer wraps a WriteSyncer in a buffer to improve performance, // if bufferSize = 0, we set it to defaultBufferSize // if flushInterval = 0, we set it to defaultFlushInterval -func Buffer(ws WriteSyncer, bufferSize int, flushInterval time.Duration) (WriteSyncer, CancelFunc) { +func Buffer(ws WriteSyncer, bufferSize int, flushInterval time.Duration) (WriteSyncer, CloseFunc) { ctx, cancel := context.WithCancel(context.Background()) - cancelfunc := func() error { + closefunc := func() error { cancel() return ws.Sync() } @@ -106,7 +106,7 @@ func Buffer(ws WriteSyncer, bufferSize int, flushInterval time.Duration) (WriteS if lws, ok := ws.(*lockedWriteSyncer); ok { if _, ok := lws.ws.(*bufferWriterSyncer); ok { // no need to layer on another buffer - return ws, cancelfunc + return ws, closefunc } } @@ -128,15 +128,15 @@ func Buffer(ws WriteSyncer, bufferSize int, flushInterval time.Duration) (WriteS go func() { select { case <-time.NewTicker(flushInterval).C: - if err := ws.Sync(); err != nil { - return - } + // the background goroutine just keep syncing + // until the close func is called. + _ = ws.Sync() case <-ctx.Done(): return } }() - return ws, cancelfunc + return ws, closefunc } func (s *bufferWriterSyncer) Write(bs []byte) (int, error) { From e571e25ad257944e3c3e42ca5d683ee14372e53e Mon Sep 17 00:00:00 2001 From: liqi Date: Mon, 1 Jun 2020 09:30:48 +0800 Subject: [PATCH 12/74] fix lint --- zapcore/write_syncer.go | 1 - 1 file changed, 1 deletion(-) diff --git a/zapcore/write_syncer.go b/zapcore/write_syncer.go index 27b3a061e..84f513013 100644 --- a/zapcore/write_syncer.go +++ b/zapcore/write_syncer.go @@ -79,7 +79,6 @@ func (s *lockedWriteSyncer) Sync() error { } type bufferWriterSyncer struct { - ws WriteSyncer bufferWriter *bufio.Writer } From 4a25c9f9007056f84bddc46114801f4b6a779929 Mon Sep 17 00:00:00 2001 From: liqi Date: Mon, 1 Jun 2020 10:44:30 +0800 Subject: [PATCH 13/74] 100% test coverage --- zapcore/write_syncer.go | 6 +++++- zapcore/write_syncer_test.go | 24 ++++++++++++++++++++++++ 2 files changed, 29 insertions(+), 1 deletion(-) diff --git a/zapcore/write_syncer.go b/zapcore/write_syncer.go index 84f513013..a9a4bac27 100644 --- a/zapcore/write_syncer.go +++ b/zapcore/write_syncer.go @@ -80,6 +80,7 @@ func (s *lockedWriteSyncer) Sync() error { type bufferWriterSyncer struct { bufferWriter *bufio.Writer + ticker *time.Ticker } // defaultBufferSize sizes the buffer associated with each WriterSync. @@ -117,16 +118,19 @@ func Buffer(ws WriteSyncer, bufferSize int, flushInterval time.Duration) (WriteS flushInterval = defaultFlushInterval } + ticker := time.NewTicker(flushInterval) + // bufio is not goroutine safe, so add lock writer here ws = Lock(&bufferWriterSyncer{ bufferWriter: bufio.NewWriterSize(ws, bufferSize), + ticker: ticker, }) // flush buffer every interval // we do not need exit this goroutine explicitly go func() { select { - case <-time.NewTicker(flushInterval).C: + case <-ticker.C: // the background goroutine just keep syncing // until the close func is called. _ = ws.Sync() diff --git a/zapcore/write_syncer_test.go b/zapcore/write_syncer_test.go index 0fdf85e8a..832acee63 100644 --- a/zapcore/write_syncer_test.go +++ b/zapcore/write_syncer_test.go @@ -24,6 +24,7 @@ import ( "bytes" "errors" "testing" + "time" "io" @@ -37,6 +38,10 @@ type writeSyncSpy struct { ztest.Syncer } +type errorWriter struct{} + +func (*errorWriter) Write([]byte) (int, error) { return 0, errors.New("unimplemented") } + func requireWriteWorks(t testing.TB, ws WriteSyncer) { n, err := ws.Write([]byte("foo")) require.NoError(t, err, "Unexpected error writing to WriteSyncer.") @@ -110,6 +115,25 @@ func TestBufferWriter(t *testing.T) { assert.Equal(t, "foo", buf.String(), "Unexpected log string") }) + t.Run("flush error", func(t *testing.T) { + ws, cancel := Buffer(AddSync(&errorWriter{}), 4, time.Nanosecond) + n, err := ws.Write([]byte("foo")) + require.NoError(t, err, "Unexpected error writing to WriteSyncer.") + require.Equal(t, 3, n, "Wrote an unexpected number of bytes.") + ws.Write([]byte("foo")) + assert.NotNil(t, cancel()) + }) + + t.Run("flush timer", func(t *testing.T) { + buf := &bytes.Buffer{} + ws, _ := Buffer(AddSync(buf), 6, time.Microsecond) + requireWriteWorks(t, ws) + assert.Equal(t, "", buf.String(), "Unexpected log calling a no-op Write method.") + ticker := ws.(*lockedWriteSyncer).ws.(*bufferWriterSyncer).ticker + <-ticker.C + <-ticker.C + assert.Equal(t, "foo", buf.String(), "Unexpected log string") + }) } func TestNewMultiWriteSyncerWorksForSingleWriter(t *testing.T) { From 99f4ea8fea635b6661cd6a547e67f4bec01d0722 Mon Sep 17 00:00:00 2001 From: liqi Date: Mon, 1 Jun 2020 10:46:28 +0800 Subject: [PATCH 14/74] improve comment --- zapcore/write_syncer.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/zapcore/write_syncer.go b/zapcore/write_syncer.go index a9a4bac27..18323396a 100644 --- a/zapcore/write_syncer.go +++ b/zapcore/write_syncer.go @@ -127,7 +127,7 @@ func Buffer(ws WriteSyncer, bufferSize int, flushInterval time.Duration) (WriteS }) // flush buffer every interval - // we do not need exit this goroutine explicitly + // we only exit this goroutine after closefunc called explicitly go func() { select { case <-ticker.C: From 223dd97899a37b2201711209c4e7f3458b3e3539 Mon Sep 17 00:00:00 2001 From: liqi Date: Mon, 1 Jun 2020 10:47:10 +0800 Subject: [PATCH 15/74] improve comment --- zapcore/write_syncer.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/zapcore/write_syncer.go b/zapcore/write_syncer.go index 18323396a..0e29d774d 100644 --- a/zapcore/write_syncer.go +++ b/zapcore/write_syncer.go @@ -127,7 +127,7 @@ func Buffer(ws WriteSyncer, bufferSize int, flushInterval time.Duration) (WriteS }) // flush buffer every interval - // we only exit this goroutine after closefunc called explicitly + // we do not need to exit this goroutine until closefunc called explicitly go func() { select { case <-ticker.C: From dd3698ed65c023e885ae5c238d1047dd59941fe1 Mon Sep 17 00:00:00 2001 From: liqi Date: Mon, 1 Jun 2020 11:09:39 +0800 Subject: [PATCH 16/74] fix test error --- zapcore/write_syncer_test.go | 4 +--- 1 file changed, 1 insertion(+), 3 deletions(-) diff --git a/zapcore/write_syncer_test.go b/zapcore/write_syncer_test.go index 832acee63..050c5715a 100644 --- a/zapcore/write_syncer_test.go +++ b/zapcore/write_syncer_test.go @@ -129,9 +129,7 @@ func TestBufferWriter(t *testing.T) { ws, _ := Buffer(AddSync(buf), 6, time.Microsecond) requireWriteWorks(t, ws) assert.Equal(t, "", buf.String(), "Unexpected log calling a no-op Write method.") - ticker := ws.(*lockedWriteSyncer).ws.(*bufferWriterSyncer).ticker - <-ticker.C - <-ticker.C + ztest.Sleep(10 * time.Millisecond) assert.Equal(t, "foo", buf.String(), "Unexpected log string") }) } From f3079deeafa66c5d711eb9644d1a341b83ff51d8 Mon Sep 17 00:00:00 2001 From: liqi Date: Mon, 1 Jun 2020 11:42:45 +0800 Subject: [PATCH 17/74] fix race condition in test case --- zapcore/write_syncer.go | 14 +++++++++++--- zapcore/write_syncer_test.go | 6 +++++- 2 files changed, 16 insertions(+), 4 deletions(-) diff --git a/zapcore/write_syncer.go b/zapcore/write_syncer.go index 0e29d774d..47cefe8cb 100644 --- a/zapcore/write_syncer.go +++ b/zapcore/write_syncer.go @@ -79,6 +79,7 @@ func (s *lockedWriteSyncer) Sync() error { } type bufferWriterSyncer struct { + sync.Mutex bufferWriter *bufio.Writer ticker *time.Ticker } @@ -120,11 +121,10 @@ func Buffer(ws WriteSyncer, bufferSize int, flushInterval time.Duration) (WriteS ticker := time.NewTicker(flushInterval) - // bufio is not goroutine safe, so add lock writer here - ws = Lock(&bufferWriterSyncer{ + ws = &bufferWriterSyncer{ bufferWriter: bufio.NewWriterSize(ws, bufferSize), ticker: ticker, - }) + } // flush buffer every interval // we do not need to exit this goroutine until closefunc called explicitly @@ -143,6 +143,10 @@ func Buffer(ws WriteSyncer, bufferSize int, flushInterval time.Duration) (WriteS } func (s *bufferWriterSyncer) Write(bs []byte) (int, error) { + // bufio is not goroutine safe, so add lock writer here + s.Lock() + defer s.Unlock() + // there are some logic internal for bufio.Writer here: // 1. when the buffer is enough, data would not be flushed. // 2. when the buffer is not enough, data would be flushed as soon as the buffer fills up. @@ -159,6 +163,10 @@ func (s *bufferWriterSyncer) Write(bs []byte) (int, error) { } func (s *bufferWriterSyncer) Sync() error { + // bufio is not goroutine safe, so add lock writer here + s.Lock() + defer s.Unlock() + return s.bufferWriter.Flush() } diff --git a/zapcore/write_syncer_test.go b/zapcore/write_syncer_test.go index 050c5715a..7c0ef41dc 100644 --- a/zapcore/write_syncer_test.go +++ b/zapcore/write_syncer_test.go @@ -112,6 +112,8 @@ func TestBufferWriter(t *testing.T) { requireWriteWorks(t, ws) assert.Equal(t, "", buf.String(), "Unexpected log calling a no-op Write method.") requireWriteWorks(t, ws) + assert.Equal(t, "", buf.String(), "Unexpected log calling a no-op Write method.") + requireWriteWorks(t, ws) assert.Equal(t, "foo", buf.String(), "Unexpected log string") }) @@ -128,8 +130,10 @@ func TestBufferWriter(t *testing.T) { buf := &bytes.Buffer{} ws, _ := Buffer(AddSync(buf), 6, time.Microsecond) requireWriteWorks(t, ws) - assert.Equal(t, "", buf.String(), "Unexpected log calling a no-op Write method.") ztest.Sleep(10 * time.Millisecond) + bws := ws.(*bufferWriterSyncer) + bws.Lock() + defer bws.Unlock() assert.Equal(t, "foo", buf.String(), "Unexpected log string") }) } From 2c09dc4249199534c3472c15902f512554f60348 Mon Sep 17 00:00:00 2001 From: liqi Date: Mon, 1 Jun 2020 11:56:01 +0800 Subject: [PATCH 18/74] 100% test coverage --- zapcore/write_syncer.go | 8 +++----- zapcore/write_syncer_test.go | 2 -- 2 files changed, 3 insertions(+), 7 deletions(-) diff --git a/zapcore/write_syncer.go b/zapcore/write_syncer.go index 47cefe8cb..991c2aac6 100644 --- a/zapcore/write_syncer.go +++ b/zapcore/write_syncer.go @@ -104,11 +104,9 @@ func Buffer(ws WriteSyncer, bufferSize int, flushInterval time.Duration) (WriteS return ws.Sync() } - if lws, ok := ws.(*lockedWriteSyncer); ok { - if _, ok := lws.ws.(*bufferWriterSyncer); ok { - // no need to layer on another buffer - return ws, closefunc - } + if _, ok := ws.(*bufferWriterSyncer); ok { + // no need to layer on another buffer + return ws, closefunc } if bufferSize == 0 { diff --git a/zapcore/write_syncer_test.go b/zapcore/write_syncer_test.go index 7c0ef41dc..1bdbc1283 100644 --- a/zapcore/write_syncer_test.go +++ b/zapcore/write_syncer_test.go @@ -112,8 +112,6 @@ func TestBufferWriter(t *testing.T) { requireWriteWorks(t, ws) assert.Equal(t, "", buf.String(), "Unexpected log calling a no-op Write method.") requireWriteWorks(t, ws) - assert.Equal(t, "", buf.String(), "Unexpected log calling a no-op Write method.") - requireWriteWorks(t, ws) assert.Equal(t, "foo", buf.String(), "Unexpected log string") }) From f0f2a288382f50944708f821e186e06d021008fc Mon Sep 17 00:00:00 2001 From: liqi Date: Fri, 5 Jun 2020 08:47:02 +0800 Subject: [PATCH 19/74] add loop and fix typo --- zapcore/write_syncer.go | 16 ++++++++------ zapcore/write_syncer_bench_test.go | 8 +++---- zapcore/write_syncer_test.go | 35 +++++++++++++++--------------- 3 files changed, 31 insertions(+), 28 deletions(-) diff --git a/zapcore/write_syncer.go b/zapcore/write_syncer.go index 991c2aac6..7890356a7 100644 --- a/zapcore/write_syncer.go +++ b/zapcore/write_syncer.go @@ -127,13 +127,15 @@ func Buffer(ws WriteSyncer, bufferSize int, flushInterval time.Duration) (WriteS // flush buffer every interval // we do not need to exit this goroutine until closefunc called explicitly go func() { - select { - case <-ticker.C: - // the background goroutine just keep syncing - // until the close func is called. - _ = ws.Sync() - case <-ctx.Done(): - return + for { + select { + case <-ticker.C: + // the background goroutine just keep syncing + // until the close func is called. + _ = ws.Sync() + case <-ctx.Done(): + return + } } }() diff --git a/zapcore/write_syncer_bench_test.go b/zapcore/write_syncer_bench_test.go index dc5d40ea1..2f25a0844 100644 --- a/zapcore/write_syncer_bench_test.go +++ b/zapcore/write_syncer_bench_test.go @@ -57,13 +57,13 @@ func BenchmarkMultiWriteSyncer(b *testing.B) { }) }) b.Run("4 discarder with buffer", func(b *testing.B) { - w, cancel := Buffer(NewMultiWriteSyncer( + w, close := Buffer(NewMultiWriteSyncer( &ztest.Discarder{}, &ztest.Discarder{}, &ztest.Discarder{}, &ztest.Discarder{}, ), 0, 0) - defer cancel() + defer close() b.ResetTimer() b.RunParallel(func(pb *testing.PB) { for pb.Next() { @@ -94,8 +94,8 @@ func BenchmarkWriteSyncer(b *testing.B) { defer file.Close() defer os.Remove(file.Name()) - w, cancel := Buffer(AddSync(file), 0, 0) - defer cancel() + w, close := Buffer(AddSync(file), 0, 0) + defer close() b.ResetTimer() b.RunParallel(func(pb *testing.PB) { for pb.Next() { diff --git a/zapcore/write_syncer_test.go b/zapcore/write_syncer_test.go index 1bdbc1283..68266765c 100644 --- a/zapcore/write_syncer_test.go +++ b/zapcore/write_syncer_test.go @@ -75,40 +75,40 @@ func TestBufferWriter(t *testing.T) { // with a no-op Sync. t.Run("sync", func(t *testing.T) { buf := &bytes.Buffer{} - ws, cancel := Buffer(AddSync(buf), 0, 0) - defer cancel() + ws, close := Buffer(AddSync(buf), 0, 0) + defer close() requireWriteWorks(t, ws) assert.Equal(t, "", buf.String(), "Unexpected log calling a no-op Write method.") assert.NoError(t, ws.Sync(), "Unexpected error calling a no-op Sync method.") assert.Equal(t, "foo", buf.String(), "Unexpected log string") }) - t.Run("1 cancel", func(t *testing.T) { + t.Run("1 close", func(t *testing.T) { buf := &bytes.Buffer{} - ws, cancel := Buffer(AddSync(buf), 0, 0) + ws, close := Buffer(AddSync(buf), 0, 0) requireWriteWorks(t, ws) assert.Equal(t, "", buf.String(), "Unexpected log calling a no-op Write method.") - cancel() + close() assert.Equal(t, "foo", buf.String(), "Unexpected log string") }) - t.Run("2 cancel", func(t *testing.T) { + t.Run("2 close", func(t *testing.T) { buf := &bytes.Buffer{} - bufsync, cancel1 := Buffer(AddSync(buf), 0, 0) - ws, cancel2 := Buffer(bufsync, 0, 0) + bufsync, close1 := Buffer(AddSync(buf), 0, 0) + ws, close2 := Buffer(bufsync, 0, 0) requireWriteWorks(t, ws) assert.Equal(t, "", buf.String(), "Unexpected log calling a no-op Write method.") - cancel2() - cancel1() + close2() + close1() assert.Equal(t, "foo", buf.String(), "Unexpected log string") }) t.Run("small buffer", func(t *testing.T) { buf := &bytes.Buffer{} - bufsync, cancel1 := Buffer(AddSync(buf), 5, 0) - ws, cancel2 := Buffer(bufsync, 5, 0) - defer cancel1() - defer cancel2() + bufsync, close1 := Buffer(AddSync(buf), 5, 0) + ws, close2 := Buffer(bufsync, 5, 0) + defer close1() + defer close2() requireWriteWorks(t, ws) assert.Equal(t, "", buf.String(), "Unexpected log calling a no-op Write method.") requireWriteWorks(t, ws) @@ -116,17 +116,18 @@ func TestBufferWriter(t *testing.T) { }) t.Run("flush error", func(t *testing.T) { - ws, cancel := Buffer(AddSync(&errorWriter{}), 4, time.Nanosecond) + ws, close := Buffer(AddSync(&errorWriter{}), 4, time.Nanosecond) n, err := ws.Write([]byte("foo")) require.NoError(t, err, "Unexpected error writing to WriteSyncer.") require.Equal(t, 3, n, "Wrote an unexpected number of bytes.") ws.Write([]byte("foo")) - assert.NotNil(t, cancel()) + assert.NotNil(t, close()) }) t.Run("flush timer", func(t *testing.T) { buf := &bytes.Buffer{} - ws, _ := Buffer(AddSync(buf), 6, time.Microsecond) + ws, close := Buffer(AddSync(buf), 6, time.Microsecond) + defer close() requireWriteWorks(t, ws) ztest.Sleep(10 * time.Millisecond) bws := ws.(*bufferWriterSyncer) From fb6efc32b71294dd97f731710eee102c3a90dc69 Mon Sep 17 00:00:00 2001 From: Sophos Date: Tue, 9 Jun 2020 09:45:37 +0800 Subject: [PATCH 20/74] Update zapcore/write_syncer.go Co-authored-by: Prashant Varanasi --- zapcore/write_syncer.go | 3 +-- 1 file changed, 1 insertion(+), 2 deletions(-) diff --git a/zapcore/write_syncer.go b/zapcore/write_syncer.go index 7890356a7..6334f4b35 100644 --- a/zapcore/write_syncer.go +++ b/zapcore/write_syncer.go @@ -153,8 +153,7 @@ func (s *bufferWriterSyncer) Write(bs []byte) (int, error) { // this would lead to log spliting, which is not acceptable for log collector // so we need to flush bufferWriter before writing the data into bufferWriter if len(bs) > s.bufferWriter.Available() && s.bufferWriter.Buffered() > 0 { - err := s.bufferWriter.Flush() - if err != nil { + if err := s.bufferWriter.Flush(); err != nil { return 0, err } } From 0977e02cfa3fa584ec9ffe3986f2656fe41b2d0f Mon Sep 17 00:00:00 2001 From: liqi Date: Tue, 9 Jun 2020 09:47:15 +0800 Subject: [PATCH 21/74] improve test --- zapcore/write_syncer_bench_test.go | 8 ++++---- 1 file changed, 4 insertions(+), 4 deletions(-) diff --git a/zapcore/write_syncer_bench_test.go b/zapcore/write_syncer_bench_test.go index 2f25a0844..f16fc3530 100644 --- a/zapcore/write_syncer_bench_test.go +++ b/zapcore/write_syncer_bench_test.go @@ -75,8 +75,8 @@ func BenchmarkMultiWriteSyncer(b *testing.B) { func BenchmarkWriteSyncer(b *testing.B) { b.Run("write file with no buffer", func(b *testing.B) { - file, err := ioutil.TempFile(".", "*") - assert.Nil(b, err) + file, err := ioutil.TempFile("", "log") + assert.NoError(b, err) defer file.Close() defer os.Remove(file.Name()) @@ -89,8 +89,8 @@ func BenchmarkWriteSyncer(b *testing.B) { }) }) b.Run("write file with buffer", func(b *testing.B) { - file, err := ioutil.TempFile(".", "*") - assert.Nil(b, err) + file, err := ioutil.TempFile("", "log") + assert.NoError(b, err) defer file.Close() defer os.Remove(file.Name()) From 65775e14432fd6ce979d20ac45776e783ca3ed8f Mon Sep 17 00:00:00 2001 From: liqi Date: Tue, 9 Jun 2020 09:54:56 +0800 Subject: [PATCH 22/74] validate loop logic in test case --- zapcore/write_syncer_test.go | 9 ++++++++- 1 file changed, 8 insertions(+), 1 deletion(-) diff --git a/zapcore/write_syncer_test.go b/zapcore/write_syncer_test.go index 68266765c..a6fe477d4 100644 --- a/zapcore/write_syncer_test.go +++ b/zapcore/write_syncer_test.go @@ -132,8 +132,15 @@ func TestBufferWriter(t *testing.T) { ztest.Sleep(10 * time.Millisecond) bws := ws.(*bufferWriterSyncer) bws.Lock() - defer bws.Unlock() assert.Equal(t, "foo", buf.String(), "Unexpected log string") + bws.Unlock() + + // flush twice to validate loop logic + requireWriteWorks(t, ws) + ztest.Sleep(10 * time.Millisecond) + bws.Lock() + assert.Equal(t, "foofoo", buf.String(), "Unexpected log string") + bws.Unlock() }) } From 470b7faa1ce990b7d7f7619f50e46da5390157ac Mon Sep 17 00:00:00 2001 From: liqi Date: Tue, 9 Jun 2020 10:00:15 +0800 Subject: [PATCH 23/74] group default config --- zapcore/write_syncer.go | 10 ++++++---- 1 file changed, 6 insertions(+), 4 deletions(-) diff --git a/zapcore/write_syncer.go b/zapcore/write_syncer.go index 6334f4b35..d5f22d039 100644 --- a/zapcore/write_syncer.go +++ b/zapcore/write_syncer.go @@ -84,11 +84,13 @@ type bufferWriterSyncer struct { ticker *time.Ticker } -// defaultBufferSize sizes the buffer associated with each WriterSync. -const defaultBufferSize = 256 * 1024 +const ( + // defaultBufferSize sizes the buffer associated with each WriterSync. + defaultBufferSize = 256 * 1024 -// defaultFlushInterval means the default flush interval -const defaultFlushInterval = 30 * time.Second + // defaultFlushInterval means the default flush interval + defaultFlushInterval = 30 * time.Second +) // CloseFunc should be called when the caller exits to clean up buffers. type CloseFunc func() error From 160e84d353b028ad645d86ae8e6d5075b943a90b Mon Sep 17 00:00:00 2001 From: liqi Date: Tue, 23 Jun 2020 10:25:36 +0800 Subject: [PATCH 24/74] improve close logic --- zapcore/write_syncer.go | 16 ++++++++-------- 1 file changed, 8 insertions(+), 8 deletions(-) diff --git a/zapcore/write_syncer.go b/zapcore/write_syncer.go index d5f22d039..465dbbdbc 100644 --- a/zapcore/write_syncer.go +++ b/zapcore/write_syncer.go @@ -99,18 +99,13 @@ type CloseFunc func() error // if bufferSize = 0, we set it to defaultBufferSize // if flushInterval = 0, we set it to defaultFlushInterval func Buffer(ws WriteSyncer, bufferSize int, flushInterval time.Duration) (WriteSyncer, CloseFunc) { - ctx, cancel := context.WithCancel(context.Background()) - - closefunc := func() error { - cancel() - return ws.Sync() - } - if _, ok := ws.(*bufferWriterSyncer); ok { // no need to layer on another buffer - return ws, closefunc + return ws, func() error { return nil } } + ctx, cancel := context.WithCancel(context.Background()) + if bufferSize == 0 { bufferSize = defaultBufferSize } @@ -141,6 +136,11 @@ func Buffer(ws WriteSyncer, bufferSize int, flushInterval time.Duration) (WriteS } }() + closefunc := func() error { + cancel() + return ws.Sync() + } + return ws, closefunc } From ee04403dad51f215cfda33c95e1ca2ca8468a5e6 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?=E5=A4=A7=E5=8F=AF?= Date: Fri, 9 Oct 2020 19:21:51 +0800 Subject: [PATCH 25/74] Update zapcore/write_syncer.go Co-authored-by: Abhinav Gupta --- zapcore/write_syncer.go | 1 + 1 file changed, 1 insertion(+) diff --git a/zapcore/write_syncer.go b/zapcore/write_syncer.go index 465dbbdbc..d39d32f0f 100644 --- a/zapcore/write_syncer.go +++ b/zapcore/write_syncer.go @@ -80,6 +80,7 @@ func (s *lockedWriteSyncer) Sync() error { type bufferWriterSyncer struct { sync.Mutex + bufferWriter *bufio.Writer ticker *time.Ticker } From 80433c220bfad0a7e7ef95c9a96612bd4bb62eb2 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?=E5=A4=A7=E5=8F=AF?= Date: Fri, 9 Oct 2020 19:23:00 +0800 Subject: [PATCH 26/74] Update zapcore/write_syncer_test.go Co-authored-by: Abhinav Gupta --- zapcore/write_syncer_test.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/zapcore/write_syncer_test.go b/zapcore/write_syncer_test.go index a6fe477d4..b6684c1cc 100644 --- a/zapcore/write_syncer_test.go +++ b/zapcore/write_syncer_test.go @@ -78,7 +78,7 @@ func TestBufferWriter(t *testing.T) { ws, close := Buffer(AddSync(buf), 0, 0) defer close() requireWriteWorks(t, ws) - assert.Equal(t, "", buf.String(), "Unexpected log calling a no-op Write method.") + assert.Empty(t, buf.String(), "Unexpected log calling a no-op Write method.") assert.NoError(t, ws.Sync(), "Unexpected error calling a no-op Sync method.") assert.Equal(t, "foo", buf.String(), "Unexpected log string") }) From 9bda819d29bf011c5193c5a53f04e2219e07419f Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?=E5=A4=A7=E5=8F=AF?= Date: Fri, 9 Oct 2020 19:23:22 +0800 Subject: [PATCH 27/74] Update zapcore/write_syncer_test.go Co-authored-by: Abhinav Gupta --- zapcore/write_syncer_test.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/zapcore/write_syncer_test.go b/zapcore/write_syncer_test.go index b6684c1cc..f0fb01720 100644 --- a/zapcore/write_syncer_test.go +++ b/zapcore/write_syncer_test.go @@ -87,7 +87,7 @@ func TestBufferWriter(t *testing.T) { buf := &bytes.Buffer{} ws, close := Buffer(AddSync(buf), 0, 0) requireWriteWorks(t, ws) - assert.Equal(t, "", buf.String(), "Unexpected log calling a no-op Write method.") + assert.Empty(t, buf.String(), "Unexpected log calling a no-op Write method.") close() assert.Equal(t, "foo", buf.String(), "Unexpected log string") }) From dc370dac3927f609cebac49f02a9d82ba0b942d7 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?=E5=A4=A7=E5=8F=AF?= Date: Fri, 9 Oct 2020 19:23:34 +0800 Subject: [PATCH 28/74] Update zapcore/write_syncer_test.go Co-authored-by: Abhinav Gupta --- zapcore/write_syncer_test.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/zapcore/write_syncer_test.go b/zapcore/write_syncer_test.go index f0fb01720..b741a32de 100644 --- a/zapcore/write_syncer_test.go +++ b/zapcore/write_syncer_test.go @@ -83,7 +83,7 @@ func TestBufferWriter(t *testing.T) { assert.Equal(t, "foo", buf.String(), "Unexpected log string") }) - t.Run("1 close", func(t *testing.T) { + t.Run("close", func(t *testing.T) { buf := &bytes.Buffer{} ws, close := Buffer(AddSync(buf), 0, 0) requireWriteWorks(t, ws) From 2ecf1f85937dda47e9baa6cc221a04fb1024352d Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?=E5=A4=A7=E5=8F=AF?= Date: Fri, 9 Oct 2020 19:23:47 +0800 Subject: [PATCH 29/74] Update zapcore/write_syncer_test.go Co-authored-by: Abhinav Gupta --- zapcore/write_syncer_test.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/zapcore/write_syncer_test.go b/zapcore/write_syncer_test.go index b741a32de..a1b3206bf 100644 --- a/zapcore/write_syncer_test.go +++ b/zapcore/write_syncer_test.go @@ -92,7 +92,7 @@ func TestBufferWriter(t *testing.T) { assert.Equal(t, "foo", buf.String(), "Unexpected log string") }) - t.Run("2 close", func(t *testing.T) { + t.Run("wrap twice", func(t *testing.T) { buf := &bytes.Buffer{} bufsync, close1 := Buffer(AddSync(buf), 0, 0) ws, close2 := Buffer(bufsync, 0, 0) From a522baf0af3426f2cd7eaf0ff3ffb9f2a20c1afa Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?=E5=A4=A7=E5=8F=AF?= Date: Fri, 9 Oct 2020 19:24:14 +0800 Subject: [PATCH 30/74] Update zapcore/write_syncer_test.go Co-authored-by: Abhinav Gupta --- zapcore/write_syncer_test.go | 6 ++---- 1 file changed, 2 insertions(+), 4 deletions(-) diff --git a/zapcore/write_syncer_test.go b/zapcore/write_syncer_test.go index a1b3206bf..6d79f6d7b 100644 --- a/zapcore/write_syncer_test.go +++ b/zapcore/write_syncer_test.go @@ -105,10 +105,8 @@ func TestBufferWriter(t *testing.T) { t.Run("small buffer", func(t *testing.T) { buf := &bytes.Buffer{} - bufsync, close1 := Buffer(AddSync(buf), 5, 0) - ws, close2 := Buffer(bufsync, 5, 0) - defer close1() - defer close2() + ws, close := Buffer(AddSync(buf), 5, 0) + defer close() requireWriteWorks(t, ws) assert.Equal(t, "", buf.String(), "Unexpected log calling a no-op Write method.") requireWriteWorks(t, ws) From 4273b8e82b5562955bcfcd71c29e8509dbf6240f Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?=E5=A4=A7=E5=8F=AF?= Date: Fri, 9 Oct 2020 19:24:24 +0800 Subject: [PATCH 31/74] Update zapcore/write_syncer_test.go Co-authored-by: Abhinav Gupta --- zapcore/write_syncer_test.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/zapcore/write_syncer_test.go b/zapcore/write_syncer_test.go index 6d79f6d7b..f09b23627 100644 --- a/zapcore/write_syncer_test.go +++ b/zapcore/write_syncer_test.go @@ -119,7 +119,7 @@ func TestBufferWriter(t *testing.T) { require.NoError(t, err, "Unexpected error writing to WriteSyncer.") require.Equal(t, 3, n, "Wrote an unexpected number of bytes.") ws.Write([]byte("foo")) - assert.NotNil(t, close()) + assert.Error(t, close(), "Expected close to fail.") }) t.Run("flush timer", func(t *testing.T) { From d88453457c2664387aefc5aec024397ae9d0928b Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?=E5=A4=A7=E5=8F=AF?= Date: Tue, 13 Oct 2020 09:43:34 +0800 Subject: [PATCH 32/74] improve close logic and use goleak --- go.mod | 10 ++++++++++ go.sum | 19 +++++++++++++++++++ zapcore/write_syncer.go | 23 +++++++++++++---------- zapcore/write_syncer_test.go | 3 +++ 4 files changed, 45 insertions(+), 10 deletions(-) diff --git a/go.mod b/go.mod index 9455c99cc..2d927129e 100644 --- a/go.mod +++ b/go.mod @@ -5,10 +5,20 @@ go 1.13 require ( github.com/benbjohnson/clock v1.1.0 github.com/pkg/errors v0.8.1 +<<<<<<< HEAD github.com/stretchr/testify v1.7.0 go.uber.org/atomic v1.7.0 go.uber.org/goleak v1.1.10 go.uber.org/multierr v1.6.0 gopkg.in/yaml.v2 v2.2.8 gopkg.in/yaml.v3 v3.0.0-20210107192922-496545a6307b // indirect +======= + github.com/stretchr/testify v1.4.0 + go.uber.org/atomic v1.6.0 + go.uber.org/goleak v1.1.10 + go.uber.org/multierr v1.5.0 + golang.org/x/lint v0.0.0-20190930215403-16217165b5de + gopkg.in/yaml.v2 v2.2.2 + honnef.co/go/tools v0.0.1-2019.2.3 +>>>>>>> 761c8e8 (improve close logic and use goleak) ) diff --git a/go.sum b/go.sum index 9031a6131..f95667197 100644 --- a/go.sum +++ b/go.sum @@ -15,6 +15,7 @@ github.com/pmezard/go-difflib v1.0.0/go.mod h1:iKH77koFhYxTK1pcRnkKkqfTogsbg7gZN github.com/stretchr/objx v0.1.0/go.mod h1:HFkY916IF+rwdDfMAkV7OtwuqBVzrE8GR6GFx+wExME= github.com/stretchr/testify v1.3.0/go.mod h1:M5WIy9Dh21IEIfnGCwXGc5bZfKNJtfHm1UVUgZn+9EI= github.com/stretchr/testify v1.4.0/go.mod h1:j7eGeouHqKxXV5pUuKE4zz7dFj8WfuZ+81PSLYec5m4= +<<<<<<< HEAD github.com/stretchr/testify v1.7.0 h1:nwc3DEeHmmLAfoZucVR881uASk0Mfjw8xYJ99tb5CcY= github.com/stretchr/testify v1.7.0/go.mod h1:6Fq8oRcR53rry900zMqJjRRixrwX3KX962/h/Wwjteg= go.uber.org/atomic v1.7.0 h1:ADUqmZGgLDDfbSL9ZmPxKTybcoEYHgpYfELNoN+7hsw= @@ -23,6 +24,16 @@ go.uber.org/goleak v1.1.10 h1:z+mqJhf6ss6BSfSM671tgKyZBFPTTJM+HLxnhPC3wu0= go.uber.org/goleak v1.1.10/go.mod h1:8a7PlsEVH3e/a/GLqe5IIrQx6GzcnRmZEufDUTk4A7A= go.uber.org/multierr v1.6.0 h1:y6IPFStTAIT5Ytl7/XYmHvzXQ7S3g/IeZW9hyZ5thw4= go.uber.org/multierr v1.6.0/go.mod h1:cdWPpRnG4AhwMwsgIHip0KRBQjJy5kYEpYjJxpXp9iU= +======= +go.uber.org/atomic v1.6.0 h1:Ezj3JGmsOnG1MoRWQkPBsKLe9DwWD9QeXzTRzzldNVk= +go.uber.org/atomic v1.6.0/go.mod h1:sABNBOSYdrvTF6hTgEIbc7YasKWGhgEQZyfxyTvoXHQ= +go.uber.org/goleak v1.1.10 h1:z+mqJhf6ss6BSfSM671tgKyZBFPTTJM+HLxnhPC3wu0= +go.uber.org/goleak v1.1.10/go.mod h1:8a7PlsEVH3e/a/GLqe5IIrQx6GzcnRmZEufDUTk4A7A= +go.uber.org/multierr v1.5.0 h1:KCa4XfM8CWFCpxXRGok+Q0SS/0XBhMDbHHGABQLvD2A= +go.uber.org/multierr v1.5.0/go.mod h1:FeouvMocqHpRaaGuG9EjoKcStLC43Zu/fmqdUMPcKYU= +go.uber.org/tools v0.0.0-20190618225709-2cfd321de3ee h1:0mgffUl7nfd+FpvXMVz4IDEaUSmT1ysygQC7qYo7sG4= +go.uber.org/tools v0.0.0-20190618225709-2cfd321de3ee/go.mod h1:vJERXedbb3MVM5f9Ejo0C68/HhF8uaILCdgjnY+goOA= +>>>>>>> 761c8e8 (improve close logic and use goleak) golang.org/x/crypto v0.0.0-20190308221718-c2843e01d9a2/go.mod h1:djNgcEr1/C05ACkg1iLfiJU5Ep61QUkGW8qpdssI0+w= golang.org/x/lint v0.0.0-20190930215403-16217165b5de h1:5hukYrvBGR8/eNkX5mdUezrA6JiaEZDtJb9Ei+1LlBs= golang.org/x/lint v0.0.0-20190930215403-16217165b5de/go.mod h1:6SW0HCj/g11FgYtHlgUYUwCkIfeOF89ocIRzGO/8vkc= @@ -32,6 +43,14 @@ golang.org/x/sync v0.0.0-20190423024810-112230192c58/go.mod h1:RxMgew5VJxzue5/jJ golang.org/x/sys v0.0.0-20190215142949-d0b11bdaac8a/go.mod h1:STP8DvDyc/dI5b8T5hshtkjS+E42TnysNCUPdjciGhY= golang.org/x/text v0.3.0/go.mod h1:NqM8EUOU14njkJ3fqMW+pc6Ldnwhi/IjpwHt7yyuwOQ= golang.org/x/tools v0.0.0-20190311212946-11955173bddd/go.mod h1:LCzVGOaR6xXOjkQ3onu1FJEFr0SW1gC7cKk1uF8kGRs= +<<<<<<< HEAD +======= +golang.org/x/tools v0.0.0-20190621195816-6e04913cbbac/go.mod h1:/rFqwRUd4F7ZHNgwSSTFct+R/Kf4OFW1sUzUTQQTgfc= +golang.org/x/tools v0.0.0-20191029041327-9cc4af7d6b2c h1:IGkKhmfzcztjm6gYkykvu/NiS8kaqbCWAEWWAyf8J5U= +golang.org/x/tools v0.0.0-20191029041327-9cc4af7d6b2c/go.mod h1:b+2E5dAYhXwXZwtnZ6UAqBI28+e2cm9otk0dWdXHAEo= +golang.org/x/tools v0.0.0-20191029190741-b9c20aec41a5 h1:hKsoRgsbwY1NafxrwTs+k64bikrLBkAgPir1TNCj3Zs= +golang.org/x/tools v0.0.0-20191029190741-b9c20aec41a5/go.mod h1:b+2E5dAYhXwXZwtnZ6UAqBI28+e2cm9otk0dWdXHAEo= +>>>>>>> 761c8e8 (improve close logic and use goleak) golang.org/x/tools v0.0.0-20191108193012-7d206e10da11 h1:Yq9t9jnGoR+dBuitxdo9l6Q7xh/zOyNnYUtDKaQ3x0E= golang.org/x/tools v0.0.0-20191108193012-7d206e10da11/go.mod h1:b+2E5dAYhXwXZwtnZ6UAqBI28+e2cm9otk0dWdXHAEo= golang.org/x/xerrors v0.0.0-20190717185122-a985d3407aa7/go.mod h1:I/5z698sn9Ka8TeJc9MKroUUfqBBauWjQqLJ2OPfmY0= diff --git a/zapcore/write_syncer.go b/zapcore/write_syncer.go index d39d32f0f..b309e04aa 100644 --- a/zapcore/write_syncer.go +++ b/zapcore/write_syncer.go @@ -22,7 +22,6 @@ package zapcore import ( "bufio" - "context" "io" "sync" "time" @@ -80,6 +79,7 @@ func (s *lockedWriteSyncer) Sync() error { type bufferWriterSyncer struct { sync.Mutex + stop chan struct{} bufferWriter *bufio.Writer ticker *time.Ticker @@ -96,7 +96,7 @@ const ( // CloseFunc should be called when the caller exits to clean up buffers. type CloseFunc func() error -// Buffer wraps a WriteSyncer in a buffer to improve performance, +// Buffer wraps a WriteSyncer in a buffer to improve performance // if bufferSize = 0, we set it to defaultBufferSize // if flushInterval = 0, we set it to defaultFlushInterval func Buffer(ws WriteSyncer, bufferSize int, flushInterval time.Duration) (WriteSyncer, CloseFunc) { @@ -105,8 +105,6 @@ func Buffer(ws WriteSyncer, bufferSize int, flushInterval time.Duration) (WriteS return ws, func() error { return nil } } - ctx, cancel := context.WithCancel(context.Background()) - if bufferSize == 0 { bufferSize = defaultBufferSize } @@ -117,7 +115,8 @@ func Buffer(ws WriteSyncer, bufferSize int, flushInterval time.Duration) (WriteS ticker := time.NewTicker(flushInterval) - ws = &bufferWriterSyncer{ + bws := &bufferWriterSyncer{ + stop: make(chan struct{}), bufferWriter: bufio.NewWriterSize(ws, bufferSize), ticker: ticker, } @@ -130,21 +129,24 @@ func Buffer(ws WriteSyncer, bufferSize int, flushInterval time.Duration) (WriteS case <-ticker.C: // the background goroutine just keep syncing // until the close func is called. - _ = ws.Sync() - case <-ctx.Done(): + _ = bws.Sync() + case <-bws.stop: return } } }() closefunc := func() error { - cancel() - return ws.Sync() + bws.stop <- struct{}{} + + return bws.Sync() } - return ws, closefunc + return bws, closefunc } +// Write writes log data into buffer syncer directly, multiple Write calls will be batched, +// and log data will be flushed to disk when the buffer is full or periodically. func (s *bufferWriterSyncer) Write(bs []byte) (int, error) { // bufio is not goroutine safe, so add lock writer here s.Lock() @@ -164,6 +166,7 @@ func (s *bufferWriterSyncer) Write(bs []byte) (int, error) { return s.bufferWriter.Write(bs) } +// Sync flushes buffered log data into disk directly. func (s *bufferWriterSyncer) Sync() error { // bufio is not goroutine safe, so add lock writer here s.Lock() diff --git a/zapcore/write_syncer_test.go b/zapcore/write_syncer_test.go index f09b23627..f41703943 100644 --- a/zapcore/write_syncer_test.go +++ b/zapcore/write_syncer_test.go @@ -30,6 +30,7 @@ import ( "github.com/stretchr/testify/assert" "github.com/stretchr/testify/require" + "go.uber.org/goleak" "go.uber.org/zap/internal/ztest" ) @@ -71,6 +72,8 @@ func TestAddSyncWriter(t *testing.T) { } func TestBufferWriter(t *testing.T) { + goleak.VerifyNone(t) + // If we pass a plain io.Writer, make sure that we still get a WriteSyncer // with a no-op Sync. t.Run("sync", func(t *testing.T) { From 0392f30d7d3ccad3f49e88d59aab806d7e944318 Mon Sep 17 00:00:00 2001 From: Abhinav Gupta Date: Mon, 2 Nov 2020 10:10:53 -0800 Subject: [PATCH 33/74] Drop `type CloseFunc` We'd like to avoid introducing a new top-level type if we can. Delete the CloseFunc type in favor of returning a naked `func() error`. --- zapcore/write_syncer.go | 9 ++------- 1 file changed, 2 insertions(+), 7 deletions(-) diff --git a/zapcore/write_syncer.go b/zapcore/write_syncer.go index b309e04aa..1a01f5aa5 100644 --- a/zapcore/write_syncer.go +++ b/zapcore/write_syncer.go @@ -93,13 +93,11 @@ const ( defaultFlushInterval = 30 * time.Second ) -// CloseFunc should be called when the caller exits to clean up buffers. -type CloseFunc func() error // Buffer wraps a WriteSyncer in a buffer to improve performance // if bufferSize = 0, we set it to defaultBufferSize // if flushInterval = 0, we set it to defaultFlushInterval -func Buffer(ws WriteSyncer, bufferSize int, flushInterval time.Duration) (WriteSyncer, CloseFunc) { +func Buffer(ws WriteSyncer, bufferSize int, flushInterval time.Duration) (_ WriteSyncer, close func() error) { if _, ok := ws.(*bufferWriterSyncer); ok { // no need to layer on another buffer return ws, func() error { return nil } @@ -136,13 +134,10 @@ func Buffer(ws WriteSyncer, bufferSize int, flushInterval time.Duration) (WriteS } }() - closefunc := func() error { + return bws, func() error { bws.stop <- struct{}{} - return bws.Sync() } - - return bws, closefunc } // Write writes log data into buffer syncer directly, multiple Write calls will be batched, From ddace4de2f6c569757f978c69ee264beec61d325 Mon Sep 17 00:00:00 2001 From: Abhinav Gupta Date: Mon, 2 Nov 2020 10:11:39 -0800 Subject: [PATCH 34/74] doc: Rewrite Buffer documentation --- zapcore/write_syncer.go | 20 ++++++++++++++++---- 1 file changed, 16 insertions(+), 4 deletions(-) diff --git a/zapcore/write_syncer.go b/zapcore/write_syncer.go index 1a01f5aa5..692157526 100644 --- a/zapcore/write_syncer.go +++ b/zapcore/write_syncer.go @@ -93,10 +93,22 @@ const ( defaultFlushInterval = 30 * time.Second ) - -// Buffer wraps a WriteSyncer in a buffer to improve performance -// if bufferSize = 0, we set it to defaultBufferSize -// if flushInterval = 0, we set it to defaultFlushInterval +// Buffer wraps a WriteSyncer to buffer its output. The returned WriteSyncer +// flushes its output as the buffer fills up, or at the provided interval, +// whichever comes first. +// +// Call the returned function to finish using the WriteSyncer and flush +// remaining bytes. +// +// func main() { +// // ... +// ws, closeWS := zapcore.Buffer(ws, 0, 0) +// defer closeWS() +// // ... +// } +// +// The buffer size defaults to 256 kB if set to zero. +// The flush interval defaults to 30 seconds if set to zero. func Buffer(ws WriteSyncer, bufferSize int, flushInterval time.Duration) (_ WriteSyncer, close func() error) { if _, ok := ws.(*bufferWriterSyncer); ok { // no need to layer on another buffer From e96c0ee9076aed9b4fde47d41742f71487e6a739 Mon Sep 17 00:00:00 2001 From: Abhinav Gupta Date: Mon, 2 Nov 2020 10:11:51 -0800 Subject: [PATCH 35/74] Prefix default{BufferSize, FlushInterval} with _ Per https://github.com/uber-go/guide/blob/master/style.md#prefix-unexported-globals-with-_ --- zapcore/write_syncer.go | 12 ++++++------ 1 file changed, 6 insertions(+), 6 deletions(-) diff --git a/zapcore/write_syncer.go b/zapcore/write_syncer.go index 692157526..06b1ba76f 100644 --- a/zapcore/write_syncer.go +++ b/zapcore/write_syncer.go @@ -86,11 +86,11 @@ type bufferWriterSyncer struct { } const ( - // defaultBufferSize sizes the buffer associated with each WriterSync. - defaultBufferSize = 256 * 1024 + // _defaultBufferSize sizes the buffer associated with each WriterSync. + _defaultBufferSize = 256 * 1024 // 256 kB - // defaultFlushInterval means the default flush interval - defaultFlushInterval = 30 * time.Second + // _defaultFlushInterval means the default flush interval + _defaultFlushInterval = 30 * time.Second ) // Buffer wraps a WriteSyncer to buffer its output. The returned WriteSyncer @@ -116,11 +116,11 @@ func Buffer(ws WriteSyncer, bufferSize int, flushInterval time.Duration) (_ Writ } if bufferSize == 0 { - bufferSize = defaultBufferSize + bufferSize = _defaultBufferSize } if flushInterval == 0 { - flushInterval = defaultFlushInterval + flushInterval = _defaultFlushInterval } ticker := time.NewTicker(flushInterval) From 570d2ff73b4b9d5c9ad1e3da71c87a2d31918adb Mon Sep 17 00:00:00 2001 From: Abhinav Gupta Date: Mon, 2 Nov 2020 10:14:23 -0800 Subject: [PATCH 36/74] Buffer/close: return a bound method Instead of returning an anonmyous function, return a bound method. The bound method is named `close`, not `Close` to avoid accidentally exposing an `io.Closer` interface. --- zapcore/write_syncer.go | 12 ++++++++---- 1 file changed, 8 insertions(+), 4 deletions(-) diff --git a/zapcore/write_syncer.go b/zapcore/write_syncer.go index 06b1ba76f..9d5fb92ff 100644 --- a/zapcore/write_syncer.go +++ b/zapcore/write_syncer.go @@ -146,10 +146,7 @@ func Buffer(ws WriteSyncer, bufferSize int, flushInterval time.Duration) (_ Writ } }() - return bws, func() error { - bws.stop <- struct{}{} - return bws.Sync() - } + return bws, bws.close } // Write writes log data into buffer syncer directly, multiple Write calls will be batched, @@ -182,6 +179,13 @@ func (s *bufferWriterSyncer) Sync() error { return s.bufferWriter.Flush() } +// Close closes the buffer, cleans up background goroutines, and flushes +// remaining, unwritten data. +func (s *bufferWriterSyncer) close() error { + s.stop <- struct{}{} + return s.Sync() +} + type writerWrapper struct { io.Writer } From d1e244a8637e59084bf892d21c5913c08d3fabb1 Mon Sep 17 00:00:00 2001 From: Abhinav Gupta Date: Mon, 2 Nov 2020 10:15:36 -0800 Subject: [PATCH 37/74] Buffer/close: Close the channel instead of posting For the channel that signals end of the goroutine, we should close it instead of posting a single value to it. --- zapcore/write_syncer.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/zapcore/write_syncer.go b/zapcore/write_syncer.go index 9d5fb92ff..658f65237 100644 --- a/zapcore/write_syncer.go +++ b/zapcore/write_syncer.go @@ -182,7 +182,7 @@ func (s *bufferWriterSyncer) Sync() error { // Close closes the buffer, cleans up background goroutines, and flushes // remaining, unwritten data. func (s *bufferWriterSyncer) close() error { - s.stop <- struct{}{} + close(s.stop) return s.Sync() } From 83f6331a4bfd090bdc54e95b76b545de91b19cab Mon Sep 17 00:00:00 2001 From: Abhinav Gupta Date: Mon, 2 Nov 2020 10:19:17 -0800 Subject: [PATCH 38/74] _default{BufferSize, FlushInterval}: docs --- zapcore/write_syncer.go | 5 +++-- 1 file changed, 3 insertions(+), 2 deletions(-) diff --git a/zapcore/write_syncer.go b/zapcore/write_syncer.go index 658f65237..b7ef51de6 100644 --- a/zapcore/write_syncer.go +++ b/zapcore/write_syncer.go @@ -86,10 +86,11 @@ type bufferWriterSyncer struct { } const ( - // _defaultBufferSize sizes the buffer associated with each WriterSync. + // _defaultBufferSize specifies the default size used by Buffer. _defaultBufferSize = 256 * 1024 // 256 kB - // _defaultFlushInterval means the default flush interval + // _defaultFlushInterval specifies the default flush interval for + // Buffer. _defaultFlushInterval = 30 * time.Second ) From ba0b65ea74fe6842c5519a0abbce75f88f654abc Mon Sep 17 00:00:00 2001 From: Abhinav Gupta Date: Mon, 2 Nov 2020 10:22:25 -0800 Subject: [PATCH 39/74] buffer: Move loop into a method Move the flush loop into its own method instead of spawning it in a closure. --- zapcore/write_syncer.go | 30 +++++++++++++++--------------- 1 file changed, 15 insertions(+), 15 deletions(-) diff --git a/zapcore/write_syncer.go b/zapcore/write_syncer.go index b7ef51de6..a752388ee 100644 --- a/zapcore/write_syncer.go +++ b/zapcore/write_syncer.go @@ -132,20 +132,7 @@ func Buffer(ws WriteSyncer, bufferSize int, flushInterval time.Duration) (_ Writ ticker: ticker, } - // flush buffer every interval - // we do not need to exit this goroutine until closefunc called explicitly - go func() { - for { - select { - case <-ticker.C: - // the background goroutine just keep syncing - // until the close func is called. - _ = bws.Sync() - case <-bws.stop: - return - } - } - }() + go bws.flushLoop() return bws, bws.close } @@ -180,7 +167,20 @@ func (s *bufferWriterSyncer) Sync() error { return s.bufferWriter.Flush() } -// Close closes the buffer, cleans up background goroutines, and flushes +// flushLoop flushes the buffer at the configured interval until Close is +// called. +func (s *bufferWriterSyncer) flushLoop() { + for { + select { + case <-s.ticker.C: + _ = s.Sync() + case <-s.stop: + return + } + } +} + +// close closes the buffer, cleans up background goroutines, and flushes // remaining, unwritten data. func (s *bufferWriterSyncer) close() error { close(s.stop) From b8a0b28f3d33b03958720fcba7e896cec65efade Mon Sep 17 00:00:00 2001 From: Abhinav Gupta Date: Mon, 2 Nov 2020 10:23:14 -0800 Subject: [PATCH 40/74] buffer/close: stop the ticker On close, stop the ticker from posting ticks to the channel. --- zapcore/write_syncer.go | 1 + 1 file changed, 1 insertion(+) diff --git a/zapcore/write_syncer.go b/zapcore/write_syncer.go index a752388ee..7b94ea45b 100644 --- a/zapcore/write_syncer.go +++ b/zapcore/write_syncer.go @@ -183,6 +183,7 @@ func (s *bufferWriterSyncer) flushLoop() { // close closes the buffer, cleans up background goroutines, and flushes // remaining, unwritten data. func (s *bufferWriterSyncer) close() error { + s.ticker.Stop() close(s.stop) return s.Sync() } From 1c5daa9592a833cece6a31e052ee0500c61923e0 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?=E5=A4=A7=E5=8F=AF?= Date: Fri, 6 Nov 2020 15:03:48 +0800 Subject: [PATCH 41/74] Update zapcore/write_syncer_test.go Co-authored-by: Prashant Varanasi --- zapcore/write_syncer_test.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/zapcore/write_syncer_test.go b/zapcore/write_syncer_test.go index f41703943..0f8fd9129 100644 --- a/zapcore/write_syncer_test.go +++ b/zapcore/write_syncer_test.go @@ -72,7 +72,7 @@ func TestAddSyncWriter(t *testing.T) { } func TestBufferWriter(t *testing.T) { - goleak.VerifyNone(t) + defer goleak.VerifyNone(t) // If we pass a plain io.Writer, make sure that we still get a WriteSyncer // with a no-op Sync. From f74c5581c49f3bb87a57ce398f47543015ef0497 Mon Sep 17 00:00:00 2001 From: liqi Date: Fri, 6 Nov 2020 15:16:07 +0800 Subject: [PATCH 42/74] improve code style --- zapcore/write_syncer.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/zapcore/write_syncer.go b/zapcore/write_syncer.go index 7b94ea45b..710b76661 100644 --- a/zapcore/write_syncer.go +++ b/zapcore/write_syncer.go @@ -79,8 +79,8 @@ func (s *lockedWriteSyncer) Sync() error { type bufferWriterSyncer struct { sync.Mutex - stop chan struct{} + stop chan struct{} bufferWriter *bufio.Writer ticker *time.Ticker } From 6f88240ed84bf9318ac3779656b12224250b2bf3 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?=E5=A4=A7=E5=8F=AF?= Date: Fri, 6 Nov 2020 15:15:36 +0800 Subject: [PATCH 43/74] Update zapcore/write_syncer.go Co-authored-by: Prashant Varanasi --- zapcore/write_syncer.go | 4 +--- 1 file changed, 1 insertion(+), 3 deletions(-) diff --git a/zapcore/write_syncer.go b/zapcore/write_syncer.go index 710b76661..cc5b2ac1f 100644 --- a/zapcore/write_syncer.go +++ b/zapcore/write_syncer.go @@ -124,12 +124,10 @@ func Buffer(ws WriteSyncer, bufferSize int, flushInterval time.Duration) (_ Writ flushInterval = _defaultFlushInterval } - ticker := time.NewTicker(flushInterval) - bws := &bufferWriterSyncer{ stop: make(chan struct{}), bufferWriter: bufio.NewWriterSize(ws, bufferSize), - ticker: ticker, + ticker: time.NewTicker(flushInterval), } go bws.flushLoop() From 963142be2252e6b18fddc2bce95b86fb450520bf Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?=E5=A4=A7=E5=8F=AF?= Date: Fri, 6 Nov 2020 15:16:52 +0800 Subject: [PATCH 44/74] Update zapcore/write_syncer.go Co-authored-by: Prashant Varanasi --- zapcore/write_syncer.go | 1 - 1 file changed, 1 deletion(-) diff --git a/zapcore/write_syncer.go b/zapcore/write_syncer.go index cc5b2ac1f..ec19c79f8 100644 --- a/zapcore/write_syncer.go +++ b/zapcore/write_syncer.go @@ -138,7 +138,6 @@ func Buffer(ws WriteSyncer, bufferSize int, flushInterval time.Duration) (_ Writ // Write writes log data into buffer syncer directly, multiple Write calls will be batched, // and log data will be flushed to disk when the buffer is full or periodically. func (s *bufferWriterSyncer) Write(bs []byte) (int, error) { - // bufio is not goroutine safe, so add lock writer here s.Lock() defer s.Unlock() From f7539267dbadd7e891a712701d71f66c2c24225c Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?=E5=A4=A7=E5=8F=AF?= Date: Fri, 6 Nov 2020 15:17:11 +0800 Subject: [PATCH 45/74] Update zapcore/write_syncer.go Co-authored-by: Prashant Varanasi --- zapcore/write_syncer.go | 8 +++----- 1 file changed, 3 insertions(+), 5 deletions(-) diff --git a/zapcore/write_syncer.go b/zapcore/write_syncer.go index ec19c79f8..ce91efa4d 100644 --- a/zapcore/write_syncer.go +++ b/zapcore/write_syncer.go @@ -141,11 +141,9 @@ func (s *bufferWriterSyncer) Write(bs []byte) (int, error) { s.Lock() defer s.Unlock() - // there are some logic internal for bufio.Writer here: - // 1. when the buffer is enough, data would not be flushed. - // 2. when the buffer is not enough, data would be flushed as soon as the buffer fills up. - // this would lead to log spliting, which is not acceptable for log collector - // so we need to flush bufferWriter before writing the data into bufferWriter + // To avoid partial writes from being flushed, we manually flush the existing buffer if: + // * The current write doesn't fit into the buffer fully, and + // * The buffer is not empty (since bufio will not split large writes when the buffer is empty) if len(bs) > s.bufferWriter.Available() && s.bufferWriter.Buffered() > 0 { if err := s.bufferWriter.Flush(); err != nil { return 0, err From 1db469236731ffdd5e55a1d562a63a8ba4a07a0d Mon Sep 17 00:00:00 2001 From: liqi Date: Fri, 6 Nov 2020 15:23:08 +0800 Subject: [PATCH 46/74] add comment --- zapcore/write_syncer.go | 3 +++ 1 file changed, 3 insertions(+) diff --git a/zapcore/write_syncer.go b/zapcore/write_syncer.go index ce91efa4d..5da3093be 100644 --- a/zapcore/write_syncer.go +++ b/zapcore/write_syncer.go @@ -168,6 +168,9 @@ func (s *bufferWriterSyncer) flushLoop() { for { select { case <-s.ticker.C: + // we just simply ignore error here + // because the underlying bufio writer stores any errors + // and we return any error from Sync() as part of the close _ = s.Sync() case <-s.stop: return From 545d164c7204dfbaf82614a82a8d4361f800bc17 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?=E5=A4=A7=E5=8F=AF?= Date: Fri, 6 Nov 2020 15:25:35 +0800 Subject: [PATCH 47/74] Update zapcore/write_syncer.go Co-authored-by: Prashant Varanasi --- zapcore/write_syncer.go | 1 - 1 file changed, 1 deletion(-) diff --git a/zapcore/write_syncer.go b/zapcore/write_syncer.go index 5da3093be..2fa152775 100644 --- a/zapcore/write_syncer.go +++ b/zapcore/write_syncer.go @@ -155,7 +155,6 @@ func (s *bufferWriterSyncer) Write(bs []byte) (int, error) { // Sync flushes buffered log data into disk directly. func (s *bufferWriterSyncer) Sync() error { - // bufio is not goroutine safe, so add lock writer here s.Lock() defer s.Unlock() From c777047ef013dc2d98022aa559f2995f6a38917d Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?=E5=A4=A7=E5=8F=AF?= Date: Fri, 6 Nov 2020 15:31:53 +0800 Subject: [PATCH 48/74] Update zapcore/write_syncer.go Co-authored-by: Abhinav Gupta --- zapcore/write_syncer.go | 1 + 1 file changed, 1 insertion(+) diff --git a/zapcore/write_syncer.go b/zapcore/write_syncer.go index 2fa152775..ff8352a1d 100644 --- a/zapcore/write_syncer.go +++ b/zapcore/write_syncer.go @@ -80,6 +80,7 @@ func (s *lockedWriteSyncer) Sync() error { type bufferWriterSyncer struct { sync.Mutex + stop chan struct{} bufferWriter *bufio.Writer ticker *time.Ticker From 1b0fcfd944d8e10e776071eb6565d05b62c984bb Mon Sep 17 00:00:00 2001 From: liqi Date: Fri, 6 Nov 2020 15:32:34 +0800 Subject: [PATCH 49/74] update --- zapcore/write_syncer.go | 1 - 1 file changed, 1 deletion(-) diff --git a/zapcore/write_syncer.go b/zapcore/write_syncer.go index ff8352a1d..2fa152775 100644 --- a/zapcore/write_syncer.go +++ b/zapcore/write_syncer.go @@ -80,7 +80,6 @@ func (s *lockedWriteSyncer) Sync() error { type bufferWriterSyncer struct { sync.Mutex - stop chan struct{} bufferWriter *bufio.Writer ticker *time.Ticker From 02c9d3f5371c8b0a39562c91bfbb9025b2422b01 Mon Sep 17 00:00:00 2001 From: Prashant Varanasi Date: Tue, 5 Jan 2021 15:27:59 -0800 Subject: [PATCH 50/74] Remove Lock/Unlock from tests --- zapcore/write_syncer_test.go | 5 ----- 1 file changed, 5 deletions(-) diff --git a/zapcore/write_syncer_test.go b/zapcore/write_syncer_test.go index 0f8fd9129..5fa1fe687 100644 --- a/zapcore/write_syncer_test.go +++ b/zapcore/write_syncer_test.go @@ -131,17 +131,12 @@ func TestBufferWriter(t *testing.T) { defer close() requireWriteWorks(t, ws) ztest.Sleep(10 * time.Millisecond) - bws := ws.(*bufferWriterSyncer) - bws.Lock() assert.Equal(t, "foo", buf.String(), "Unexpected log string") - bws.Unlock() // flush twice to validate loop logic requireWriteWorks(t, ws) ztest.Sleep(10 * time.Millisecond) - bws.Lock() assert.Equal(t, "foofoo", buf.String(), "Unexpected log string") - bws.Unlock() }) } From 4804188b7a300f58bf780a015bc784d3910a506a Mon Sep 17 00:00:00 2001 From: liqi Date: Wed, 6 Jan 2021 15:46:05 +0800 Subject: [PATCH 51/74] remove double buffer check --- zapcore/write_syncer.go | 5 ----- 1 file changed, 5 deletions(-) diff --git a/zapcore/write_syncer.go b/zapcore/write_syncer.go index 2fa152775..2c99d3d37 100644 --- a/zapcore/write_syncer.go +++ b/zapcore/write_syncer.go @@ -111,11 +111,6 @@ const ( // The buffer size defaults to 256 kB if set to zero. // The flush interval defaults to 30 seconds if set to zero. func Buffer(ws WriteSyncer, bufferSize int, flushInterval time.Duration) (_ WriteSyncer, close func() error) { - if _, ok := ws.(*bufferWriterSyncer); ok { - // no need to layer on another buffer - return ws, func() error { return nil } - } - if bufferSize == 0 { bufferSize = _defaultBufferSize } From 4ca46e9f615e3d231956ca725250ba3cf327f732 Mon Sep 17 00:00:00 2001 From: liqi Date: Wed, 6 Jan 2021 15:47:13 +0800 Subject: [PATCH 52/74] set timer to zero --- zapcore/write_syncer_test.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/zapcore/write_syncer_test.go b/zapcore/write_syncer_test.go index 5fa1fe687..61c7a6790 100644 --- a/zapcore/write_syncer_test.go +++ b/zapcore/write_syncer_test.go @@ -117,7 +117,7 @@ func TestBufferWriter(t *testing.T) { }) t.Run("flush error", func(t *testing.T) { - ws, close := Buffer(AddSync(&errorWriter{}), 4, time.Nanosecond) + ws, close := Buffer(AddSync(&errorWriter{}), 4, 0) n, err := ws.Write([]byte("foo")) require.NoError(t, err, "Unexpected error writing to WriteSyncer.") require.Equal(t, 3, n, "Wrote an unexpected number of bytes.") From b1a95ffa4318d1b9e860a266f64274dbda0e78f3 Mon Sep 17 00:00:00 2001 From: liqi Date: Wed, 6 Jan 2021 15:52:19 +0800 Subject: [PATCH 53/74] remove errorWriter --- zapcore/write_syncer_test.go | 6 +----- 1 file changed, 1 insertion(+), 5 deletions(-) diff --git a/zapcore/write_syncer_test.go b/zapcore/write_syncer_test.go index 61c7a6790..98d62ff75 100644 --- a/zapcore/write_syncer_test.go +++ b/zapcore/write_syncer_test.go @@ -39,10 +39,6 @@ type writeSyncSpy struct { ztest.Syncer } -type errorWriter struct{} - -func (*errorWriter) Write([]byte) (int, error) { return 0, errors.New("unimplemented") } - func requireWriteWorks(t testing.TB, ws WriteSyncer) { n, err := ws.Write([]byte("foo")) require.NoError(t, err, "Unexpected error writing to WriteSyncer.") @@ -117,7 +113,7 @@ func TestBufferWriter(t *testing.T) { }) t.Run("flush error", func(t *testing.T) { - ws, close := Buffer(AddSync(&errorWriter{}), 4, 0) + ws, close := Buffer(AddSync(&ztest.FailWriter{}), 4, 0) n, err := ws.Write([]byte("foo")) require.NoError(t, err, "Unexpected error writing to WriteSyncer.") require.Equal(t, 3, n, "Wrote an unexpected number of bytes.") From 6d58a7dc52155a610e44cd6abbbf08c00628b361 Mon Sep 17 00:00:00 2001 From: liqi Date: Wed, 6 Jan 2021 16:59:24 +0800 Subject: [PATCH 54/74] add SyncBuffer --- internal/ztest/writer.go | 26 ++++++++++++++++++++++++++ zapcore/write_syncer_test.go | 2 +- 2 files changed, 27 insertions(+), 1 deletion(-) diff --git a/internal/ztest/writer.go b/internal/ztest/writer.go index 9fdd5805e..b9a1928dc 100644 --- a/internal/ztest/writer.go +++ b/internal/ztest/writer.go @@ -25,6 +25,7 @@ import ( "errors" "io/ioutil" "strings" + "sync" ) // A Syncer is a spy for the Sync portion of zapcore.WriteSyncer. @@ -94,3 +95,28 @@ func (b *Buffer) Lines() []string { func (b *Buffer) Stripped() string { return strings.TrimRight(b.String(), "\n") } + +// SyncBuffer is an implementation of bytes.Buffer which is goroutine safe. +type SyncBuffer struct { + sync.RWMutex + + buf bytes.Buffer +} + +// Write appends the contents of p to the buffer, growing the buffer as +// needed. +func (b *SyncBuffer) Write(p []byte) (n int, err error) { + b.Lock() + defer b.Unlock() + + return b.buf.Write(p) +} + +// String returns the contents of the unread portion of the buffer +// as a string. +func (b *SyncBuffer) String() string { + b.RLock() + defer b.RUnlock() + + return b.buf.String() +} diff --git a/zapcore/write_syncer_test.go b/zapcore/write_syncer_test.go index 98d62ff75..e41ae2369 100644 --- a/zapcore/write_syncer_test.go +++ b/zapcore/write_syncer_test.go @@ -122,7 +122,7 @@ func TestBufferWriter(t *testing.T) { }) t.Run("flush timer", func(t *testing.T) { - buf := &bytes.Buffer{} + buf := &ztest.SyncBuffer{} ws, close := Buffer(AddSync(buf), 6, time.Microsecond) defer close() requireWriteWorks(t, ws) From 2312b394cfaf21f292a7e2557dcd8f17b2c8c1d1 Mon Sep 17 00:00:00 2001 From: Moises Vega Date: Tue, 25 May 2021 13:01:39 -0700 Subject: [PATCH 55/74] Add buffered write syncer --- go.mod | 10 -- go.sum | 19 --- internal/ztest/writer.go | 26 ---- zapcore/buffered_write_syncer.go | 131 ++++++++++++++++++++ zapcore/buffered_write_syncer_bench_test.go | 49 ++++++++ zapcore/buffered_write_syncer_test.go | 106 ++++++++++++++++ zapcore/write_syncer.go | 105 ---------------- zapcore/write_syncer_bench_test.go | 31 ++--- zapcore/write_syncer_test.go | 74 +---------- 9 files changed, 296 insertions(+), 255 deletions(-) create mode 100644 zapcore/buffered_write_syncer.go create mode 100644 zapcore/buffered_write_syncer_bench_test.go create mode 100644 zapcore/buffered_write_syncer_test.go diff --git a/go.mod b/go.mod index 2d927129e..9455c99cc 100644 --- a/go.mod +++ b/go.mod @@ -5,20 +5,10 @@ go 1.13 require ( github.com/benbjohnson/clock v1.1.0 github.com/pkg/errors v0.8.1 -<<<<<<< HEAD github.com/stretchr/testify v1.7.0 go.uber.org/atomic v1.7.0 go.uber.org/goleak v1.1.10 go.uber.org/multierr v1.6.0 gopkg.in/yaml.v2 v2.2.8 gopkg.in/yaml.v3 v3.0.0-20210107192922-496545a6307b // indirect -======= - github.com/stretchr/testify v1.4.0 - go.uber.org/atomic v1.6.0 - go.uber.org/goleak v1.1.10 - go.uber.org/multierr v1.5.0 - golang.org/x/lint v0.0.0-20190930215403-16217165b5de - gopkg.in/yaml.v2 v2.2.2 - honnef.co/go/tools v0.0.1-2019.2.3 ->>>>>>> 761c8e8 (improve close logic and use goleak) ) diff --git a/go.sum b/go.sum index f95667197..9031a6131 100644 --- a/go.sum +++ b/go.sum @@ -15,7 +15,6 @@ github.com/pmezard/go-difflib v1.0.0/go.mod h1:iKH77koFhYxTK1pcRnkKkqfTogsbg7gZN github.com/stretchr/objx v0.1.0/go.mod h1:HFkY916IF+rwdDfMAkV7OtwuqBVzrE8GR6GFx+wExME= github.com/stretchr/testify v1.3.0/go.mod h1:M5WIy9Dh21IEIfnGCwXGc5bZfKNJtfHm1UVUgZn+9EI= github.com/stretchr/testify v1.4.0/go.mod h1:j7eGeouHqKxXV5pUuKE4zz7dFj8WfuZ+81PSLYec5m4= -<<<<<<< HEAD github.com/stretchr/testify v1.7.0 h1:nwc3DEeHmmLAfoZucVR881uASk0Mfjw8xYJ99tb5CcY= github.com/stretchr/testify v1.7.0/go.mod h1:6Fq8oRcR53rry900zMqJjRRixrwX3KX962/h/Wwjteg= go.uber.org/atomic v1.7.0 h1:ADUqmZGgLDDfbSL9ZmPxKTybcoEYHgpYfELNoN+7hsw= @@ -24,16 +23,6 @@ go.uber.org/goleak v1.1.10 h1:z+mqJhf6ss6BSfSM671tgKyZBFPTTJM+HLxnhPC3wu0= go.uber.org/goleak v1.1.10/go.mod h1:8a7PlsEVH3e/a/GLqe5IIrQx6GzcnRmZEufDUTk4A7A= go.uber.org/multierr v1.6.0 h1:y6IPFStTAIT5Ytl7/XYmHvzXQ7S3g/IeZW9hyZ5thw4= go.uber.org/multierr v1.6.0/go.mod h1:cdWPpRnG4AhwMwsgIHip0KRBQjJy5kYEpYjJxpXp9iU= -======= -go.uber.org/atomic v1.6.0 h1:Ezj3JGmsOnG1MoRWQkPBsKLe9DwWD9QeXzTRzzldNVk= -go.uber.org/atomic v1.6.0/go.mod h1:sABNBOSYdrvTF6hTgEIbc7YasKWGhgEQZyfxyTvoXHQ= -go.uber.org/goleak v1.1.10 h1:z+mqJhf6ss6BSfSM671tgKyZBFPTTJM+HLxnhPC3wu0= -go.uber.org/goleak v1.1.10/go.mod h1:8a7PlsEVH3e/a/GLqe5IIrQx6GzcnRmZEufDUTk4A7A= -go.uber.org/multierr v1.5.0 h1:KCa4XfM8CWFCpxXRGok+Q0SS/0XBhMDbHHGABQLvD2A= -go.uber.org/multierr v1.5.0/go.mod h1:FeouvMocqHpRaaGuG9EjoKcStLC43Zu/fmqdUMPcKYU= -go.uber.org/tools v0.0.0-20190618225709-2cfd321de3ee h1:0mgffUl7nfd+FpvXMVz4IDEaUSmT1ysygQC7qYo7sG4= -go.uber.org/tools v0.0.0-20190618225709-2cfd321de3ee/go.mod h1:vJERXedbb3MVM5f9Ejo0C68/HhF8uaILCdgjnY+goOA= ->>>>>>> 761c8e8 (improve close logic and use goleak) golang.org/x/crypto v0.0.0-20190308221718-c2843e01d9a2/go.mod h1:djNgcEr1/C05ACkg1iLfiJU5Ep61QUkGW8qpdssI0+w= golang.org/x/lint v0.0.0-20190930215403-16217165b5de h1:5hukYrvBGR8/eNkX5mdUezrA6JiaEZDtJb9Ei+1LlBs= golang.org/x/lint v0.0.0-20190930215403-16217165b5de/go.mod h1:6SW0HCj/g11FgYtHlgUYUwCkIfeOF89ocIRzGO/8vkc= @@ -43,14 +32,6 @@ golang.org/x/sync v0.0.0-20190423024810-112230192c58/go.mod h1:RxMgew5VJxzue5/jJ golang.org/x/sys v0.0.0-20190215142949-d0b11bdaac8a/go.mod h1:STP8DvDyc/dI5b8T5hshtkjS+E42TnysNCUPdjciGhY= golang.org/x/text v0.3.0/go.mod h1:NqM8EUOU14njkJ3fqMW+pc6Ldnwhi/IjpwHt7yyuwOQ= golang.org/x/tools v0.0.0-20190311212946-11955173bddd/go.mod h1:LCzVGOaR6xXOjkQ3onu1FJEFr0SW1gC7cKk1uF8kGRs= -<<<<<<< HEAD -======= -golang.org/x/tools v0.0.0-20190621195816-6e04913cbbac/go.mod h1:/rFqwRUd4F7ZHNgwSSTFct+R/Kf4OFW1sUzUTQQTgfc= -golang.org/x/tools v0.0.0-20191029041327-9cc4af7d6b2c h1:IGkKhmfzcztjm6gYkykvu/NiS8kaqbCWAEWWAyf8J5U= -golang.org/x/tools v0.0.0-20191029041327-9cc4af7d6b2c/go.mod h1:b+2E5dAYhXwXZwtnZ6UAqBI28+e2cm9otk0dWdXHAEo= -golang.org/x/tools v0.0.0-20191029190741-b9c20aec41a5 h1:hKsoRgsbwY1NafxrwTs+k64bikrLBkAgPir1TNCj3Zs= -golang.org/x/tools v0.0.0-20191029190741-b9c20aec41a5/go.mod h1:b+2E5dAYhXwXZwtnZ6UAqBI28+e2cm9otk0dWdXHAEo= ->>>>>>> 761c8e8 (improve close logic and use goleak) golang.org/x/tools v0.0.0-20191108193012-7d206e10da11 h1:Yq9t9jnGoR+dBuitxdo9l6Q7xh/zOyNnYUtDKaQ3x0E= golang.org/x/tools v0.0.0-20191108193012-7d206e10da11/go.mod h1:b+2E5dAYhXwXZwtnZ6UAqBI28+e2cm9otk0dWdXHAEo= golang.org/x/xerrors v0.0.0-20190717185122-a985d3407aa7/go.mod h1:I/5z698sn9Ka8TeJc9MKroUUfqBBauWjQqLJ2OPfmY0= diff --git a/internal/ztest/writer.go b/internal/ztest/writer.go index b9a1928dc..9fdd5805e 100644 --- a/internal/ztest/writer.go +++ b/internal/ztest/writer.go @@ -25,7 +25,6 @@ import ( "errors" "io/ioutil" "strings" - "sync" ) // A Syncer is a spy for the Sync portion of zapcore.WriteSyncer. @@ -95,28 +94,3 @@ func (b *Buffer) Lines() []string { func (b *Buffer) Stripped() string { return strings.TrimRight(b.String(), "\n") } - -// SyncBuffer is an implementation of bytes.Buffer which is goroutine safe. -type SyncBuffer struct { - sync.RWMutex - - buf bytes.Buffer -} - -// Write appends the contents of p to the buffer, growing the buffer as -// needed. -func (b *SyncBuffer) Write(p []byte) (n int, err error) { - b.Lock() - defer b.Unlock() - - return b.buf.Write(p) -} - -// String returns the contents of the unread portion of the buffer -// as a string. -func (b *SyncBuffer) String() string { - b.RLock() - defer b.RUnlock() - - return b.buf.String() -} diff --git a/zapcore/buffered_write_syncer.go b/zapcore/buffered_write_syncer.go new file mode 100644 index 000000000..e336866c9 --- /dev/null +++ b/zapcore/buffered_write_syncer.go @@ -0,0 +1,131 @@ +// Copyright (c) 2021 Uber Technologies, Inc. +// +// Permission is hereby granted, free of charge, to any person obtaining a copy +// of this software and associated documentation files (the "Software"), to deal +// in the Software without restriction, including without limitation the rights +// to use, copy, modify, merge, publish, distribute, sublicense, and/or sell +// copies of the Software, and to permit persons to whom the Software is +// furnished to do so, subject to the following conditions: +// +// The above copyright notice and this permission notice shall be included in +// all copies or substantial portions of the Software. +// +// THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR +// IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY, +// FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL THE +// AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER +// LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING FROM, +// OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN +// THE SOFTWARE. + +package zapcore + +import ( + "bufio" + "sync" + "time" +) + +// A BufferedWriteSyncer is a WriteSyncer that can also flush any buffered data +// with the ability to change the buffer size, flush interval and Clock. +// The default values are; Size 256kb, FlushInterval 30s. +type BufferedWriteSyncer struct { + WriteSyncer + + Size int + FlushInterval time.Duration + Clock Clock + + // unexported fields for state + mu sync.Mutex + writer *bufio.Writer + ticker *time.Ticker + stop chan struct{} + initialized bool +} + +const ( + // _defaultBufferSize specifies the default size used by Buffer. + _defaultBufferSize = 256 * 1024 // 256 kB + + // _defaultFlushInterval specifies the default flush interval for + // Buffer. + _defaultFlushInterval = 30 * time.Second +) + +func (s *BufferedWriteSyncer) loadConfig() { + size := s.Size + if size == 0 { + size = _defaultBufferSize + } + + flushInterval := s.FlushInterval + if flushInterval == 0 { + flushInterval = _defaultFlushInterval + } + + if s.Clock != nil { + s.ticker = s.Clock.NewTicker(flushInterval) + } else { + s.ticker = DefaultClock.NewTicker(flushInterval) + } + + s.writer = bufio.NewWriterSize(s.WriteSyncer, size) + s.stop = make(chan struct{}) + s.initialized = true + go s.flushLoop() +} + +// Write writes log data into buffer syncer directly, multiple Write calls will be batched, +// and log data will be flushed to disk when the buffer is full or periodically. +func (s *BufferedWriteSyncer) Write(bs []byte) (int, error) { + s.mu.Lock() + defer s.mu.Unlock() + + if !s.initialized { + s.loadConfig() + } + + // To avoid partial writes from being flushed, we manually flush the existing buffer if: + // * The current write doesn't fit into the buffer fully, and + // * The buffer is not empty (since bufio will not split large writes when the buffer is empty) + if len(bs) > s.writer.Available() && s.writer.Buffered() > 0 { + if err := s.writer.Flush(); err != nil { + return 0, err + } + } + + return s.writer.Write(bs) +} + +// Sync flushes buffered log data into disk directly. +func (s *BufferedWriteSyncer) Sync() error { + s.mu.Lock() + defer s.mu.Unlock() + + return s.writer.Flush() +} + +// flushLoop flushes the buffer at the configured interval until Close is +// called. +func (s *BufferedWriteSyncer) flushLoop() { + for { + select { + case <-s.ticker.C: + // we just simply ignore error here + // because the underlying bufio writer stores any errors + // and we return any error from Sync() as part of the close + _ = s.Sync() + case <-s.stop: + return + } + } +} + +// Close closes the buffer, cleans up background goroutines, and flushes +// remaining, unwritten data. +func (s *BufferedWriteSyncer) Close() error { + s.ticker.Stop() + close(s.stop) + return s.Sync() +} diff --git a/zapcore/buffered_write_syncer_bench_test.go b/zapcore/buffered_write_syncer_bench_test.go new file mode 100644 index 000000000..df3177e4c --- /dev/null +++ b/zapcore/buffered_write_syncer_bench_test.go @@ -0,0 +1,49 @@ +// Copyright (c) 2021 Uber Technologies, Inc. +// +// Permission is hereby granted, free of charge, to any person obtaining a copy +// of this software and associated documentation files (the "Software"), to deal +// in the Software without restriction, including without limitation the rights +// to use, copy, modify, merge, publish, distribute, sublicense, and/or sell +// copies of the Software, and to permit persons to whom the Software is +// furnished to do so, subject to the following conditions: +// +// The above copyright notice and this permission notice shall be included in +// all copies or substantial portions of the Software. +// +// THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR +// IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY, +// FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL THE +// AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER +// LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING FROM, +// OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN +// THE SOFTWARE. + +package zapcore + +import ( + "io/ioutil" + "os" + "testing" + + "github.com/stretchr/testify/assert" +) + +func BenchmarkBufferedWriteSyncer(b *testing.B) { + b.Run("write file with buffer", func(b *testing.B) { + file, err := ioutil.TempFile("", "log") + assert.NoError(b, err) + defer file.Close() + defer os.Remove(file.Name()) + + w := &BufferedWriteSyncer{ + WriteSyncer: AddSync(file), + } + defer w.Close() + b.ResetTimer() + b.RunParallel(func(pb *testing.PB) { + for pb.Next() { + w.Write([]byte("foobarbazbabble")) + } + }) + }) +} diff --git a/zapcore/buffered_write_syncer_test.go b/zapcore/buffered_write_syncer_test.go new file mode 100644 index 000000000..55cfac2f0 --- /dev/null +++ b/zapcore/buffered_write_syncer_test.go @@ -0,0 +1,106 @@ +// Copyright (c) 2021 Uber Technologies, Inc. +// +// Permission is hereby granted, free of charge, to any person obtaining a copy +// of this software and associated documentation files (the "Software"), to deal +// in the Software without restriction, including without limitation the rights +// to use, copy, modify, merge, publish, distribute, sublicense, and/or sell +// copies of the Software, and to permit persons to whom the Software is +// furnished to do so, subject to the following conditions: +// +// The above copyright notice and this permission notice shall be included in +// all copies or substantial portions of the Software. +// +// THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR +// IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY, +// FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL THE +// AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER +// LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING FROM, +// OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN +// THE SOFTWARE. + +package zapcore + +import ( + "bytes" + "testing" + "time" + + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" + "go.uber.org/zap/internal/ztest" +) + +func TestBufferWriter(t *testing.T) { + // If we pass a plain io.Writer, make sure that we still get a WriteSyncer + // with a no-op Sync. + t.Run("sync", func(t *testing.T) { + buf := &bytes.Buffer{} + ws := &BufferedWriteSyncer{WriteSyncer: AddSync(buf)} + + requireWriteWorks(t, ws) + assert.Empty(t, buf.String(), "Unexpected log calling a no-op Write method.") + assert.NoError(t, ws.Sync(), "Unexpected error calling a no-op Sync method.") + assert.Equal(t, "foo", buf.String(), "Unexpected log string") + assert.NoError(t, ws.Close()) + }) + + t.Run("close", func(t *testing.T) { + buf := &bytes.Buffer{} + ws := &BufferedWriteSyncer{WriteSyncer: AddSync(buf)} + requireWriteWorks(t, ws) + assert.Empty(t, buf.String(), "Unexpected log calling a no-op Write method.") + assert.NoError(t, ws.Close()) + assert.Equal(t, "foo", buf.String(), "Unexpected log string") + }) + + t.Run("wrap twice", func(t *testing.T) { + buf := &bytes.Buffer{} + bufsync := &BufferedWriteSyncer{WriteSyncer: AddSync(buf)} + ws := &BufferedWriteSyncer{WriteSyncer: bufsync} + requireWriteWorks(t, ws) + assert.Equal(t, "", buf.String(), "Unexpected log calling a no-op Write method.") + assert.NoError(t, ws.Close()) + assert.NoError(t, bufsync.Close()) + assert.Equal(t, "foo", buf.String(), "Unexpected log string") + }) + + t.Run("small buffer", func(t *testing.T) { + buf := &bytes.Buffer{} + ws := &BufferedWriteSyncer{WriteSyncer: AddSync(buf), Size: 5} + + requireWriteWorks(t, ws) + assert.Equal(t, "", buf.String(), "Unexpected log calling a no-op Write method.") + requireWriteWorks(t, ws) + assert.Equal(t, "foo", buf.String(), "Unexpected log string") + assert.NoError(t, ws.Close()) + }) + + t.Run("flush error", func(t *testing.T) { + ws := &BufferedWriteSyncer{WriteSyncer: &ztest.FailWriter{}, Size: 4} + n, err := ws.Write([]byte("foo")) + require.NoError(t, err, "Unexpected error writing to WriteSyncer.") + require.Equal(t, 3, n, "Wrote an unexpected number of bytes.") + ws.Write([]byte("foo")) + assert.Error(t, ws.Close(), "Expected close to fail.") + }) + + t.Run("flush timer", func(t *testing.T) { + buf := &bytes.Buffer{} + clock := newControlledClock() + ws := &BufferedWriteSyncer{ + WriteSyncer: AddSync(buf), + Size: 6, + FlushInterval: time.Microsecond, + Clock: clock, + } + requireWriteWorks(t, ws) + clock.Add(10 * time.Millisecond) + assert.Equal(t, "foo", buf.String(), "Unexpected log string") + + // flush twice to validate loop logic + requireWriteWorks(t, ws) + clock.Add(10 * time.Millisecond) + assert.Equal(t, "foofoo", buf.String(), "Unexpected log string") + assert.NoError(t, ws.Close()) + }) +} diff --git a/zapcore/write_syncer.go b/zapcore/write_syncer.go index 2c99d3d37..d4a1af3d0 100644 --- a/zapcore/write_syncer.go +++ b/zapcore/write_syncer.go @@ -21,10 +21,8 @@ package zapcore import ( - "bufio" "io" "sync" - "time" "go.uber.org/multierr" ) @@ -77,109 +75,6 @@ func (s *lockedWriteSyncer) Sync() error { return err } -type bufferWriterSyncer struct { - sync.Mutex - - stop chan struct{} - bufferWriter *bufio.Writer - ticker *time.Ticker -} - -const ( - // _defaultBufferSize specifies the default size used by Buffer. - _defaultBufferSize = 256 * 1024 // 256 kB - - // _defaultFlushInterval specifies the default flush interval for - // Buffer. - _defaultFlushInterval = 30 * time.Second -) - -// Buffer wraps a WriteSyncer to buffer its output. The returned WriteSyncer -// flushes its output as the buffer fills up, or at the provided interval, -// whichever comes first. -// -// Call the returned function to finish using the WriteSyncer and flush -// remaining bytes. -// -// func main() { -// // ... -// ws, closeWS := zapcore.Buffer(ws, 0, 0) -// defer closeWS() -// // ... -// } -// -// The buffer size defaults to 256 kB if set to zero. -// The flush interval defaults to 30 seconds if set to zero. -func Buffer(ws WriteSyncer, bufferSize int, flushInterval time.Duration) (_ WriteSyncer, close func() error) { - if bufferSize == 0 { - bufferSize = _defaultBufferSize - } - - if flushInterval == 0 { - flushInterval = _defaultFlushInterval - } - - bws := &bufferWriterSyncer{ - stop: make(chan struct{}), - bufferWriter: bufio.NewWriterSize(ws, bufferSize), - ticker: time.NewTicker(flushInterval), - } - - go bws.flushLoop() - - return bws, bws.close -} - -// Write writes log data into buffer syncer directly, multiple Write calls will be batched, -// and log data will be flushed to disk when the buffer is full or periodically. -func (s *bufferWriterSyncer) Write(bs []byte) (int, error) { - s.Lock() - defer s.Unlock() - - // To avoid partial writes from being flushed, we manually flush the existing buffer if: - // * The current write doesn't fit into the buffer fully, and - // * The buffer is not empty (since bufio will not split large writes when the buffer is empty) - if len(bs) > s.bufferWriter.Available() && s.bufferWriter.Buffered() > 0 { - if err := s.bufferWriter.Flush(); err != nil { - return 0, err - } - } - - return s.bufferWriter.Write(bs) -} - -// Sync flushes buffered log data into disk directly. -func (s *bufferWriterSyncer) Sync() error { - s.Lock() - defer s.Unlock() - - return s.bufferWriter.Flush() -} - -// flushLoop flushes the buffer at the configured interval until Close is -// called. -func (s *bufferWriterSyncer) flushLoop() { - for { - select { - case <-s.ticker.C: - // we just simply ignore error here - // because the underlying bufio writer stores any errors - // and we return any error from Sync() as part of the close - _ = s.Sync() - case <-s.stop: - return - } - } -} - -// close closes the buffer, cleans up background goroutines, and flushes -// remaining, unwritten data. -func (s *bufferWriterSyncer) close() error { - s.ticker.Stop() - close(s.stop) - return s.Sync() -} - type writerWrapper struct { io.Writer } diff --git a/zapcore/write_syncer_bench_test.go b/zapcore/write_syncer_bench_test.go index f16fc3530..c3bcafe54 100644 --- a/zapcore/write_syncer_bench_test.go +++ b/zapcore/write_syncer_bench_test.go @@ -57,13 +57,15 @@ func BenchmarkMultiWriteSyncer(b *testing.B) { }) }) b.Run("4 discarder with buffer", func(b *testing.B) { - w, close := Buffer(NewMultiWriteSyncer( - &ztest.Discarder{}, - &ztest.Discarder{}, - &ztest.Discarder{}, - &ztest.Discarder{}, - ), 0, 0) - defer close() + w := &BufferedWriteSyncer{ + WriteSyncer: NewMultiWriteSyncer( + &ztest.Discarder{}, + &ztest.Discarder{}, + &ztest.Discarder{}, + &ztest.Discarder{}, + ), + } + defer w.Close() b.ResetTimer() b.RunParallel(func(pb *testing.PB) { for pb.Next() { @@ -88,19 +90,4 @@ func BenchmarkWriteSyncer(b *testing.B) { } }) }) - b.Run("write file with buffer", func(b *testing.B) { - file, err := ioutil.TempFile("", "log") - assert.NoError(b, err) - defer file.Close() - defer os.Remove(file.Name()) - - w, close := Buffer(AddSync(file), 0, 0) - defer close() - b.ResetTimer() - b.RunParallel(func(pb *testing.PB) { - for pb.Next() { - w.Write([]byte("foobarbazbabble")) - } - }) - }) } diff --git a/zapcore/write_syncer_test.go b/zapcore/write_syncer_test.go index e41ae2369..4748be7f5 100644 --- a/zapcore/write_syncer_test.go +++ b/zapcore/write_syncer_test.go @@ -23,14 +23,11 @@ package zapcore import ( "bytes" "errors" - "testing" - "time" - "io" + "testing" "github.com/stretchr/testify/assert" "github.com/stretchr/testify/require" - "go.uber.org/goleak" "go.uber.org/zap/internal/ztest" ) @@ -67,75 +64,6 @@ func TestAddSyncWriter(t *testing.T) { assert.NoError(t, ws.Sync(), "Unexpected error calling a no-op Sync method.") } -func TestBufferWriter(t *testing.T) { - defer goleak.VerifyNone(t) - - // If we pass a plain io.Writer, make sure that we still get a WriteSyncer - // with a no-op Sync. - t.Run("sync", func(t *testing.T) { - buf := &bytes.Buffer{} - ws, close := Buffer(AddSync(buf), 0, 0) - defer close() - requireWriteWorks(t, ws) - assert.Empty(t, buf.String(), "Unexpected log calling a no-op Write method.") - assert.NoError(t, ws.Sync(), "Unexpected error calling a no-op Sync method.") - assert.Equal(t, "foo", buf.String(), "Unexpected log string") - }) - - t.Run("close", func(t *testing.T) { - buf := &bytes.Buffer{} - ws, close := Buffer(AddSync(buf), 0, 0) - requireWriteWorks(t, ws) - assert.Empty(t, buf.String(), "Unexpected log calling a no-op Write method.") - close() - assert.Equal(t, "foo", buf.String(), "Unexpected log string") - }) - - t.Run("wrap twice", func(t *testing.T) { - buf := &bytes.Buffer{} - bufsync, close1 := Buffer(AddSync(buf), 0, 0) - ws, close2 := Buffer(bufsync, 0, 0) - requireWriteWorks(t, ws) - assert.Equal(t, "", buf.String(), "Unexpected log calling a no-op Write method.") - close2() - close1() - assert.Equal(t, "foo", buf.String(), "Unexpected log string") - }) - - t.Run("small buffer", func(t *testing.T) { - buf := &bytes.Buffer{} - ws, close := Buffer(AddSync(buf), 5, 0) - defer close() - requireWriteWorks(t, ws) - assert.Equal(t, "", buf.String(), "Unexpected log calling a no-op Write method.") - requireWriteWorks(t, ws) - assert.Equal(t, "foo", buf.String(), "Unexpected log string") - }) - - t.Run("flush error", func(t *testing.T) { - ws, close := Buffer(AddSync(&ztest.FailWriter{}), 4, 0) - n, err := ws.Write([]byte("foo")) - require.NoError(t, err, "Unexpected error writing to WriteSyncer.") - require.Equal(t, 3, n, "Wrote an unexpected number of bytes.") - ws.Write([]byte("foo")) - assert.Error(t, close(), "Expected close to fail.") - }) - - t.Run("flush timer", func(t *testing.T) { - buf := &ztest.SyncBuffer{} - ws, close := Buffer(AddSync(buf), 6, time.Microsecond) - defer close() - requireWriteWorks(t, ws) - ztest.Sleep(10 * time.Millisecond) - assert.Equal(t, "foo", buf.String(), "Unexpected log string") - - // flush twice to validate loop logic - requireWriteWorks(t, ws) - ztest.Sleep(10 * time.Millisecond) - assert.Equal(t, "foofoo", buf.String(), "Unexpected log string") - }) -} - func TestNewMultiWriteSyncerWorksForSingleWriter(t *testing.T) { w := &ztest.Buffer{} From 7c32a14a040d4873f0ca8f44b8b4856dc070a24d Mon Sep 17 00:00:00 2001 From: Moises Vega Date: Tue, 1 Jun 2021 12:12:17 -0700 Subject: [PATCH 56/74] Set default Clock zapcore/buffered_write_syncer.go Co-authored-by: Abhinav Gupta --- zapcore/buffered_write_syncer.go | 7 +++---- 1 file changed, 3 insertions(+), 4 deletions(-) diff --git a/zapcore/buffered_write_syncer.go b/zapcore/buffered_write_syncer.go index e336866c9..f0127d39f 100644 --- a/zapcore/buffered_write_syncer.go +++ b/zapcore/buffered_write_syncer.go @@ -64,11 +64,10 @@ func (s *BufferedWriteSyncer) loadConfig() { flushInterval = _defaultFlushInterval } - if s.Clock != nil { - s.ticker = s.Clock.NewTicker(flushInterval) - } else { - s.ticker = DefaultClock.NewTicker(flushInterval) + if s.Clock == nil { + s.Clock = DefaultClock } + s.ticker = s.clock.NewTicker(flushInterval) s.writer = bufio.NewWriterSize(s.WriteSyncer, size) s.stop = make(chan struct{}) From ffba68baad737e6ccdac8cec28f9973b7f71d4fa Mon Sep 17 00:00:00 2001 From: Moises Vega Date: Tue, 1 Jun 2021 12:15:28 -0700 Subject: [PATCH 57/74] Use require instead assert zapcore/buffered_write_syncer_bench_test.go Co-authored-by: Abhinav Gupta --- zapcore/buffered_write_syncer_bench_test.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/zapcore/buffered_write_syncer_bench_test.go b/zapcore/buffered_write_syncer_bench_test.go index df3177e4c..3398f7745 100644 --- a/zapcore/buffered_write_syncer_bench_test.go +++ b/zapcore/buffered_write_syncer_bench_test.go @@ -31,7 +31,7 @@ import ( func BenchmarkBufferedWriteSyncer(b *testing.B) { b.Run("write file with buffer", func(b *testing.B) { file, err := ioutil.TempFile("", "log") - assert.NoError(b, err) + require.NoError(b, err) defer file.Close() defer os.Remove(file.Name()) From a3fbb8e162e2b2a441d1482ec6ac913f1609f9be Mon Sep 17 00:00:00 2001 From: Moises Vega Date: Tue, 1 Jun 2021 12:36:54 -0700 Subject: [PATCH 58/74] Update Close() comment, use filepath to create tmpDir and mutate Clock on loadConfig if needed --- zapcore/buffered_write_syncer.go | 4 ++-- zapcore/buffered_write_syncer_bench_test.go | 6 +++--- 2 files changed, 5 insertions(+), 5 deletions(-) diff --git a/zapcore/buffered_write_syncer.go b/zapcore/buffered_write_syncer.go index f0127d39f..82fc7e71d 100644 --- a/zapcore/buffered_write_syncer.go +++ b/zapcore/buffered_write_syncer.go @@ -67,7 +67,7 @@ func (s *BufferedWriteSyncer) loadConfig() { if s.Clock == nil { s.Clock = DefaultClock } - s.ticker = s.clock.NewTicker(flushInterval) + s.ticker = s.Clock.NewTicker(flushInterval) s.writer = bufio.NewWriterSize(s.WriteSyncer, size) s.stop = make(chan struct{}) @@ -122,7 +122,7 @@ func (s *BufferedWriteSyncer) flushLoop() { } // Close closes the buffer, cleans up background goroutines, and flushes -// remaining, unwritten data. +// remaining, unwritten data. This will not close the underlying WriteSyncer. func (s *BufferedWriteSyncer) Close() error { s.ticker.Stop() close(s.stop) diff --git a/zapcore/buffered_write_syncer_bench_test.go b/zapcore/buffered_write_syncer_bench_test.go index 3398f7745..bce99e742 100644 --- a/zapcore/buffered_write_syncer_bench_test.go +++ b/zapcore/buffered_write_syncer_bench_test.go @@ -21,16 +21,16 @@ package zapcore import ( - "io/ioutil" "os" + "path/filepath" "testing" - "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" ) func BenchmarkBufferedWriteSyncer(b *testing.B) { b.Run("write file with buffer", func(b *testing.B) { - file, err := ioutil.TempFile("", "log") + file, err := os.Create(filepath.Join(b.TempDir(), "log")) require.NoError(b, err) defer file.Close() defer os.Remove(file.Name()) From 39f731607749528d92c8ef673eecec4d32da98fb Mon Sep 17 00:00:00 2001 From: Moises Vega Date: Tue, 1 Jun 2021 14:54:09 -0700 Subject: [PATCH 59/74] Use ioutil for creating tmp file --- zapcore/buffered_write_syncer_bench_test.go | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/zapcore/buffered_write_syncer_bench_test.go b/zapcore/buffered_write_syncer_bench_test.go index bce99e742..9b5a45e6f 100644 --- a/zapcore/buffered_write_syncer_bench_test.go +++ b/zapcore/buffered_write_syncer_bench_test.go @@ -21,8 +21,8 @@ package zapcore import ( + "io/ioutil" "os" - "path/filepath" "testing" "github.com/stretchr/testify/require" @@ -30,7 +30,7 @@ import ( func BenchmarkBufferedWriteSyncer(b *testing.B) { b.Run("write file with buffer", func(b *testing.B) { - file, err := os.Create(filepath.Join(b.TempDir(), "log")) + file, err := ioutil.TempFile("", "log") require.NoError(b, err) defer file.Close() defer os.Remove(file.Name()) From 10b45db7be2d6c7ce807ac0bfbd02d9fde7dde42 Mon Sep 17 00:00:00 2001 From: Moises Vega Date: Fri, 4 Jun 2021 05:13:57 -0700 Subject: [PATCH 60/74] Sync underlying writeSyncer --- zapcore/buffered_write_syncer.go | 7 ++++++- zapcore/buffered_write_syncer_test.go | 4 ++-- 2 files changed, 8 insertions(+), 3 deletions(-) diff --git a/zapcore/buffered_write_syncer.go b/zapcore/buffered_write_syncer.go index 82fc7e71d..9e8e6bdd9 100644 --- a/zapcore/buffered_write_syncer.go +++ b/zapcore/buffered_write_syncer.go @@ -24,6 +24,8 @@ import ( "bufio" "sync" "time" + + "go.uber.org/multierr" ) // A BufferedWriteSyncer is a WriteSyncer that can also flush any buffered data @@ -37,6 +39,7 @@ type BufferedWriteSyncer struct { Clock Clock // unexported fields for state + ws WriteSyncer mu sync.Mutex writer *bufio.Writer ticker *time.Ticker @@ -54,6 +57,8 @@ const ( ) func (s *BufferedWriteSyncer) loadConfig() { + s.ws = s.WriteSyncer + size := s.Size if size == 0 { size = _defaultBufferSize @@ -102,7 +107,7 @@ func (s *BufferedWriteSyncer) Sync() error { s.mu.Lock() defer s.mu.Unlock() - return s.writer.Flush() + return multierr.Append(s.writer.Flush(), s.ws.Sync()) } // flushLoop flushes the buffer at the configured interval until Close is diff --git a/zapcore/buffered_write_syncer_test.go b/zapcore/buffered_write_syncer_test.go index 55cfac2f0..89ab3af3c 100644 --- a/zapcore/buffered_write_syncer_test.go +++ b/zapcore/buffered_write_syncer_test.go @@ -94,12 +94,12 @@ func TestBufferWriter(t *testing.T) { Clock: clock, } requireWriteWorks(t, ws) - clock.Add(10 * time.Millisecond) + clock.Add(10 * time.Microsecond) assert.Equal(t, "foo", buf.String(), "Unexpected log string") // flush twice to validate loop logic requireWriteWorks(t, ws) - clock.Add(10 * time.Millisecond) + clock.Add(10 * time.Microsecond) assert.Equal(t, "foofoo", buf.String(), "Unexpected log string") assert.NoError(t, ws.Close()) }) From 0962b0f2098735b939121b8cc33a200c936fab4e Mon Sep 17 00:00:00 2001 From: Moises Vega Date: Fri, 4 Jun 2021 05:30:10 -0700 Subject: [PATCH 61/74] Update default documentation and don't double lock --- go.sum | 8 ++++++++ zapcore/buffered_write_syncer.go | 24 ++++++++++++++++++------ 2 files changed, 26 insertions(+), 6 deletions(-) diff --git a/go.sum b/go.sum index 9031a6131..b330071a0 100644 --- a/go.sum +++ b/go.sum @@ -5,6 +5,7 @@ github.com/davecgh/go-spew v1.1.1 h1:vj9j/u1bqnvCEfJOwUhtlOARqs3+rkHYY13jYWTU97c github.com/davecgh/go-spew v1.1.1/go.mod h1:J7Y8YcW2NihsgmVo/mv3lAwl/skON4iLHjSsI+c5H38= github.com/kr/pretty v0.1.0 h1:L/CwN0zerZDmRFUapSPitk6f+Q3+0za1rQkzVuMiMFI= github.com/kr/pretty v0.1.0/go.mod h1:dAy3ld7l9f0ibDNOQOHHMYYIIbhfbHSm3C4ZsoJORNo= +github.com/kr/pty v1.1.1 h1:VkoXIwSboBpnk99O/KFauAEILuNHv5DVFKZMBN/gUgw= github.com/kr/pty v1.1.1/go.mod h1:pFQYn66WHrOpPYNljwOMqo10TkYh1fy3cYio2l3bCsQ= github.com/kr/text v0.1.0 h1:45sCR5RtlFHMR4UwH9sdQ5TC8v0qDQCHnXt+kaKSTVE= github.com/kr/text v0.1.0/go.mod h1:4Jbv+DJW3UT/LiOwJeYQe1efqtUx/iVham/4vfdArNI= @@ -12,6 +13,7 @@ github.com/pkg/errors v0.8.1 h1:iURUrRGxPUNPdy5/HRSm+Yj6okJ6UtLINN0Q9M4+h3I= github.com/pkg/errors v0.8.1/go.mod h1:bwawxfHBFNV+L2hUp1rHADufV3IMtnDRdf1r5NINEl0= github.com/pmezard/go-difflib v1.0.0 h1:4DBwDE0NGyQoBHbLQYPwSUPoCMWR5BEzIk/f1lZbAQM= github.com/pmezard/go-difflib v1.0.0/go.mod h1:iKH77koFhYxTK1pcRnkKkqfTogsbg7gZNVY4sRDYZ/4= +github.com/stretchr/objx v0.1.0 h1:4G4v2dO3VZwixGIRoQ5Lfboy6nUhCyYzaqnIAPPhYs4= github.com/stretchr/objx v0.1.0/go.mod h1:HFkY916IF+rwdDfMAkV7OtwuqBVzrE8GR6GFx+wExME= github.com/stretchr/testify v1.3.0/go.mod h1:M5WIy9Dh21IEIfnGCwXGc5bZfKNJtfHm1UVUgZn+9EI= github.com/stretchr/testify v1.4.0/go.mod h1:j7eGeouHqKxXV5pUuKE4zz7dFj8WfuZ+81PSLYec5m4= @@ -23,17 +25,23 @@ go.uber.org/goleak v1.1.10 h1:z+mqJhf6ss6BSfSM671tgKyZBFPTTJM+HLxnhPC3wu0= go.uber.org/goleak v1.1.10/go.mod h1:8a7PlsEVH3e/a/GLqe5IIrQx6GzcnRmZEufDUTk4A7A= go.uber.org/multierr v1.6.0 h1:y6IPFStTAIT5Ytl7/XYmHvzXQ7S3g/IeZW9hyZ5thw4= go.uber.org/multierr v1.6.0/go.mod h1:cdWPpRnG4AhwMwsgIHip0KRBQjJy5kYEpYjJxpXp9iU= +golang.org/x/crypto v0.0.0-20190308221718-c2843e01d9a2 h1:VklqNMn3ovrHsnt90PveolxSbWFaJdECFbxSq0Mqo2M= golang.org/x/crypto v0.0.0-20190308221718-c2843e01d9a2/go.mod h1:djNgcEr1/C05ACkg1iLfiJU5Ep61QUkGW8qpdssI0+w= golang.org/x/lint v0.0.0-20190930215403-16217165b5de h1:5hukYrvBGR8/eNkX5mdUezrA6JiaEZDtJb9Ei+1LlBs= golang.org/x/lint v0.0.0-20190930215403-16217165b5de/go.mod h1:6SW0HCj/g11FgYtHlgUYUwCkIfeOF89ocIRzGO/8vkc= golang.org/x/net v0.0.0-20190311183353-d8887717615a/go.mod h1:t9HGtf8HONx5eT2rtn7q6eTqICYqUVnKs3thJo3Qplg= +golang.org/x/net v0.0.0-20190620200207-3b0461eec859 h1:R/3boaszxrf1GEUWTVDzSKVwLmSJpwZ1yqXm8j0v2QI= golang.org/x/net v0.0.0-20190620200207-3b0461eec859/go.mod h1:z5CRVTTTmAJ677TzLLGU+0bjPO0LkuOLi4/5GtJWs/s= +golang.org/x/sync v0.0.0-20190423024810-112230192c58 h1:8gQV6CLnAEikrhgkHFbMAEhagSSnXWGV915qUMm9mrU= golang.org/x/sync v0.0.0-20190423024810-112230192c58/go.mod h1:RxMgew5VJxzue5/jJTE5uejpjVlOe/izrB70Jof72aM= +golang.org/x/sys v0.0.0-20190215142949-d0b11bdaac8a h1:1BGLXjeY4akVXGgbC9HugT3Jv3hCI0z56oJR5vAMgBU= golang.org/x/sys v0.0.0-20190215142949-d0b11bdaac8a/go.mod h1:STP8DvDyc/dI5b8T5hshtkjS+E42TnysNCUPdjciGhY= +golang.org/x/text v0.3.0 h1:g61tztE5qeGQ89tm6NTjjM9VPIm088od1l6aSorWRWg= golang.org/x/text v0.3.0/go.mod h1:NqM8EUOU14njkJ3fqMW+pc6Ldnwhi/IjpwHt7yyuwOQ= golang.org/x/tools v0.0.0-20190311212946-11955173bddd/go.mod h1:LCzVGOaR6xXOjkQ3onu1FJEFr0SW1gC7cKk1uF8kGRs= golang.org/x/tools v0.0.0-20191108193012-7d206e10da11 h1:Yq9t9jnGoR+dBuitxdo9l6Q7xh/zOyNnYUtDKaQ3x0E= golang.org/x/tools v0.0.0-20191108193012-7d206e10da11/go.mod h1:b+2E5dAYhXwXZwtnZ6UAqBI28+e2cm9otk0dWdXHAEo= +golang.org/x/xerrors v0.0.0-20190717185122-a985d3407aa7 h1:9zdDQZ7Thm29KFXgAX/+yaf3eVbP7djjWp/dXAppNCc= golang.org/x/xerrors v0.0.0-20190717185122-a985d3407aa7/go.mod h1:I/5z698sn9Ka8TeJc9MKroUUfqBBauWjQqLJ2OPfmY0= gopkg.in/check.v1 v0.0.0-20161208181325-20d25e280405/go.mod h1:Co6ibVJAznAaIkqp8huTwlJQCZ016jof/cbN4VW5Yz0= gopkg.in/check.v1 v1.0.0-20180628173108-788fd7840127 h1:qIbj1fsPNlZgppZ+VLlY7N33q108Sa+fhmuc+sWQYwY= diff --git a/zapcore/buffered_write_syncer.go b/zapcore/buffered_write_syncer.go index 9e8e6bdd9..0009b683a 100644 --- a/zapcore/buffered_write_syncer.go +++ b/zapcore/buffered_write_syncer.go @@ -30,13 +30,20 @@ import ( // A BufferedWriteSyncer is a WriteSyncer that can also flush any buffered data // with the ability to change the buffer size, flush interval and Clock. -// The default values are; Size 256kb, FlushInterval 30s. +// BufferedWriteSyncer is safe for concurrent use. You don't need to use +// zapcore.Lock for WriteSyncers with BufferedWriteSyncer. type BufferedWriteSyncer struct { WriteSyncer - Size int + // Size specifies the maximum amount of data the writer will buffer before + // flushing. Defaults to 256 kB. + Size int + // FlushInterval specifies how often the writer should flush data if there + // have been no writes. Defaults to 30 seconds. FlushInterval time.Duration - Clock Clock + // Clock, if specified, provides control of the source of time for the + // writer. Uses the system clock by default. + Clock Clock // unexported fields for state ws WriteSyncer @@ -56,7 +63,7 @@ const ( _defaultFlushInterval = 30 * time.Second ) -func (s *BufferedWriteSyncer) loadConfig() { +func (s *BufferedWriteSyncer) initialize() { s.ws = s.WriteSyncer size := s.Size @@ -74,7 +81,12 @@ func (s *BufferedWriteSyncer) loadConfig() { } s.ticker = s.Clock.NewTicker(flushInterval) - s.writer = bufio.NewWriterSize(s.WriteSyncer, size) + writer := s.WriteSyncer + if w, ok := writer.(*lockedWriteSyncer); ok { + writer = w.ws + } // don't double lock + s.writer = bufio.NewWriterSize(writer, size) + s.stop = make(chan struct{}) s.initialized = true go s.flushLoop() @@ -87,7 +99,7 @@ func (s *BufferedWriteSyncer) Write(bs []byte) (int, error) { defer s.mu.Unlock() if !s.initialized { - s.loadConfig() + s.initialize() } // To avoid partial writes from being flushed, we manually flush the existing buffer if: From 7dedbc081e8e2402716916a2f61d287eb9386b13 Mon Sep 17 00:00:00 2001 From: Moises Vega Date: Fri, 4 Jun 2021 05:35:31 -0700 Subject: [PATCH 62/74] Add test case with lockedWriteSyncer --- go.sum | 8 -------- zapcore/buffered_write_syncer_test.go | 11 +++++++++++ 2 files changed, 11 insertions(+), 8 deletions(-) diff --git a/go.sum b/go.sum index b330071a0..9031a6131 100644 --- a/go.sum +++ b/go.sum @@ -5,7 +5,6 @@ github.com/davecgh/go-spew v1.1.1 h1:vj9j/u1bqnvCEfJOwUhtlOARqs3+rkHYY13jYWTU97c github.com/davecgh/go-spew v1.1.1/go.mod h1:J7Y8YcW2NihsgmVo/mv3lAwl/skON4iLHjSsI+c5H38= github.com/kr/pretty v0.1.0 h1:L/CwN0zerZDmRFUapSPitk6f+Q3+0za1rQkzVuMiMFI= github.com/kr/pretty v0.1.0/go.mod h1:dAy3ld7l9f0ibDNOQOHHMYYIIbhfbHSm3C4ZsoJORNo= -github.com/kr/pty v1.1.1 h1:VkoXIwSboBpnk99O/KFauAEILuNHv5DVFKZMBN/gUgw= github.com/kr/pty v1.1.1/go.mod h1:pFQYn66WHrOpPYNljwOMqo10TkYh1fy3cYio2l3bCsQ= github.com/kr/text v0.1.0 h1:45sCR5RtlFHMR4UwH9sdQ5TC8v0qDQCHnXt+kaKSTVE= github.com/kr/text v0.1.0/go.mod h1:4Jbv+DJW3UT/LiOwJeYQe1efqtUx/iVham/4vfdArNI= @@ -13,7 +12,6 @@ github.com/pkg/errors v0.8.1 h1:iURUrRGxPUNPdy5/HRSm+Yj6okJ6UtLINN0Q9M4+h3I= github.com/pkg/errors v0.8.1/go.mod h1:bwawxfHBFNV+L2hUp1rHADufV3IMtnDRdf1r5NINEl0= github.com/pmezard/go-difflib v1.0.0 h1:4DBwDE0NGyQoBHbLQYPwSUPoCMWR5BEzIk/f1lZbAQM= github.com/pmezard/go-difflib v1.0.0/go.mod h1:iKH77koFhYxTK1pcRnkKkqfTogsbg7gZNVY4sRDYZ/4= -github.com/stretchr/objx v0.1.0 h1:4G4v2dO3VZwixGIRoQ5Lfboy6nUhCyYzaqnIAPPhYs4= github.com/stretchr/objx v0.1.0/go.mod h1:HFkY916IF+rwdDfMAkV7OtwuqBVzrE8GR6GFx+wExME= github.com/stretchr/testify v1.3.0/go.mod h1:M5WIy9Dh21IEIfnGCwXGc5bZfKNJtfHm1UVUgZn+9EI= github.com/stretchr/testify v1.4.0/go.mod h1:j7eGeouHqKxXV5pUuKE4zz7dFj8WfuZ+81PSLYec5m4= @@ -25,23 +23,17 @@ go.uber.org/goleak v1.1.10 h1:z+mqJhf6ss6BSfSM671tgKyZBFPTTJM+HLxnhPC3wu0= go.uber.org/goleak v1.1.10/go.mod h1:8a7PlsEVH3e/a/GLqe5IIrQx6GzcnRmZEufDUTk4A7A= go.uber.org/multierr v1.6.0 h1:y6IPFStTAIT5Ytl7/XYmHvzXQ7S3g/IeZW9hyZ5thw4= go.uber.org/multierr v1.6.0/go.mod h1:cdWPpRnG4AhwMwsgIHip0KRBQjJy5kYEpYjJxpXp9iU= -golang.org/x/crypto v0.0.0-20190308221718-c2843e01d9a2 h1:VklqNMn3ovrHsnt90PveolxSbWFaJdECFbxSq0Mqo2M= golang.org/x/crypto v0.0.0-20190308221718-c2843e01d9a2/go.mod h1:djNgcEr1/C05ACkg1iLfiJU5Ep61QUkGW8qpdssI0+w= golang.org/x/lint v0.0.0-20190930215403-16217165b5de h1:5hukYrvBGR8/eNkX5mdUezrA6JiaEZDtJb9Ei+1LlBs= golang.org/x/lint v0.0.0-20190930215403-16217165b5de/go.mod h1:6SW0HCj/g11FgYtHlgUYUwCkIfeOF89ocIRzGO/8vkc= golang.org/x/net v0.0.0-20190311183353-d8887717615a/go.mod h1:t9HGtf8HONx5eT2rtn7q6eTqICYqUVnKs3thJo3Qplg= -golang.org/x/net v0.0.0-20190620200207-3b0461eec859 h1:R/3boaszxrf1GEUWTVDzSKVwLmSJpwZ1yqXm8j0v2QI= golang.org/x/net v0.0.0-20190620200207-3b0461eec859/go.mod h1:z5CRVTTTmAJ677TzLLGU+0bjPO0LkuOLi4/5GtJWs/s= -golang.org/x/sync v0.0.0-20190423024810-112230192c58 h1:8gQV6CLnAEikrhgkHFbMAEhagSSnXWGV915qUMm9mrU= golang.org/x/sync v0.0.0-20190423024810-112230192c58/go.mod h1:RxMgew5VJxzue5/jJTE5uejpjVlOe/izrB70Jof72aM= -golang.org/x/sys v0.0.0-20190215142949-d0b11bdaac8a h1:1BGLXjeY4akVXGgbC9HugT3Jv3hCI0z56oJR5vAMgBU= golang.org/x/sys v0.0.0-20190215142949-d0b11bdaac8a/go.mod h1:STP8DvDyc/dI5b8T5hshtkjS+E42TnysNCUPdjciGhY= -golang.org/x/text v0.3.0 h1:g61tztE5qeGQ89tm6NTjjM9VPIm088od1l6aSorWRWg= golang.org/x/text v0.3.0/go.mod h1:NqM8EUOU14njkJ3fqMW+pc6Ldnwhi/IjpwHt7yyuwOQ= golang.org/x/tools v0.0.0-20190311212946-11955173bddd/go.mod h1:LCzVGOaR6xXOjkQ3onu1FJEFr0SW1gC7cKk1uF8kGRs= golang.org/x/tools v0.0.0-20191108193012-7d206e10da11 h1:Yq9t9jnGoR+dBuitxdo9l6Q7xh/zOyNnYUtDKaQ3x0E= golang.org/x/tools v0.0.0-20191108193012-7d206e10da11/go.mod h1:b+2E5dAYhXwXZwtnZ6UAqBI28+e2cm9otk0dWdXHAEo= -golang.org/x/xerrors v0.0.0-20190717185122-a985d3407aa7 h1:9zdDQZ7Thm29KFXgAX/+yaf3eVbP7djjWp/dXAppNCc= golang.org/x/xerrors v0.0.0-20190717185122-a985d3407aa7/go.mod h1:I/5z698sn9Ka8TeJc9MKroUUfqBBauWjQqLJ2OPfmY0= gopkg.in/check.v1 v0.0.0-20161208181325-20d25e280405/go.mod h1:Co6ibVJAznAaIkqp8huTwlJQCZ016jof/cbN4VW5Yz0= gopkg.in/check.v1 v1.0.0-20180628173108-788fd7840127 h1:qIbj1fsPNlZgppZ+VLlY7N33q108Sa+fhmuc+sWQYwY= diff --git a/zapcore/buffered_write_syncer_test.go b/zapcore/buffered_write_syncer_test.go index 89ab3af3c..216babf9c 100644 --- a/zapcore/buffered_write_syncer_test.go +++ b/zapcore/buffered_write_syncer_test.go @@ -75,6 +75,17 @@ func TestBufferWriter(t *testing.T) { assert.NoError(t, ws.Close()) }) + t.Run("with lockedWriteSyncer", func(t *testing.T) { + buf := &bytes.Buffer{} + ws := &BufferedWriteSyncer{WriteSyncer: &lockedWriteSyncer{ws: AddSync(buf)}, Size: 5} + + requireWriteWorks(t, ws) + assert.Equal(t, "", buf.String(), "Unexpected log calling a no-op Write method.") + requireWriteWorks(t, ws) + assert.Equal(t, "foo", buf.String(), "Unexpected log string") + assert.NoError(t, ws.Close()) + }) + t.Run("flush error", func(t *testing.T) { ws := &BufferedWriteSyncer{WriteSyncer: &ztest.FailWriter{}, Size: 4} n, err := ws.Write([]byte("foo")) From f8f3a3dae526a7245199cf2c542dd1f49402d096 Mon Sep 17 00:00:00 2001 From: Moises Vega Date: Mon, 7 Jun 2021 18:58:11 -0700 Subject: [PATCH 63/74] Use empty assert.Empty Co-authored-by: Abhinav Gupta --- zapcore/buffered_write_syncer_test.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/zapcore/buffered_write_syncer_test.go b/zapcore/buffered_write_syncer_test.go index 216babf9c..1e28f2d91 100644 --- a/zapcore/buffered_write_syncer_test.go +++ b/zapcore/buffered_write_syncer_test.go @@ -58,7 +58,7 @@ func TestBufferWriter(t *testing.T) { bufsync := &BufferedWriteSyncer{WriteSyncer: AddSync(buf)} ws := &BufferedWriteSyncer{WriteSyncer: bufsync} requireWriteWorks(t, ws) - assert.Equal(t, "", buf.String(), "Unexpected log calling a no-op Write method.") + assert.Empty(t, buf.String(), "Unexpected log calling a no-op Write method.") assert.NoError(t, ws.Close()) assert.NoError(t, bufsync.Close()) assert.Equal(t, "foo", buf.String(), "Unexpected log string") From acfd294a6149ee0675a4bba707d9dc6df1042e83 Mon Sep 17 00:00:00 2001 From: Moises Vega Date: Mon, 7 Jun 2021 19:03:20 -0700 Subject: [PATCH 64/74] Use zapcore.Lock for BufferedWriteSyncer tests Co-authored-by: Abhinav Gupta --- zapcore/buffered_write_syncer_test.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/zapcore/buffered_write_syncer_test.go b/zapcore/buffered_write_syncer_test.go index 1e28f2d91..bd96a45a9 100644 --- a/zapcore/buffered_write_syncer_test.go +++ b/zapcore/buffered_write_syncer_test.go @@ -77,7 +77,7 @@ func TestBufferWriter(t *testing.T) { t.Run("with lockedWriteSyncer", func(t *testing.T) { buf := &bytes.Buffer{} - ws := &BufferedWriteSyncer{WriteSyncer: &lockedWriteSyncer{ws: AddSync(buf)}, Size: 5} + ws := &BufferedWriteSyncer{WriteSyncer: Lock(AddSync(buf)), Size: 5} requireWriteWorks(t, ws) assert.Equal(t, "", buf.String(), "Unexpected log calling a no-op Write method.") From f32b7962dab92a9b9aa8a8f24cc17a0f210db2e5 Mon Sep 17 00:00:00 2001 From: Moises Vega Date: Mon, 7 Jun 2021 19:28:15 -0700 Subject: [PATCH 65/74] Add asserts on close/remove in benchmark buffered write and add test case for wrap twice sync --- go.sum | 8 ++++++++ zapcore/buffered_write_syncer_bench_test.go | 8 ++++++-- zapcore/buffered_write_syncer_test.go | 2 ++ 3 files changed, 16 insertions(+), 2 deletions(-) diff --git a/go.sum b/go.sum index 9031a6131..b330071a0 100644 --- a/go.sum +++ b/go.sum @@ -5,6 +5,7 @@ github.com/davecgh/go-spew v1.1.1 h1:vj9j/u1bqnvCEfJOwUhtlOARqs3+rkHYY13jYWTU97c github.com/davecgh/go-spew v1.1.1/go.mod h1:J7Y8YcW2NihsgmVo/mv3lAwl/skON4iLHjSsI+c5H38= github.com/kr/pretty v0.1.0 h1:L/CwN0zerZDmRFUapSPitk6f+Q3+0za1rQkzVuMiMFI= github.com/kr/pretty v0.1.0/go.mod h1:dAy3ld7l9f0ibDNOQOHHMYYIIbhfbHSm3C4ZsoJORNo= +github.com/kr/pty v1.1.1 h1:VkoXIwSboBpnk99O/KFauAEILuNHv5DVFKZMBN/gUgw= github.com/kr/pty v1.1.1/go.mod h1:pFQYn66WHrOpPYNljwOMqo10TkYh1fy3cYio2l3bCsQ= github.com/kr/text v0.1.0 h1:45sCR5RtlFHMR4UwH9sdQ5TC8v0qDQCHnXt+kaKSTVE= github.com/kr/text v0.1.0/go.mod h1:4Jbv+DJW3UT/LiOwJeYQe1efqtUx/iVham/4vfdArNI= @@ -12,6 +13,7 @@ github.com/pkg/errors v0.8.1 h1:iURUrRGxPUNPdy5/HRSm+Yj6okJ6UtLINN0Q9M4+h3I= github.com/pkg/errors v0.8.1/go.mod h1:bwawxfHBFNV+L2hUp1rHADufV3IMtnDRdf1r5NINEl0= github.com/pmezard/go-difflib v1.0.0 h1:4DBwDE0NGyQoBHbLQYPwSUPoCMWR5BEzIk/f1lZbAQM= github.com/pmezard/go-difflib v1.0.0/go.mod h1:iKH77koFhYxTK1pcRnkKkqfTogsbg7gZNVY4sRDYZ/4= +github.com/stretchr/objx v0.1.0 h1:4G4v2dO3VZwixGIRoQ5Lfboy6nUhCyYzaqnIAPPhYs4= github.com/stretchr/objx v0.1.0/go.mod h1:HFkY916IF+rwdDfMAkV7OtwuqBVzrE8GR6GFx+wExME= github.com/stretchr/testify v1.3.0/go.mod h1:M5WIy9Dh21IEIfnGCwXGc5bZfKNJtfHm1UVUgZn+9EI= github.com/stretchr/testify v1.4.0/go.mod h1:j7eGeouHqKxXV5pUuKE4zz7dFj8WfuZ+81PSLYec5m4= @@ -23,17 +25,23 @@ go.uber.org/goleak v1.1.10 h1:z+mqJhf6ss6BSfSM671tgKyZBFPTTJM+HLxnhPC3wu0= go.uber.org/goleak v1.1.10/go.mod h1:8a7PlsEVH3e/a/GLqe5IIrQx6GzcnRmZEufDUTk4A7A= go.uber.org/multierr v1.6.0 h1:y6IPFStTAIT5Ytl7/XYmHvzXQ7S3g/IeZW9hyZ5thw4= go.uber.org/multierr v1.6.0/go.mod h1:cdWPpRnG4AhwMwsgIHip0KRBQjJy5kYEpYjJxpXp9iU= +golang.org/x/crypto v0.0.0-20190308221718-c2843e01d9a2 h1:VklqNMn3ovrHsnt90PveolxSbWFaJdECFbxSq0Mqo2M= golang.org/x/crypto v0.0.0-20190308221718-c2843e01d9a2/go.mod h1:djNgcEr1/C05ACkg1iLfiJU5Ep61QUkGW8qpdssI0+w= golang.org/x/lint v0.0.0-20190930215403-16217165b5de h1:5hukYrvBGR8/eNkX5mdUezrA6JiaEZDtJb9Ei+1LlBs= golang.org/x/lint v0.0.0-20190930215403-16217165b5de/go.mod h1:6SW0HCj/g11FgYtHlgUYUwCkIfeOF89ocIRzGO/8vkc= golang.org/x/net v0.0.0-20190311183353-d8887717615a/go.mod h1:t9HGtf8HONx5eT2rtn7q6eTqICYqUVnKs3thJo3Qplg= +golang.org/x/net v0.0.0-20190620200207-3b0461eec859 h1:R/3boaszxrf1GEUWTVDzSKVwLmSJpwZ1yqXm8j0v2QI= golang.org/x/net v0.0.0-20190620200207-3b0461eec859/go.mod h1:z5CRVTTTmAJ677TzLLGU+0bjPO0LkuOLi4/5GtJWs/s= +golang.org/x/sync v0.0.0-20190423024810-112230192c58 h1:8gQV6CLnAEikrhgkHFbMAEhagSSnXWGV915qUMm9mrU= golang.org/x/sync v0.0.0-20190423024810-112230192c58/go.mod h1:RxMgew5VJxzue5/jJTE5uejpjVlOe/izrB70Jof72aM= +golang.org/x/sys v0.0.0-20190215142949-d0b11bdaac8a h1:1BGLXjeY4akVXGgbC9HugT3Jv3hCI0z56oJR5vAMgBU= golang.org/x/sys v0.0.0-20190215142949-d0b11bdaac8a/go.mod h1:STP8DvDyc/dI5b8T5hshtkjS+E42TnysNCUPdjciGhY= +golang.org/x/text v0.3.0 h1:g61tztE5qeGQ89tm6NTjjM9VPIm088od1l6aSorWRWg= golang.org/x/text v0.3.0/go.mod h1:NqM8EUOU14njkJ3fqMW+pc6Ldnwhi/IjpwHt7yyuwOQ= golang.org/x/tools v0.0.0-20190311212946-11955173bddd/go.mod h1:LCzVGOaR6xXOjkQ3onu1FJEFr0SW1gC7cKk1uF8kGRs= golang.org/x/tools v0.0.0-20191108193012-7d206e10da11 h1:Yq9t9jnGoR+dBuitxdo9l6Q7xh/zOyNnYUtDKaQ3x0E= golang.org/x/tools v0.0.0-20191108193012-7d206e10da11/go.mod h1:b+2E5dAYhXwXZwtnZ6UAqBI28+e2cm9otk0dWdXHAEo= +golang.org/x/xerrors v0.0.0-20190717185122-a985d3407aa7 h1:9zdDQZ7Thm29KFXgAX/+yaf3eVbP7djjWp/dXAppNCc= golang.org/x/xerrors v0.0.0-20190717185122-a985d3407aa7/go.mod h1:I/5z698sn9Ka8TeJc9MKroUUfqBBauWjQqLJ2OPfmY0= gopkg.in/check.v1 v0.0.0-20161208181325-20d25e280405/go.mod h1:Co6ibVJAznAaIkqp8huTwlJQCZ016jof/cbN4VW5Yz0= gopkg.in/check.v1 v1.0.0-20180628173108-788fd7840127 h1:qIbj1fsPNlZgppZ+VLlY7N33q108Sa+fhmuc+sWQYwY= diff --git a/zapcore/buffered_write_syncer_bench_test.go b/zapcore/buffered_write_syncer_bench_test.go index 9b5a45e6f..c67717678 100644 --- a/zapcore/buffered_write_syncer_bench_test.go +++ b/zapcore/buffered_write_syncer_bench_test.go @@ -25,6 +25,7 @@ import ( "os" "testing" + "github.com/stretchr/testify/assert" "github.com/stretchr/testify/require" ) @@ -32,8 +33,11 @@ func BenchmarkBufferedWriteSyncer(b *testing.B) { b.Run("write file with buffer", func(b *testing.B) { file, err := ioutil.TempFile("", "log") require.NoError(b, err) - defer file.Close() - defer os.Remove(file.Name()) + + defer func() { + assert.NoError(b, file.Close()) + assert.NoError(b, os.Remove(file.Name())) + }() w := &BufferedWriteSyncer{ WriteSyncer: AddSync(file), diff --git a/zapcore/buffered_write_syncer_test.go b/zapcore/buffered_write_syncer_test.go index bd96a45a9..a998478bb 100644 --- a/zapcore/buffered_write_syncer_test.go +++ b/zapcore/buffered_write_syncer_test.go @@ -59,6 +59,8 @@ func TestBufferWriter(t *testing.T) { ws := &BufferedWriteSyncer{WriteSyncer: bufsync} requireWriteWorks(t, ws) assert.Empty(t, buf.String(), "Unexpected log calling a no-op Write method.") + require.NoError(t, ws.Sync()) + assert.Equal(t, "foo", buf.String()) assert.NoError(t, ws.Close()) assert.NoError(t, bufsync.Close()) assert.Equal(t, "foo", buf.String(), "Unexpected log string") From 17cdba55bcf8abb727a0101b1eb791c737de55bf Mon Sep 17 00:00:00 2001 From: Abhinav Gupta Date: Tue, 8 Jun 2021 13:09:04 -0700 Subject: [PATCH 66/74] Take a pass over the BufferedWriteSyncer docs --- zapcore/buffered_write_syncer.go | 27 ++++++++++++++++++++------- 1 file changed, 20 insertions(+), 7 deletions(-) diff --git a/zapcore/buffered_write_syncer.go b/zapcore/buffered_write_syncer.go index 0009b683a..6e26c6d92 100644 --- a/zapcore/buffered_write_syncer.go +++ b/zapcore/buffered_write_syncer.go @@ -28,21 +28,34 @@ import ( "go.uber.org/multierr" ) -// A BufferedWriteSyncer is a WriteSyncer that can also flush any buffered data -// with the ability to change the buffer size, flush interval and Clock. +// A BufferedWriteSyncer is a WriteSyncer that buffers writes in-memory before +// flushing them to a wrapped WriteSyncer after reaching some limit, or at some +// fixed interval--whichever comes first. +// // BufferedWriteSyncer is safe for concurrent use. You don't need to use // zapcore.Lock for WriteSyncers with BufferedWriteSyncer. type BufferedWriteSyncer struct { + // WriteSyncer is the WriteSyncer wrapped by BufferedWriteSyncer. + // + // This field is required. WriteSyncer - // Size specifies the maximum amount of data the writer will buffer before - // flushing. Defaults to 256 kB. + // Size specifies the maximum amount of data the writer will buffered + // before flushing. + // + // Defaults to 256 kB if unspecified. Size int - // FlushInterval specifies how often the writer should flush data if there - // have been no writes. Defaults to 30 seconds. + + // FlushInterval specifies how often the writer should flush data if + // there have been no writes. + // + // Defaults to 30 seconds if unspecified. FlushInterval time.Duration + // Clock, if specified, provides control of the source of time for the - // writer. Uses the system clock by default. + // writer. + // + // Defaults to the system clock. Clock Clock // unexported fields for state From 97ae2a6db38e5809bef9d49c84b69745f9201725 Mon Sep 17 00:00:00 2001 From: Abhinav Gupta Date: Tue, 8 Jun 2021 13:09:25 -0700 Subject: [PATCH 67/74] Move consts to the top of the file --- zapcore/buffered_write_syncer.go | 18 +++++++++--------- 1 file changed, 9 insertions(+), 9 deletions(-) diff --git a/zapcore/buffered_write_syncer.go b/zapcore/buffered_write_syncer.go index 6e26c6d92..37b142b37 100644 --- a/zapcore/buffered_write_syncer.go +++ b/zapcore/buffered_write_syncer.go @@ -28,6 +28,15 @@ import ( "go.uber.org/multierr" ) +const ( + // _defaultBufferSize specifies the default size used by Buffer. + _defaultBufferSize = 256 * 1024 // 256 kB + + // _defaultFlushInterval specifies the default flush interval for + // Buffer. + _defaultFlushInterval = 30 * time.Second +) + // A BufferedWriteSyncer is a WriteSyncer that buffers writes in-memory before // flushing them to a wrapped WriteSyncer after reaching some limit, or at some // fixed interval--whichever comes first. @@ -67,15 +76,6 @@ type BufferedWriteSyncer struct { initialized bool } -const ( - // _defaultBufferSize specifies the default size used by Buffer. - _defaultBufferSize = 256 * 1024 // 256 kB - - // _defaultFlushInterval specifies the default flush interval for - // Buffer. - _defaultFlushInterval = 30 * time.Second -) - func (s *BufferedWriteSyncer) initialize() { s.ws = s.WriteSyncer From b58819e4b6954e36badfcfc74bf7a2793f39298b Mon Sep 17 00:00:00 2001 From: Abhinav Gupta Date: Tue, 8 Jun 2021 13:16:15 -0700 Subject: [PATCH 68/74] Rename Close to Stop --- zapcore/buffered_write_syncer.go | 8 ++++---- zapcore/buffered_write_syncer_bench_test.go | 2 +- zapcore/buffered_write_syncer_test.go | 16 ++++++++-------- zapcore/write_syncer_bench_test.go | 2 +- 4 files changed, 14 insertions(+), 14 deletions(-) diff --git a/zapcore/buffered_write_syncer.go b/zapcore/buffered_write_syncer.go index 37b142b37..fba5403e4 100644 --- a/zapcore/buffered_write_syncer.go +++ b/zapcore/buffered_write_syncer.go @@ -135,7 +135,7 @@ func (s *BufferedWriteSyncer) Sync() error { return multierr.Append(s.writer.Flush(), s.ws.Sync()) } -// flushLoop flushes the buffer at the configured interval until Close is +// flushLoop flushes the buffer at the configured interval until Stop is // called. func (s *BufferedWriteSyncer) flushLoop() { for { @@ -151,9 +151,9 @@ func (s *BufferedWriteSyncer) flushLoop() { } } -// Close closes the buffer, cleans up background goroutines, and flushes -// remaining, unwritten data. This will not close the underlying WriteSyncer. -func (s *BufferedWriteSyncer) Close() error { +// Stop closes the buffer, cleans up background goroutines, and flushes +// remaining unwritten data. +func (s *BufferedWriteSyncer) Stop() error { s.ticker.Stop() close(s.stop) return s.Sync() diff --git a/zapcore/buffered_write_syncer_bench_test.go b/zapcore/buffered_write_syncer_bench_test.go index c67717678..a6ff85e0d 100644 --- a/zapcore/buffered_write_syncer_bench_test.go +++ b/zapcore/buffered_write_syncer_bench_test.go @@ -42,7 +42,7 @@ func BenchmarkBufferedWriteSyncer(b *testing.B) { w := &BufferedWriteSyncer{ WriteSyncer: AddSync(file), } - defer w.Close() + defer w.Stop() b.ResetTimer() b.RunParallel(func(pb *testing.PB) { for pb.Next() { diff --git a/zapcore/buffered_write_syncer_test.go b/zapcore/buffered_write_syncer_test.go index a998478bb..511e1a80d 100644 --- a/zapcore/buffered_write_syncer_test.go +++ b/zapcore/buffered_write_syncer_test.go @@ -41,7 +41,7 @@ func TestBufferWriter(t *testing.T) { assert.Empty(t, buf.String(), "Unexpected log calling a no-op Write method.") assert.NoError(t, ws.Sync(), "Unexpected error calling a no-op Sync method.") assert.Equal(t, "foo", buf.String(), "Unexpected log string") - assert.NoError(t, ws.Close()) + assert.NoError(t, ws.Stop()) }) t.Run("close", func(t *testing.T) { @@ -49,7 +49,7 @@ func TestBufferWriter(t *testing.T) { ws := &BufferedWriteSyncer{WriteSyncer: AddSync(buf)} requireWriteWorks(t, ws) assert.Empty(t, buf.String(), "Unexpected log calling a no-op Write method.") - assert.NoError(t, ws.Close()) + assert.NoError(t, ws.Stop()) assert.Equal(t, "foo", buf.String(), "Unexpected log string") }) @@ -61,8 +61,8 @@ func TestBufferWriter(t *testing.T) { assert.Empty(t, buf.String(), "Unexpected log calling a no-op Write method.") require.NoError(t, ws.Sync()) assert.Equal(t, "foo", buf.String()) - assert.NoError(t, ws.Close()) - assert.NoError(t, bufsync.Close()) + assert.NoError(t, ws.Stop()) + assert.NoError(t, bufsync.Stop()) assert.Equal(t, "foo", buf.String(), "Unexpected log string") }) @@ -74,7 +74,7 @@ func TestBufferWriter(t *testing.T) { assert.Equal(t, "", buf.String(), "Unexpected log calling a no-op Write method.") requireWriteWorks(t, ws) assert.Equal(t, "foo", buf.String(), "Unexpected log string") - assert.NoError(t, ws.Close()) + assert.NoError(t, ws.Stop()) }) t.Run("with lockedWriteSyncer", func(t *testing.T) { @@ -85,7 +85,7 @@ func TestBufferWriter(t *testing.T) { assert.Equal(t, "", buf.String(), "Unexpected log calling a no-op Write method.") requireWriteWorks(t, ws) assert.Equal(t, "foo", buf.String(), "Unexpected log string") - assert.NoError(t, ws.Close()) + assert.NoError(t, ws.Stop()) }) t.Run("flush error", func(t *testing.T) { @@ -94,7 +94,7 @@ func TestBufferWriter(t *testing.T) { require.NoError(t, err, "Unexpected error writing to WriteSyncer.") require.Equal(t, 3, n, "Wrote an unexpected number of bytes.") ws.Write([]byte("foo")) - assert.Error(t, ws.Close(), "Expected close to fail.") + assert.Error(t, ws.Stop(), "Expected close to fail.") }) t.Run("flush timer", func(t *testing.T) { @@ -114,6 +114,6 @@ func TestBufferWriter(t *testing.T) { requireWriteWorks(t, ws) clock.Add(10 * time.Microsecond) assert.Equal(t, "foofoo", buf.String(), "Unexpected log string") - assert.NoError(t, ws.Close()) + assert.NoError(t, ws.Stop()) }) } diff --git a/zapcore/write_syncer_bench_test.go b/zapcore/write_syncer_bench_test.go index c3bcafe54..9b3492e83 100644 --- a/zapcore/write_syncer_bench_test.go +++ b/zapcore/write_syncer_bench_test.go @@ -65,7 +65,7 @@ func BenchmarkMultiWriteSyncer(b *testing.B) { &ztest.Discarder{}, ), } - defer w.Close() + defer w.Stop() b.ResetTimer() b.RunParallel(func(pb *testing.PB) { for pb.Next() { From afe558a89a3be7c16eb4c93d373926dce7c4afc0 Mon Sep 17 00:00:00 2001 From: Abhinav Gupta Date: Tue, 8 Jun 2021 13:22:22 -0700 Subject: [PATCH 69/74] Stop: Wait until flushLoop stops --- zapcore/buffered_write_syncer.go | 13 +++++++++---- 1 file changed, 9 insertions(+), 4 deletions(-) diff --git a/zapcore/buffered_write_syncer.go b/zapcore/buffered_write_syncer.go index fba5403e4..fe2667339 100644 --- a/zapcore/buffered_write_syncer.go +++ b/zapcore/buffered_write_syncer.go @@ -68,12 +68,13 @@ type BufferedWriteSyncer struct { Clock Clock // unexported fields for state - ws WriteSyncer mu sync.Mutex + initialized bool // whether initialize() has run + ws WriteSyncer writer *bufio.Writer ticker *time.Ticker - stop chan struct{} - initialized bool + stop chan struct{} // closed when flushLoop should stop + done chan struct{} // closed when flushLoop has stopped } func (s *BufferedWriteSyncer) initialize() { @@ -101,6 +102,7 @@ func (s *BufferedWriteSyncer) initialize() { s.writer = bufio.NewWriterSize(writer, size) s.stop = make(chan struct{}) + s.done = make(chan struct{}) s.initialized = true go s.flushLoop() } @@ -138,6 +140,8 @@ func (s *BufferedWriteSyncer) Sync() error { // flushLoop flushes the buffer at the configured interval until Stop is // called. func (s *BufferedWriteSyncer) flushLoop() { + defer close(s.done) + for { select { case <-s.ticker.C: @@ -155,6 +159,7 @@ func (s *BufferedWriteSyncer) flushLoop() { // remaining unwritten data. func (s *BufferedWriteSyncer) Stop() error { s.ticker.Stop() - close(s.stop) + close(s.stop) // tell flushLoop to stop + <-s.done // and wait until it has return s.Sync() } From 49444fc8a61e05f689870f9f14cf964fde87c8fd Mon Sep 17 00:00:00 2001 From: Abhinav Gupta Date: Tue, 8 Jun 2021 13:35:53 -0700 Subject: [PATCH 70/74] fixup! Rename Close to Stop --- zapcore/buffered_write_syncer_test.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/zapcore/buffered_write_syncer_test.go b/zapcore/buffered_write_syncer_test.go index 511e1a80d..cf7d67bf9 100644 --- a/zapcore/buffered_write_syncer_test.go +++ b/zapcore/buffered_write_syncer_test.go @@ -44,7 +44,7 @@ func TestBufferWriter(t *testing.T) { assert.NoError(t, ws.Stop()) }) - t.Run("close", func(t *testing.T) { + t.Run("stop", func(t *testing.T) { buf := &bytes.Buffer{} ws := &BufferedWriteSyncer{WriteSyncer: AddSync(buf)} requireWriteWorks(t, ws) From 43d9b548440670b02f9785e054830fe64f9956e8 Mon Sep 17 00:00:00 2001 From: Abhinav Gupta Date: Tue, 8 Jun 2021 13:36:00 -0700 Subject: [PATCH 71/74] Stop/Sync: handle uninitialized calls These methods should not panic if called without `Write` first (which is what starts the background goroutine). --- zapcore/buffered_write_syncer.go | 23 ++++++++++++++++++++--- zapcore/buffered_write_syncer_test.go | 14 +++++++++++++- 2 files changed, 33 insertions(+), 4 deletions(-) diff --git a/zapcore/buffered_write_syncer.go b/zapcore/buffered_write_syncer.go index fe2667339..78b58d7e5 100644 --- a/zapcore/buffered_write_syncer.go +++ b/zapcore/buffered_write_syncer.go @@ -134,6 +134,10 @@ func (s *BufferedWriteSyncer) Sync() error { s.mu.Lock() defer s.mu.Unlock() + if !s.initialized { + return nil + } + return multierr.Append(s.writer.Flush(), s.ws.Sync()) } @@ -157,9 +161,22 @@ func (s *BufferedWriteSyncer) flushLoop() { // Stop closes the buffer, cleans up background goroutines, and flushes // remaining unwritten data. +// +// This must be called exactly once per BufferedWriteSyncer. func (s *BufferedWriteSyncer) Stop() error { - s.ticker.Stop() - close(s.stop) // tell flushLoop to stop - <-s.done // and wait until it has + // Critical section. + func() { + s.mu.Lock() + defer s.mu.Unlock() + + if !s.initialized { + return + } + + s.ticker.Stop() + close(s.stop) // tell flushLoop to stop + <-s.done // and wait until it has + }() + return s.Sync() } diff --git a/zapcore/buffered_write_syncer_test.go b/zapcore/buffered_write_syncer_test.go index cf7d67bf9..7f5ac50ea 100644 --- a/zapcore/buffered_write_syncer_test.go +++ b/zapcore/buffered_write_syncer_test.go @@ -94,7 +94,7 @@ func TestBufferWriter(t *testing.T) { require.NoError(t, err, "Unexpected error writing to WriteSyncer.") require.Equal(t, 3, n, "Wrote an unexpected number of bytes.") ws.Write([]byte("foo")) - assert.Error(t, ws.Stop(), "Expected close to fail.") + assert.Error(t, ws.Stop(), "Expected stop to fail.") }) t.Run("flush timer", func(t *testing.T) { @@ -117,3 +117,15 @@ func TestBufferWriter(t *testing.T) { assert.NoError(t, ws.Stop()) }) } + +func TestBufferWriterWithoutStart(t *testing.T) { + t.Run("stop", func(t *testing.T) { + ws := &BufferedWriteSyncer{WriteSyncer: AddSync(new(bytes.Buffer))} + assert.NoError(t, ws.Stop(), "Stop must not fail") + }) + + t.Run("Sync", func(t *testing.T) { + ws := &BufferedWriteSyncer{WriteSyncer: AddSync(new(bytes.Buffer))} + assert.NoError(t, ws.Sync(), "Sync must not fail") + }) +} From 7c7fb4d057c556d41e6b25bab96a3e6b3626bdc7 Mon Sep 17 00:00:00 2001 From: Abhinav Gupta Date: Tue, 8 Jun 2021 13:38:19 -0700 Subject: [PATCH 72/74] Rename WriteSyncer field to WS Writing `BufferedWriteSyncer{WriteSyncer: ...}` is a mouthful. Let's go for something short and obvious like: ``` package io type LimitedReader struct { R Reader // underlying reader N int64 // max bytes remaining } ``` --- zapcore/buffered_write_syncer.go | 9 +++++---- zapcore/buffered_write_syncer_bench_test.go | 2 +- zapcore/buffered_write_syncer_test.go | 20 ++++++++++---------- zapcore/write_syncer_bench_test.go | 2 +- 4 files changed, 17 insertions(+), 16 deletions(-) diff --git a/zapcore/buffered_write_syncer.go b/zapcore/buffered_write_syncer.go index 78b58d7e5..bb4f319e7 100644 --- a/zapcore/buffered_write_syncer.go +++ b/zapcore/buffered_write_syncer.go @@ -44,10 +44,11 @@ const ( // BufferedWriteSyncer is safe for concurrent use. You don't need to use // zapcore.Lock for WriteSyncers with BufferedWriteSyncer. type BufferedWriteSyncer struct { - // WriteSyncer is the WriteSyncer wrapped by BufferedWriteSyncer. + // WS is the WriteSyncer around which BufferedWriteSyncer will buffer + // writes. // // This field is required. - WriteSyncer + WS WriteSyncer // Size specifies the maximum amount of data the writer will buffered // before flushing. @@ -78,7 +79,7 @@ type BufferedWriteSyncer struct { } func (s *BufferedWriteSyncer) initialize() { - s.ws = s.WriteSyncer + s.ws = s.WS size := s.Size if size == 0 { @@ -95,7 +96,7 @@ func (s *BufferedWriteSyncer) initialize() { } s.ticker = s.Clock.NewTicker(flushInterval) - writer := s.WriteSyncer + writer := s.WS if w, ok := writer.(*lockedWriteSyncer); ok { writer = w.ws } // don't double lock diff --git a/zapcore/buffered_write_syncer_bench_test.go b/zapcore/buffered_write_syncer_bench_test.go index a6ff85e0d..dd1583c14 100644 --- a/zapcore/buffered_write_syncer_bench_test.go +++ b/zapcore/buffered_write_syncer_bench_test.go @@ -40,7 +40,7 @@ func BenchmarkBufferedWriteSyncer(b *testing.B) { }() w := &BufferedWriteSyncer{ - WriteSyncer: AddSync(file), + WS: AddSync(file), } defer w.Stop() b.ResetTimer() diff --git a/zapcore/buffered_write_syncer_test.go b/zapcore/buffered_write_syncer_test.go index 7f5ac50ea..9c28076bb 100644 --- a/zapcore/buffered_write_syncer_test.go +++ b/zapcore/buffered_write_syncer_test.go @@ -35,7 +35,7 @@ func TestBufferWriter(t *testing.T) { // with a no-op Sync. t.Run("sync", func(t *testing.T) { buf := &bytes.Buffer{} - ws := &BufferedWriteSyncer{WriteSyncer: AddSync(buf)} + ws := &BufferedWriteSyncer{WS: AddSync(buf)} requireWriteWorks(t, ws) assert.Empty(t, buf.String(), "Unexpected log calling a no-op Write method.") @@ -46,7 +46,7 @@ func TestBufferWriter(t *testing.T) { t.Run("stop", func(t *testing.T) { buf := &bytes.Buffer{} - ws := &BufferedWriteSyncer{WriteSyncer: AddSync(buf)} + ws := &BufferedWriteSyncer{WS: AddSync(buf)} requireWriteWorks(t, ws) assert.Empty(t, buf.String(), "Unexpected log calling a no-op Write method.") assert.NoError(t, ws.Stop()) @@ -55,8 +55,8 @@ func TestBufferWriter(t *testing.T) { t.Run("wrap twice", func(t *testing.T) { buf := &bytes.Buffer{} - bufsync := &BufferedWriteSyncer{WriteSyncer: AddSync(buf)} - ws := &BufferedWriteSyncer{WriteSyncer: bufsync} + bufsync := &BufferedWriteSyncer{WS: AddSync(buf)} + ws := &BufferedWriteSyncer{WS: bufsync} requireWriteWorks(t, ws) assert.Empty(t, buf.String(), "Unexpected log calling a no-op Write method.") require.NoError(t, ws.Sync()) @@ -68,7 +68,7 @@ func TestBufferWriter(t *testing.T) { t.Run("small buffer", func(t *testing.T) { buf := &bytes.Buffer{} - ws := &BufferedWriteSyncer{WriteSyncer: AddSync(buf), Size: 5} + ws := &BufferedWriteSyncer{WS: AddSync(buf), Size: 5} requireWriteWorks(t, ws) assert.Equal(t, "", buf.String(), "Unexpected log calling a no-op Write method.") @@ -79,7 +79,7 @@ func TestBufferWriter(t *testing.T) { t.Run("with lockedWriteSyncer", func(t *testing.T) { buf := &bytes.Buffer{} - ws := &BufferedWriteSyncer{WriteSyncer: Lock(AddSync(buf)), Size: 5} + ws := &BufferedWriteSyncer{WS: Lock(AddSync(buf)), Size: 5} requireWriteWorks(t, ws) assert.Equal(t, "", buf.String(), "Unexpected log calling a no-op Write method.") @@ -89,7 +89,7 @@ func TestBufferWriter(t *testing.T) { }) t.Run("flush error", func(t *testing.T) { - ws := &BufferedWriteSyncer{WriteSyncer: &ztest.FailWriter{}, Size: 4} + ws := &BufferedWriteSyncer{WS: &ztest.FailWriter{}, Size: 4} n, err := ws.Write([]byte("foo")) require.NoError(t, err, "Unexpected error writing to WriteSyncer.") require.Equal(t, 3, n, "Wrote an unexpected number of bytes.") @@ -101,7 +101,7 @@ func TestBufferWriter(t *testing.T) { buf := &bytes.Buffer{} clock := newControlledClock() ws := &BufferedWriteSyncer{ - WriteSyncer: AddSync(buf), + WS: AddSync(buf), Size: 6, FlushInterval: time.Microsecond, Clock: clock, @@ -120,12 +120,12 @@ func TestBufferWriter(t *testing.T) { func TestBufferWriterWithoutStart(t *testing.T) { t.Run("stop", func(t *testing.T) { - ws := &BufferedWriteSyncer{WriteSyncer: AddSync(new(bytes.Buffer))} + ws := &BufferedWriteSyncer{WS: AddSync(new(bytes.Buffer))} assert.NoError(t, ws.Stop(), "Stop must not fail") }) t.Run("Sync", func(t *testing.T) { - ws := &BufferedWriteSyncer{WriteSyncer: AddSync(new(bytes.Buffer))} + ws := &BufferedWriteSyncer{WS: AddSync(new(bytes.Buffer))} assert.NoError(t, ws.Sync(), "Sync must not fail") }) } diff --git a/zapcore/write_syncer_bench_test.go b/zapcore/write_syncer_bench_test.go index 9b3492e83..0793805d5 100644 --- a/zapcore/write_syncer_bench_test.go +++ b/zapcore/write_syncer_bench_test.go @@ -58,7 +58,7 @@ func BenchmarkMultiWriteSyncer(b *testing.B) { }) b.Run("4 discarder with buffer", func(b *testing.B) { w := &BufferedWriteSyncer{ - WriteSyncer: NewMultiWriteSyncer( + WS: NewMultiWriteSyncer( &ztest.Discarder{}, &ztest.Discarder{}, &ztest.Discarder{}, From f30d68b9251d1dff7fa227c4dcac45be80155563 Mon Sep 17 00:00:00 2001 From: Abhinav Gupta Date: Tue, 8 Jun 2021 13:46:20 -0700 Subject: [PATCH 73/74] Overwrite WS instead of maintaining to WriteSyncer fields --- zapcore/buffered_write_syncer.go | 28 ++++++++++++++++------------ 1 file changed, 16 insertions(+), 12 deletions(-) diff --git a/zapcore/buffered_write_syncer.go b/zapcore/buffered_write_syncer.go index bb4f319e7..3ac5e676d 100644 --- a/zapcore/buffered_write_syncer.go +++ b/zapcore/buffered_write_syncer.go @@ -45,7 +45,8 @@ const ( // zapcore.Lock for WriteSyncers with BufferedWriteSyncer. type BufferedWriteSyncer struct { // WS is the WriteSyncer around which BufferedWriteSyncer will buffer - // writes. + // writes. The provided WriteSyncer must not be used directly once + // wrapped in a BufferedWriteSyncer. // // This field is required. WS WriteSyncer @@ -71,7 +72,6 @@ type BufferedWriteSyncer struct { // unexported fields for state mu sync.Mutex initialized bool // whether initialize() has run - ws WriteSyncer writer *bufio.Writer ticker *time.Ticker stop chan struct{} // closed when flushLoop should stop @@ -79,8 +79,6 @@ type BufferedWriteSyncer struct { } func (s *BufferedWriteSyncer) initialize() { - s.ws = s.WS - size := s.Size if size == 0 { size = _defaultBufferSize @@ -96,11 +94,15 @@ func (s *BufferedWriteSyncer) initialize() { } s.ticker = s.Clock.NewTicker(flushInterval) - writer := s.WS - if w, ok := writer.(*lockedWriteSyncer); ok { - writer = w.ws - } // don't double lock - s.writer = bufio.NewWriterSize(writer, size) + // Unpack to the underlying WriteSyncer if we have a lockedWriteSyncer + // to avoid double-locking. Note that there's a risk here if the user + // tries to use the Lock-ed WriteSyncer directly in addition to using + // it with BufferedWriteSyncer, so we declare that the wrapped + // WriteSyncer is only ours to use once wrapped. + if w, ok := s.WS.(*lockedWriteSyncer); ok { + s.WS = w.ws + } + s.writer = bufio.NewWriterSize(s.WS, size) s.stop = make(chan struct{}) s.done = make(chan struct{}) @@ -135,11 +137,13 @@ func (s *BufferedWriteSyncer) Sync() error { s.mu.Lock() defer s.mu.Unlock() - if !s.initialized { - return nil + var err error + if w := s.writer; w != nil { + // w is nil if we haven't yet been initialized. + err = w.Flush() } - return multierr.Append(s.writer.Flush(), s.ws.Sync()) + return multierr.Append(err, s.WS.Sync()) } // flushLoop flushes the buffer at the configured interval until Stop is From ac5b8ada58b8d13431d12145b1bc1204f5521718 Mon Sep 17 00:00:00 2001 From: Abhinav Gupta Date: Tue, 8 Jun 2021 16:32:46 -0700 Subject: [PATCH 74/74] Drop Lock unpacking, check initialized, fix docs --- zapcore/buffered_write_syncer.go | 21 +++++---------------- 1 file changed, 5 insertions(+), 16 deletions(-) diff --git a/zapcore/buffered_write_syncer.go b/zapcore/buffered_write_syncer.go index 3ac5e676d..f08ca7e81 100644 --- a/zapcore/buffered_write_syncer.go +++ b/zapcore/buffered_write_syncer.go @@ -45,8 +45,7 @@ const ( // zapcore.Lock for WriteSyncers with BufferedWriteSyncer. type BufferedWriteSyncer struct { // WS is the WriteSyncer around which BufferedWriteSyncer will buffer - // writes. The provided WriteSyncer must not be used directly once - // wrapped in a BufferedWriteSyncer. + // writes. // // This field is required. WS WriteSyncer @@ -92,18 +91,9 @@ func (s *BufferedWriteSyncer) initialize() { if s.Clock == nil { s.Clock = DefaultClock } - s.ticker = s.Clock.NewTicker(flushInterval) - // Unpack to the underlying WriteSyncer if we have a lockedWriteSyncer - // to avoid double-locking. Note that there's a risk here if the user - // tries to use the Lock-ed WriteSyncer directly in addition to using - // it with BufferedWriteSyncer, so we declare that the wrapped - // WriteSyncer is only ours to use once wrapped. - if w, ok := s.WS.(*lockedWriteSyncer); ok { - s.WS = w.ws - } + s.ticker = s.Clock.NewTicker(flushInterval) s.writer = bufio.NewWriterSize(s.WS, size) - s.stop = make(chan struct{}) s.done = make(chan struct{}) s.initialized = true @@ -138,9 +128,8 @@ func (s *BufferedWriteSyncer) Sync() error { defer s.mu.Unlock() var err error - if w := s.writer; w != nil { - // w is nil if we haven't yet been initialized. - err = w.Flush() + if s.initialized { + err = s.writer.Flush() } return multierr.Append(err, s.WS.Sync()) @@ -167,7 +156,7 @@ func (s *BufferedWriteSyncer) flushLoop() { // Stop closes the buffer, cleans up background goroutines, and flushes // remaining unwritten data. // -// This must be called exactly once per BufferedWriteSyncer. +// This must be called exactly once. func (s *BufferedWriteSyncer) Stop() error { // Critical section. func() {