Use multiple cores in logger

Another take on #66

This change introduces a multicore implementation that allows
additonal zap cores to be added at runtime. Each core can be
configured with distinct encoders and writers which makes
it possible to tail the logs in a program using a different
log format (e.g. program may log in json but interactive
tailing can be in plaintext). This comes at the cost of an
additional mutex that must be taken on each write since the
destination of the write is mutable.

It reworks (and simplifies) the pipe reader implementation
added in #87 and adds a
new function NewPipeReaderFormat which creates a pipe reader
using a different output format.

This change also allows us to reconfigure logging after it has been
initialised by swapping out the initial zap core with a
newly configured one. This solves the problem that I attempted
in #88

Adds a Config struct to enable easier reconfiguration
of the logger. The default config is still read from the
environment in init() but a client of the package can now call
SetupLogging again with a custom config to adjust logging after
initialization.

Note that the fix for #83
is slightly different. If a file is specified using GOLOG_FILE
then logging to stderr will be disabled but logging can be
configured to write to both file and stderr by calling SetupLogging
with the appropriate configuration.

core.go

@@ -0,0 +1,120 @@
+package log
+
+import (
+	"sync"
+
+	"go.uber.org/multierr"
+	"go.uber.org/zap"
+	"go.uber.org/zap/zapcore"
+)
+
+var _ zapcore.Core = (*lockedMultiCore)(nil)
+
+type lockedMultiCore struct {
+	mu    sync.RWMutex // guards mutations to cores slice
+	cores []zapcore.Core
+}
+
+func (l *lockedMultiCore) With(fields []zapcore.Field) zapcore.Core {
+	l.mu.RLock()
+	defer l.mu.RUnlock()
+	sub := &lockedMultiCore{
+		cores: make([]zapcore.Core, len(l.cores)),
+	}
+	for i := range l.cores {
+		sub.cores[i] = l.cores[i].With(fields)
+	}
+	return sub
+}
+
+func (l *lockedMultiCore) Enabled(lvl zapcore.Level) bool {
+	l.mu.RLock()
+	defer l.mu.RUnlock()
+	for i := range l.cores {
+		if l.cores[i].Enabled(lvl) {
+			return true
+		}
+	}
+	return false
+}
+
+func (l *lockedMultiCore) Check(ent zapcore.Entry, ce *zapcore.CheckedEntry) *zapcore.CheckedEntry {
+	l.mu.RLock()
+	defer l.mu.RUnlock()
+	for i := range l.cores {
+		ce = l.cores[i].Check(ent, ce)
+	}
+	return ce
+}
+
+func (l *lockedMultiCore) Write(ent zapcore.Entry, fields []zapcore.Field) error {
+	l.mu.RLock()
+	defer l.mu.RUnlock()
+	var err error
+	for i := range l.cores {
+		err = multierr.Append(err, l.cores[i].Write(ent, fields))
+	}
+	return err
+}
+
+func (l *lockedMultiCore) Sync() error {
+	l.mu.RLock()
+	defer l.mu.RUnlock()
+	var err error
+	for i := range l.cores {
+		err = multierr.Append(err, l.cores[i].Sync())
+	}
+	return err
+}
+
+func (l *lockedMultiCore) AddCore(core zapcore.Core) {
+	l.mu.Lock()
+	defer l.mu.Unlock()
+
+	l.cores = append(l.cores, core)
+}
+
+func (l *lockedMultiCore) DeleteCore(core zapcore.Core) {
+	l.mu.Lock()
+	defer l.mu.Unlock()
+
+	w := 0
+	for i := 0; i < len(l.cores); i++ {
+		if l.cores[i] == core {
+			continue
+		}
+		l.cores[w] = l.cores[i]
+		w++
+	}
+	l.cores = l.cores[:w]
+}
+
+func (l *lockedMultiCore) ReplaceCore(original, replacement zapcore.Core) {
+	l.mu.Lock()
+	defer l.mu.Unlock()
+
+	for i := 0; i < len(l.cores); i++ {
+		if l.cores[i] == original {
+			l.cores[i] = replacement
+		}
+	}
+}
+
+func newCore(format LogFormat, ws zapcore.WriteSyncer, level LogLevel) zapcore.Core {
+	encCfg := zap.NewProductionEncoderConfig()
+	encCfg.EncodeTime = zapcore.ISO8601TimeEncoder
+
+	var encoder zapcore.Encoder
+	switch format {
+	case PlaintextOutput:
+		encCfg.EncodeLevel = zapcore.CapitalLevelEncoder
+		encoder = zapcore.NewConsoleEncoder(encCfg)
+	case JSONOutput:
+		encoder = zapcore.NewJSONEncoder(encCfg)
+	default:
+		encCfg.EncodeLevel = zapcore.CapitalColorLevelEncoder
+		encoder = zapcore.NewConsoleEncoder(encCfg)
+	}
+
+	return zapcore.NewCore(encoder, ws, zap.NewAtomicLevelAt(zapcore.Level(level)))
+}

core_test.go

@@ -0,0 +1,177 @@
+package log
+
+import (
+	"bytes"
+	"testing"
+	"time"
+
+	"go.uber.org/zap/zapcore"
+)
+
+func TestNewCoreFormat(t *testing.T) {
+	entry := zapcore.Entry{
+		LoggerName: "main",
+		Level:      zapcore.InfoLevel,
+		Message:    "scooby",
+		Time:       time.Date(2010, 5, 23, 15, 14, 0, 0, time.UTC),
+	}
+
+	testCases := []struct {
+		format LogFormat
+		want   string
+	}{
+		{
+			format: ColorizedOutput,
+			want:   "2010-05-23T15:14:00.000Z\t\x1b[34mINFO\x1b[0m\tmain\tscooby\n",
+		},
+		{
+			format: JSONOutput,
+			want:   `{"level":"info","ts":"2010-05-23T15:14:00.000Z","logger":"main","msg":"scooby"}` + "\n",
+		},
+		{
+			format: PlaintextOutput,
+			want:   "2010-05-23T15:14:00.000Z\tINFO\tmain\tscooby\n",
+		},
+	}
+
+	for _, tc := range testCases {
+		buf := &bytes.Buffer{}
+		ws := zapcore.AddSync(buf)
+
+		core := newCore(tc.format, ws, LevelDebug)
+		core.Write(entry, nil)
+
+		got := buf.String()
+		if got != tc.want {
+			t.Errorf("got %q, want %q", got, tc.want)
+		}
+	}
+
+}
+
+func TestLockedMultiCoreAddCore(t *testing.T) {
+	mc := &lockedMultiCore{}
+
+	buf1 := &bytes.Buffer{}
+	core1 := newCore(PlaintextOutput, zapcore.AddSync(buf1), LevelDebug)
+	mc.AddCore(core1)
+
+	buf2 := &bytes.Buffer{}
+	core2 := newCore(ColorizedOutput, zapcore.AddSync(buf2), LevelDebug)
+	mc.AddCore(core2)
+
+	entry := zapcore.Entry{
+		LoggerName: "main",
+		Level:      zapcore.InfoLevel,
+		Message:    "scooby",
+		Time:       time.Date(2010, 5, 23, 15, 14, 0, 0, time.UTC),
+	}
+	mc.Write(entry, nil)
+
+	want1 := "2010-05-23T15:14:00.000Z\tINFO\tmain\tscooby\n"
+	got1 := buf1.String()
+	if got1 != want1 {
+		t.Errorf("core1 got %q, want %q", got1, want1)
+	}
+
+	want2 := "2010-05-23T15:14:00.000Z\t\x1b[34mINFO\x1b[0m\tmain\tscooby\n"
+	got2 := buf2.String()
+	if got2 != want2 {
+		t.Errorf("core2 got %q, want %q", got2, want2)
+	}
+
+}
+
+func TestLockedMultiCoreDeleteCore(t *testing.T) {
+
+	mc := &lockedMultiCore{}
+
+	buf1 := &bytes.Buffer{}
+	core1 := newCore(PlaintextOutput, zapcore.AddSync(buf1), LevelDebug)
+	mc.AddCore(core1)
+
+	// Write entry to just first core
+	entry := zapcore.Entry{
+		LoggerName: "main",
+		Level:      zapcore.InfoLevel,
+		Message:    "scooby",
+		Time:       time.Date(2010, 5, 23, 15, 14, 0, 0, time.UTC),
+	}
+	mc.Write(entry, nil)
+
+	buf2 := &bytes.Buffer{}
+	core2 := newCore(ColorizedOutput, zapcore.AddSync(buf2), LevelDebug)
+	mc.AddCore(core2)
+
+	// Remove the first core
+	mc.DeleteCore(core1)
+
+	// Write another entry
+	entry2 := zapcore.Entry{
+		LoggerName: "main",
+		Level:      zapcore.InfoLevel,
+		Message:    "velma",
+		Time:       time.Date(2010, 5, 23, 15, 15, 0, 0, time.UTC),
+	}
+
+	mc.Write(entry2, nil)
+
+	want1 := "2010-05-23T15:14:00.000Z\tINFO\tmain\tscooby\n"
+	got1 := buf1.String()
+	if got1 != want1 {
+		t.Errorf("core1 got %q, want %q", got1, want1)
+	}
+
+	want2 := "2010-05-23T15:15:00.000Z\t\x1b[34mINFO\x1b[0m\tmain\tvelma\n"
+	got2 := buf2.String()
+	if got2 != want2 {
+		t.Errorf("core2 got %q, want %q", got2, want2)
+	}
+
+}
+
+func TestLockedMultiCoreReplaceCore(t *testing.T) {
+	mc := &lockedMultiCore{}
+
+	buf1 := &bytes.Buffer{}
+	core1 := newCore(PlaintextOutput, zapcore.AddSync(buf1), LevelDebug)
+	mc.AddCore(core1)
+
+	// Write entry to just first core
+	entry := zapcore.Entry{
+		LoggerName: "main",
+		Level:      zapcore.InfoLevel,
+		Message:    "scooby",
+		Time:       time.Date(2010, 5, 23, 15, 14, 0, 0, time.UTC),
+	}
+	mc.Write(entry, nil)
+
+	buf2 := &bytes.Buffer{}
+	core2 := newCore(ColorizedOutput, zapcore.AddSync(buf2), LevelDebug)
+
+	// Replace the first core with the second
+	mc.ReplaceCore(core1, core2)
+
+	// Write another entry
+	entry2 := zapcore.Entry{
+		LoggerName: "main",
+		Level:      zapcore.InfoLevel,
+		Message:    "velma",
+		Time:       time.Date(2010, 5, 23, 15, 15, 0, 0, time.UTC),
+	}
+
+	mc.Write(entry2, nil)
+
+	want1 := "2010-05-23T15:14:00.000Z\tINFO\tmain\tscooby\n"
+	got1 := buf1.String()
+	if got1 != want1 {
+		t.Errorf("core1 got %q, want %q", got1, want1)
+	}
+
+	want2 := "2010-05-23T15:15:00.000Z\t\x1b[34mINFO\x1b[0m\tmain\tvelma\n"
+	got2 := buf2.String()
+	if got2 != want2 {
+		t.Errorf("core2 got %q, want %q", got2, want2)
+	}
+
+}

go.mod

@@ -1,5 +1,8 @@
 module github.com/ipfs/go-log/v2
 
-require go.uber.org/zap v1.14.1
+require (
+	go.uber.org/multierr v1.5.0
+	go.uber.org/zap v1.14.1
+)
 
 go 1.12

go.sum

@@ -29,6 +29,7 @@ go.uber.org/tools v0.0.0-20190618225709-2cfd321de3ee h1:0mgffUl7nfd+FpvXMVz4IDEa
 go.uber.org/tools v0.0.0-20190618225709-2cfd321de3ee/go.mod h1:vJERXedbb3MVM5f9Ejo0C68/HhF8uaILCdgjnY+goOA=
 go.uber.org/zap v1.14.1 h1:nYDKopTbvAPq/NrUVZwT15y2lpROBiLLyoRTbXOYWOo=
 go.uber.org/zap v1.14.1/go.mod h1:Mb2vm2krFEG5DV0W9qcHBYFtp/Wku1cvYaqPsS/WYfc=
+go.uber.org/zap v1.15.0 h1:ZZCA22JRF2gQE5FoNmhmrf7jeJJ2uhqDUNRYKm8dvmM=
 golang.org/x/crypto v0.0.0-20190308221718-c2843e01d9a2/go.mod h1:djNgcEr1/C05ACkg1iLfiJU5Ep61QUkGW8qpdssI0+w=
 golang.org/x/crypto v0.0.0-20190510104115-cbcb75029529/go.mod h1:yigFU9vqHzYiE8UmvKecakEJjdnWj3jj499lnFckfCI=
 golang.org/x/lint v0.0.0-20190930215403-16217165b5de h1:5hukYrvBGR8/eNkX5mdUezrA6JiaEZDtJb9Ei+1LlBs=