Merge pull request #93 from ipfs/fix/log-level

Fix log level handling

log_level_test.go

@@ -0,0 +1,43 @@
+package log
+
+import (
+	"encoding/json"
+	"io"
+	"testing"
+)
+
+func TestLogLevel(t *testing.T) {
+	const subsystem = "log-level-test"
+	logger := Logger(subsystem)
+	reader := NewPipeReader()
+	done := make(chan struct{})
+	go func() {
+		defer close(done)
+		decoder := json.NewDecoder(reader)
+		for {
+			var entry struct {
+				Message string `json:"msg"`
+			}
+			err := decoder.Decode(&entry)
+			switch err {
+			default:
+				t.Error(err)
+				return
+			case io.EOF:
+				return
+			case nil:
+			}
+			if entry.Message != "bar" {
+				t.Errorf("unexpected message: %s", entry.Message)
+			}
+		}
+	}()
+	logger.Debugw("foo")
+	SetLogLevel(subsystem, "debug")
+	logger.Debugw("bar")
+	SetAllLoggers(LevelInfo)
+	logger.Debugw("baz")
+	logger.Sync()
+	reader.Close()
+	<-done
+}

pipe.go

@@ -3,14 +3,16 @@ package log
 import (
 	"io"
 
+	"go.uber.org/multierr"
 	"go.uber.org/zap/zapcore"
 )
 
 // A PipeReader is a reader that reads from the logger. It is synchronous
 // so blocking on read will affect logging performance.
 type PipeReader struct {
-	r    *io.PipeReader
-	core zapcore.Core
+	r      *io.PipeReader
+	closer io.Closer
+	core   zapcore.Core
 }
 
 // Read implements the standard Read interface
@@ -23,18 +25,23 @@ func (p *PipeReader) Close() error {
 	if p.core != nil {
 		loggerCore.DeleteCore(p.core)
 	}
-	return p.r.Close()
+	return multierr.Append(p.core.Sync(), p.closer.Close())
 }
 
 // NewPipeReader creates a new in-memory reader that reads from all loggers
 // The caller must call Close on the returned reader when done.
+//
+// By default, it:
+//
+// 1. Logs JSON. This can be changed by passing the PipeFormat option.
+// 2. Logs everything that would otherwise be logged to the "primary" log
+//    output. That is, everything enabled by SetLogLevel. The minimum log level
+//    can be increased by passing the PipeLevel option.
 func NewPipeReader(opts ...PipeReaderOption) *PipeReader {
-	loggerMutex.Lock()
 	opt := pipeReaderOptions{
-		format: primaryFormat,
-		level:  primaryLevel,
+		format: JSONOutput,
+		level:  LevelDebug,
 	}
-	loggerMutex.Unlock()
 
 	for _, o := range opts {
 		o.setOption(&opt)
@@ -43,8 +50,9 @@ func NewPipeReader(opts ...PipeReaderOption) *PipeReader {
 	r, w := io.Pipe()
 
 	p := &PipeReader{
-		r:    r,
-		core: newCore(opt.format, zapcore.AddSync(w), opt.level),
+		r:      r,
+		closer: w,
+		core:   newCore(opt.format, zapcore.AddSync(w), opt.level),
 	}
 
 	loggerCore.AddCore(p.core)

setup.go

@@ -65,11 +65,11 @@ var loggerMutex sync.RWMutex // guards access to global logger state
 var loggers = make(map[string]*zap.SugaredLogger)
 var levels = make(map[string]zap.AtomicLevel)
 
-// primaryFormat is the default format of the primary core used for logging
+// primaryFormat is the format of the primary core used for logging
 var primaryFormat LogFormat = ColorizedOutput
 
-// primaryLevel is the default log level of the primary core used for logging
-var primaryLevel LogLevel = LevelError
+// defaultLevel is the default log level
+var defaultLevel LogLevel = LevelError
 
 // primaryCore is the primary logging core
 var primaryCore zapcore.Core
@@ -86,7 +86,7 @@ func SetupLogging(cfg Config) {
 	defer loggerMutex.Unlock()
 
 	primaryFormat = cfg.Format
-	primaryLevel = cfg.Level
+	defaultLevel = cfg.Level
 
 	outputPaths := []string{}
 
@@ -111,15 +111,15 @@ func SetupLogging(cfg Config) {
 		panic(fmt.Sprintf("unable to open logging output: %v", err))
 	}
 
-	newPrimaryCore := newCore(primaryFormat, ws, primaryLevel)
+	newPrimaryCore := newCore(primaryFormat, ws, LevelDebug) // the main core needs to log everything.
 	if primaryCore != nil {
 		loggerCore.ReplaceCore(primaryCore, newPrimaryCore)
 	} else {
 		loggerCore.AddCore(newPrimaryCore)
 	}
 	primaryCore = newPrimaryCore
 
-	setAllLoggers(primaryLevel)
+	setAllLoggers(defaultLevel)
 }
 
 // SetDebugLogging calls SetAllLoggers with logging.DEBUG
@@ -209,7 +209,7 @@ func getLogger(name string) *zap.SugaredLogger {
 	defer loggerMutex.Unlock()
 	log, ok := loggers[name]
 	if !ok {
-		levels[name] = zap.NewAtomicLevelAt(zapcore.Level(primaryLevel))
+		levels[name] = zap.NewAtomicLevelAt(zapcore.Level(defaultLevel))
 		log = zap.New(loggerCore).
 			WithOptions(zap.IncreaseLevel(levels[name])).
 			Named(name).