hook: introduce mechanism for hooking into raw logger output

go.mod

@@ -6,9 +6,11 @@ require (
 	github.com/cockroachdb/errors v1.9.0
 	github.com/fatih/color v1.13.0
 	github.com/getsentry/sentry-go v0.13.0
-	github.com/google/go-cmp v0.5.7
+	github.com/google/go-cmp v0.5.9
 	github.com/google/uuid v1.3.0
-	github.com/stretchr/testify v1.8.0
+	github.com/hexops/autogold/v2 v2.0.3
+	github.com/stretchr/testify v1.8.1
+	go.bobheadxi.dev/streamline v1.2.2
 	go.uber.org/atomic v1.10.0
 	go.uber.org/zap v1.23.0
 )
@@ -17,15 +19,26 @@ require (
 	github.com/cockroachdb/logtags v0.0.0-20211118104740-dabe8e521a4f // indirect
 	github.com/cockroachdb/redact v1.1.3 // indirect
 	github.com/davecgh/go-spew v1.1.1 // indirect
+	github.com/djherbis/buffer v1.2.0 // indirect
+	github.com/djherbis/nio/v3 v3.0.1 // indirect
 	github.com/gogo/protobuf v1.3.2 // indirect
+	github.com/hexops/autogold v1.3.1 // indirect
+	github.com/hexops/gotextdiff v1.0.3 // indirect
+	github.com/hexops/valast v1.4.3 // indirect
+	github.com/itchyny/gojq v0.12.11 // indirect
+	github.com/itchyny/timefmt-go v0.1.5 // indirect
 	github.com/kr/pretty v0.3.0 // indirect
 	github.com/kr/text v0.2.0 // indirect
-	github.com/mattn/go-colorable v0.1.12 // indirect
-	github.com/mattn/go-isatty v0.0.14 // indirect
+	github.com/mattn/go-colorable v0.1.13 // indirect
+	github.com/mattn/go-isatty v0.0.16 // indirect
+	github.com/nightlyone/lockfile v1.0.0 // indirect
 	github.com/pkg/errors v0.9.1 // indirect
 	github.com/pmezard/go-difflib v1.0.0 // indirect
-	github.com/rogpeppe/go-internal v1.8.1 // indirect
+	github.com/rogpeppe/go-internal v1.9.0 // indirect
 	go.uber.org/multierr v1.8.0 // indirect
-	golang.org/x/sys v0.0.0-20220520151302-bc2c85ada10a // indirect
+	golang.org/x/mod v0.7.0 // indirect
+	golang.org/x/sys v0.4.0 // indirect
+	golang.org/x/tools v0.5.0 // indirect
 	gopkg.in/yaml.v3 v3.0.1 // indirect
+	mvdan.cc/gofumpt v0.4.0 // indirect
 )

hook/writer.go

@@ -0,0 +1,36 @@
+package hook
+
+import (
+	"io"
+
+	"go.uber.org/zap"
+	"go.uber.org/zap/zapcore"
+
+	"github.com/sourcegraph/log"
+	"github.com/sourcegraph/log/internal/configurable"
+	"github.com/sourcegraph/log/internal/sinkcores/outputcore"
+	"github.com/sourcegraph/log/output"
+)
+
+type writerSyncerAdapter struct{ io.Writer }
+
+func (writerSyncerAdapter) Sync() error { return nil }
+
+// Writer hooks receiver to rendered log output at level in the requested format,
+// typically one of 'json' or 'console'.
+func Writer(logger log.Logger, receiver io.Writer, level log.Level, format output.Format) log.Logger {
+	cl := configurable.Cast(logger)
+
+	// Adapt to WriteSyncer in case receiver doesn't implement it
+	var writeSyncer zapcore.WriteSyncer
+	if ws, ok := receiver.(zapcore.WriteSyncer); ok {
+		writeSyncer = ws
+	} else {
+		writeSyncer = writerSyncerAdapter{receiver}
+	}
+
+	core := outputcore.NewCore(writeSyncer, level.Parse(), format, zap.SamplingConfig{}, nil, false)
+	return cl.WithCore(func(c zapcore.Core) zapcore.Core {
+		return zapcore.NewTee(c, core)
+	})
+}

hook/writer_test.go

@@ -0,0 +1,44 @@
+package hook_test
+
+import (
+	"testing"
+
+	"github.com/hexops/autogold/v2"
+	"github.com/stretchr/testify/require"
+	"go.bobheadxi.dev/streamline/jq"
+	"go.bobheadxi.dev/streamline/pipe"
+
+	"github.com/sourcegraph/log"
+	"github.com/sourcegraph/log/hook"
+	"github.com/sourcegraph/log/logtest"
+	"github.com/sourcegraph/log/output"
+)
+
+func TestWriter(t *testing.T) {
+	logger, exportLogs := logtest.Captured(t)
+
+	writer, stream := pipe.NewStream()
+	hookedLogger := hook.Writer(logger, writer, log.LevelWarn, output.FormatJSON)
+
+	hookedLogger.Debug("debug message")
+	hookedLogger.Warn("warn message")
+	hookedLogger.Error("error message")
+
+	logger.Error("parent message")
+
+	// done with writing
+	writer.CloseWithError(nil)
+
+	// hooked logger output - only warn and above, and messages logged to parent are not
+	// included. We only get the messages because there's no easy way to mock the clock.
+	hookedOutput, err := stream.WithPipeline(jq.Pipeline(".Body")).Lines()
+	require.NoError(t, err)
+	autogold.Expect([]string{`"warn message"`, `"error message"`}).Equal(t, hookedOutput)
+
+	// parent logger output - should receive everything
+	parentOutput := exportLogs().Messages()
+	autogold.Expect([]string{
+		"debug message", "warn message", "error message",
+		"parent message",
+	}).Equal(t, parentOutput)
+}

init.go

@@ -13,9 +13,14 @@ var (
 	EnvDevelopment = globallogger.EnvDevelopment
 	// EnvLogFormat is key of the environment variable that is used to set the log format
 	// on Init.
+	//
+	// The value should be one of 'json' or 'console', defaulting to 'json'.
 	EnvLogFormat = "SRC_LOG_FORMAT"
 	// EnvLogLevel is key of the environment variable that can be used to set the log
 	// level on Init.
+	//
+	// The value is one of 'debug', 'info', 'warn', 'error', or 'none', defaulting to
+	// 'warn'.
 	EnvLogLevel = "SRC_LOG_LEVEL"
 	// EnvLogScopeLevel is key of the environment variable that can be used to
 	// override the log level for specific scopes and its children.

internal/encoders/config.go

@@ -4,6 +4,7 @@ import (
 	"fmt"
 
 	"github.com/fatih/color"
+	"github.com/sourcegraph/log/output"
 	"go.uber.org/zap/zapcore"
 )
 
@@ -63,16 +64,16 @@ func applyDevConfig(cfg zapcore.EncoderConfig) zapcore.EncoderConfig {
 	return cfg
 }
 
-func BuildEncoder(format OutputFormat, development bool) (enc zapcore.Encoder) {
+func BuildEncoder(format output.Format, development bool) (enc zapcore.Encoder) {
 	config := OpenTelemetryConfig
 	if development {
 		config = applyDevConfig(config)
 	}
 
 	switch format {
-	case OutputConsole:
+	case output.FormatConsole:
 		return zapcore.NewConsoleEncoder(config)
-	case OutputJSON:
+	case output.FormatJSON:
 		return zapcore.NewJSONEncoder(config)
 	default:
 		panic("unknown output format")

internal/globallogger/globallogger.go

@@ -12,6 +12,7 @@ import (
 
 	"github.com/sourcegraph/log/internal/encoders"
 	"github.com/sourcegraph/log/internal/otelfields"
+	"github.com/sourcegraph/log/internal/stderr"
 )
 
 var (
@@ -71,7 +72,7 @@ func (f *forceSyncer) OnWrite(_ *zapcore.CheckedEntry, _ []zapcore.Field) {
 }
 
 func initLogger(r otelfields.Resource, development bool, sinks []zapcore.Core) *zap.Logger {
-	internalErrsSink, err := openStderr()
+	internalErrsSink, err := stderr.Open()
 	if err != nil {
 		panic(err.Error())
 	}
@@ -101,11 +102,3 @@ func initLogger(r otelfields.Resource, development bool, sinks []zapcore.Core) *
 	}
 	return logger.With(zap.Object(otelfields.ResourceFieldKey, &encoders.ResourceEncoder{Resource: r}))
 }
-
-func openStderr() (zapcore.WriteSyncer, error) {
-	errSink, _, err := zap.Open("stderr")
-	if err != nil {
-		return nil, err
-	}
-	return errSink, nil
-}

internal/sinkcores/outputcore/core.go

@@ -3,15 +3,17 @@ package outputcore
 import (
 	"time"
 
-	"github.com/sourcegraph/log/internal/encoders"
 	"go.uber.org/zap"
 	"go.uber.org/zap/zapcore"
+
+	"github.com/sourcegraph/log/internal/encoders"
+	"github.com/sourcegraph/log/output"
 )
 
 func NewCore(
 	output zapcore.WriteSyncer,
 	level zapcore.LevelEnabler,
-	format encoders.OutputFormat,
+	format output.Format,
 	sampling zap.SamplingConfig,
 	overrides []Override,
 	development bool,

logger_test.go

@@ -11,7 +11,7 @@ import (
 	"github.com/sourcegraph/log/logtest"
 )
 
-func newTestLogger(t *testing.T) (log.Logger, func() []logtest.CapturedLog) {
+func newTestLogger(t *testing.T) (log.Logger, func() logtest.CapturedLogs) {
 	logger, exportLogs := logtest.Captured(t)
 	assert.NotNil(t, logger)
 

logtest/logtest.go

@@ -12,10 +12,10 @@ import (
 
 	"github.com/sourcegraph/log"
 	"github.com/sourcegraph/log/internal/configurable"
-	"github.com/sourcegraph/log/internal/encoders"
 	"github.com/sourcegraph/log/internal/globallogger"
 	"github.com/sourcegraph/log/internal/sinkcores/outputcore"
 	"github.com/sourcegraph/log/internal/stderr"
+	"github.com/sourcegraph/log/output"
 )
 
 // stdTestInit guards the initialization of the standard library testing package.
@@ -54,11 +54,11 @@ func InitWithLevel(_ *testing.M, level log.Level) {
 
 func initGlobal(level zapcore.Level) {
 	// send output from package-scope loggers to stderr (we can't write to testing here)
-	output, err := stderr.Open()
+	w, err := stderr.Open()
 	if err != nil {
 		panic(err)
 	}
-	core := outputcore.NewCore(output, level, encoders.OutputConsole, zap.SamplingConfig{}, nil, true)
+	core := outputcore.NewCore(w, level, output.FormatConsole, zap.SamplingConfig{}, nil, true)
 	// use an empty resource, we don't log output Resource in dev mode anyway
 	globallogger.Init(log.Resource{}, true, []zapcore.Core{core})
 }
@@ -71,6 +71,17 @@ type CapturedLog struct {
 	Fields  map[string]interface{}
 }
 
+type CapturedLogs []CapturedLog
+
+// Messages aggregates all messages (excluding fields) from the captured log entries.
+func (cl CapturedLogs) Messages() []string {
+	var messages []string
+	for _, l := range cl {
+		messages = append(messages, l.Message)
+	}
+	return messages
+}
+
 type LoggerOptions struct {
 	// Level configures the minimum log level to output.
 	Level log.Level
@@ -102,7 +113,7 @@ func scopedTestLogger(t testing.TB, options LoggerOptions) log.Logger {
 		return outputcore.NewCore(&testingWriter{
 			t:          t,
 			markFailed: options.FailOnErrorLogs,
-		}, level, encoders.OutputConsole, zap.SamplingConfig{}, nil, true)
+		}, level, output.FormatConsole, zap.SamplingConfig{}, nil, true)
 	})
 }
 
@@ -123,7 +134,7 @@ func ScopedWith(t testing.TB, options LoggerOptions) log.Logger {
 
 // Captured retrieves a logger from scoped to the the given test, and returns a callback,
 // dumpLogs, which flushes the logger buffer and returns log entries.
-func Captured(t testing.TB) (logger log.Logger, exportLogs func() []CapturedLog) {
+func Captured(t testing.TB) (logger log.Logger, exportLogs func() CapturedLogs) {
 	// Cast into internal APIs
 	cl := configurable.Cast(scopedTestLogger(t, LoggerOptions{}))
 
@@ -133,7 +144,7 @@ func Captured(t testing.TB) (logger log.Logger, exportLogs func() []CapturedLog)
 		return zapcore.NewTee(c, observerCore)
 	})
 
-	return logger, func() []CapturedLog {
+	return logger, func() CapturedLogs {
 		observerCore.Sync()
 
 		entries := entries.TakeAll()

output/output.go

@@ -0,0 +1,34 @@
+package output
+
+// Format configures sourcegraph/log output encoding.
+type Format string
+
+const (
+	// FormatJSON encodes log entries to a machine-readable, OpenTelemetry-structured
+	// format.
+	FormatJSON Format = "json"
+	// FormatConsole encodes log entries to a human-readable format.
+	FormatConsole Format = "console"
+)
+
+// ParseFormat parses the given format string as a supported output format, while
+// trying to maintain some degree of back-compat with the intent of previously supported
+// log formats.
+func ParseFormat(format string) Format {
+	switch format {
+	case string(FormatJSON),
+		// True 'logfmt' has significant limitations around certain field types:
+		// https://github.com/jsternberg/zap-logfmt#limitations so since it implies a
+		// desire for a somewhat structured format, we interpret it as OutputJSON.
+		"logfmt":
+		return FormatJSON
+	case string(FormatConsole),
+		// The previous 'condensed' format is optimized for local dev, so it serves the
+		// same purpose as OutputConsole
+		"condensed":
+		return FormatConsole
+	}
+
+	// Fall back to JSON output
+	return FormatJSON
+}