per-subsystem log-levels

setup.go

@@ -30,9 +30,9 @@ const (
 	envLoggingFmt = "GOLOG_LOG_FMT"
 
 	envLoggingFile = "GOLOG_FILE" // /path/to/file
-	envLoggingURL = "GOLOG_URL" // url that will be processed by sink in the zap
+	envLoggingURL  = "GOLOG_URL"  // url that will be processed by sink in the zap
 
-	envLoggingOutput = "GOLOG_OUTPUT" // possible values: stdout|stderr|file combine multiple values with '+'
+	envLoggingOutput = "GOLOG_OUTPUT"     // possible values: stdout|stderr|file combine multiple values with '+'
 	envLoggingLabels = "GOLOG_LOG_LABELS" // comma-separated key-value pairs, i.e. "app=example_app,dc=sjc-1"
 )
 
@@ -48,9 +48,12 @@ type Config struct {
 	// Format overrides the format of the log output. Defaults to ColorizedOutput
 	Format LogFormat
 
-	// Level is the minimum enabled logging level.
+	// Level is the default minimum enabled logging level.
 	Level LogLevel
 
+	// SubsystemLevels are the default levels per-subsystem. When unspecified, defaults to Level.
+	SubsystemLevels map[string]LogLevel
+
 	// Stderr indicates whether logs should be written to stderr.
 	Stderr bool
 
@@ -139,6 +142,14 @@ func SetupLogging(cfg Config) {
 	primaryCore = newPrimaryCore
 
 	setAllLoggers(defaultLevel)
+
+	for name, level := range cfg.SubsystemLevels {
+		if leveler, ok := levels[name]; ok {
+			leveler.SetLevel(zapcore.Level(level))
+		} else {
+			levels[name] = zap.NewAtomicLevelAt(zapcore.Level(level))
+		}
+	}
 }
 
 // SetDebugLogging calls SetAllLoggers with logging.DEBUG
@@ -228,10 +239,14 @@ func getLogger(name string) *zap.SugaredLogger {
 	defer loggerMutex.Unlock()
 	log, ok := loggers[name]
 	if !ok {
-		levels[name] = zap.NewAtomicLevelAt(zapcore.Level(defaultLevel))
+		level, ok := levels[name]
+		if !ok {
+			level = zap.NewAtomicLevelAt(zapcore.Level(defaultLevel))
+			levels[name] = level
+		}
 		log = zap.New(loggerCore).
 			WithOptions(
-				zap.IncreaseLevel(levels[name]),
+				zap.IncreaseLevel(level),
 				zap.AddCaller(),
 			).
 			Named(name).
@@ -246,10 +261,11 @@ func getLogger(name string) *zap.SugaredLogger {
 // configFromEnv returns a Config with defaults populated using environment variables.
 func configFromEnv() Config {
 	cfg := Config{
-		Format: ColorizedOutput,
-		Stderr: true,
-		Level:  LevelError,
-		Labels: map[string]string{},
+		Format:          ColorizedOutput,
+		Stderr:          true,
+		Level:           LevelError,
+		SubsystemLevels: map[string]LogLevel{},
+		Labels:          map[string]string{},
 	}
 
 	format := os.Getenv(envLoggingFmt)
@@ -269,10 +285,19 @@ func configFromEnv() Config {
 		lvl = os.Getenv(envIPFSLogging)
 	}
 	if lvl != "" {
-		var err error
-		cfg.Level, err = LevelFromString(lvl)
-		if err != nil {
-			fmt.Fprintf(os.Stderr, "error setting log levels: %s\n", err)
+		for _, kvs := range strings.Split(lvl, ",") {
+			kv := strings.SplitN(kvs, "=", 2)
+			lvl, err := LevelFromString(kv[len(kv)-1])
+			if err != nil {
+				fmt.Fprintf(os.Stderr, "error setting log level %q: %s\n", kvs, err)
+				continue
+			}
+			switch len(kv) {
+			case 1:
+				cfg.Level = lvl
+			case 2:
+				cfg.SubsystemLevels[kv[0]] = lvl
+			}
 		}
 	}
 

setup_test.go

@@ -60,9 +60,11 @@ func TestLogToFileAndStderr(t *testing.T) {
 	defer os.Remove(logfile.Name())
 
 	os.Setenv(envLoggingFile, logfile.Name())
+	defer os.Unsetenv(envLoggingFile)
 
 	// set log output env var
 	os.Setenv(envLoggingOutput, "file+stderr")
+	defer os.Unsetenv(envLoggingOutput)
 
 	SetupLogging(configFromEnv())
 
@@ -102,6 +104,7 @@ func TestLogToFile(t *testing.T) {
 
 	// set the go-log file env var
 	os.Setenv(envLoggingFile, logfile.Name())
+	defer os.Unsetenv(envLoggingFile)
 
 	SetupLogging(configFromEnv())
 
@@ -137,6 +140,7 @@ func TestLogLabels(t *testing.T) {
 
 	// set the go-log labels env var
 	os.Setenv(envLoggingLabels, "app=example_app,dc=sjc-1,foobar") // foobar to ensure we don't panic on bad input.
+	defer os.Unsetenv(envLoggingLabels)
 	SetupLogging(configFromEnv())
 
 	log := getLogger("test")
@@ -154,3 +158,48 @@ func TestLogLabels(t *testing.T) {
 		t.Errorf("got %q, wanted it to contain log output", buf.String())
 	}
 }
+
+func TestSubsystemLevels(t *testing.T) {
+	r, w, err := os.Pipe()
+	if err != nil {
+		t.Fatalf("failed to open pipe: %v", err)
+	}
+
+	stderr := os.Stderr
+	os.Stderr = w
+	defer func() {
+		os.Stderr = stderr
+	}()
+
+	// set the go-log labels env var
+	os.Setenv(envLogging, "info,test1=debug")
+	defer os.Unsetenv(envLoggingLabels)
+	SetupLogging(configFromEnv())
+
+	log1 := getLogger("test1")
+	log2 := getLogger("test2")
+
+	log1.Debug("debug1")
+	log1.Info("info1")
+	log2.Debug("debug2")
+	log2.Info("info2")
+	w.Close()
+
+	buf := &bytes.Buffer{}
+	if _, err := io.Copy(buf, r); err != nil && err != io.ErrClosedPipe {
+		t.Fatalf("unexpected error: %v", err)
+	}
+
+	if !strings.Contains(buf.String(), "debug1") {
+		t.Errorf("got %q, wanted it to contain debug1", buf.String())
+	}
+	if strings.Contains(buf.String(), "debug2") {
+		t.Errorf("got %q, wanted it to not contain debug2", buf.String())
+	}
+	if !strings.Contains(buf.String(), "info1") {
+		t.Errorf("got %q, wanted it to contain info1", buf.String())
+	}
+	if !strings.Contains(buf.String(), "info2") {
+		t.Errorf("got %q, wanted it to contain info2", buf.String())
+	}
+}