Merge pull request #85 from cdr/ctx-log

Refactor for Context only logging

README.md

@@ -35,9 +35,9 @@ go get cdr.dev/slog
 Many more examples available at [godoc](https://godoc.org/cdr.dev/slog#pkg-examples).
 
 ```go
-log := sloghuman.Make(os.Stdout)
+ctx := sloghuman.Make(ctx, os.Stdout)
 
-log.Info(context.Background(), "my message here",
+slog.Info(ctx, "my message here",
     slog.F("field_name", "something or the other"),
     slog.F("some_map", slog.M(
         slog.F("nested_fields", time.Date(2000, time.February, 5, 4, 4, 4, 0, time.UTC)),
@@ -87,6 +87,8 @@ Here is a list of reasons how we improved on zap with slog.
 
 1. Full [context.Context](https://blog.golang.org/context) support
     - `slog` lets you set fields in a `context.Context` such that any log with the context prints those fields.
+    - `slog` stores the actual logger in the `context.Context`, following the example of
+    [the Go trace library](https://golang.org/pkg/runtime/trace/). Our logger doesn't bloat type and function signatures.
     - We wanted to be able to pull up all relevant logs for a given trace, user or request. With zap, we were plugging
       these fields in for every relevant log or passing around a logger with the fields set. This became very verbose.
 

context.go

@@ -0,0 +1,27 @@
+package slog
+
+import "context"
+
+type loggerCtxKey = struct{}
+
+// SinkContext is used by slog.Make to compose many loggers together.
+type SinkContext struct {
+	Sink
+	context.Context
+}
+
+func contextWithLogger(ctx context.Context, l logger) SinkContext {
+	ctx = context.WithValue(ctx, loggerCtxKey{}, l)
+	return SinkContext{
+		Context: ctx,
+		Sink:    l,
+	}
+}
+
+func loggerFromContext(ctx context.Context) (logger, bool) {
+	v := ctx.Value(loggerCtxKey{})
+	if v == nil {
+		return logger{}, false
+	}
+	return v.(logger), true
+}

example_helper_test.go

@@ -12,12 +12,12 @@ import (
 func httpLogHelper(ctx context.Context, status int) {
 	slog.Helper()
 
-	l.Info(ctx, "sending HTTP response",
+	slog.Info(ctx, "sending HTTP response",
 		slog.F("status", status),
 	)
 }
 
-var l = sloghuman.Make(os.Stdout)
+var l = sloghuman.Make(context.Background(), os.Stdout)
 
 func ExampleHelper() {
 	ctx := context.Background()

example_marshaller_test.go

@@ -21,9 +21,9 @@ func (s myStruct) MarshalJSON() ([]byte, error) {
 }
 
 func Example_marshaller() {
-	l := sloghuman.Make(os.Stdout)
+	ctx := sloghuman.Make(context.Background(), os.Stdout)
 
-	l.Info(context.Background(), "wow",
+	slog.Info(ctx, "wow",
 		slog.F("myStruct", myStruct{
 			foo: 1,
 			bar: 2,

example_test.go

@@ -18,14 +18,14 @@ import (
 )
 
 func Example() {
-	log := sloghuman.Make(os.Stdout)
+	ctx := sloghuman.Make(context.Background(), os.Stdout)
 
-	log.Info(context.Background(), "my message here",
+	slog.Info(ctx, "my message here",
 		slog.F("field_name", "something or the other"),
 		slog.F("some_map", slog.M(
 			slog.F("nested_fields", time.Date(2000, time.February, 5, 4, 4, 4, 0, time.UTC)),
 		)),
-		slog.Error(
+		slog.Err(
 			xerrors.Errorf("wrap1: %w",
 				xerrors.Errorf("wrap2: %w",
 					io.EOF,
@@ -45,15 +45,15 @@ func Example() {
 }
 
 func Example_struct() {
-	l := sloghuman.Make(os.Stdout)
+	ctx := sloghuman.Make(context.Background(), os.Stdout)
 
 	type hello struct {
 		Meow int       `json:"meow"`
 		Bar  string    `json:"bar"`
 		M    time.Time `json:"m"`
 	}
 
-	l.Info(context.Background(), "check out my structure",
+	slog.Info(ctx, "check out my structure",
 		slog.F("hello", hello{
 			Meow: 1,
 			Bar:  "barbar",
@@ -76,68 +76,69 @@ func Example_testing() {
 }
 
 func Example_tracing() {
-	log := sloghuman.Make(os.Stdout)
+	var ctx context.Context
+	ctx = sloghuman.Make(context.Background(), os.Stdout)
 
-	ctx, _ := trace.StartSpan(context.Background(), "spanName")
+	ctx, _ = trace.StartSpan(ctx, "spanName")
 
-	log.Info(ctx, "my msg", slog.F("hello", "hi"))
+	slog.Info(ctx, "my msg", slog.F("hello", "hi"))
 
 	// 2019-12-09 21:59:48.110 [INFO]	<example_test.go:62>	my msg	{"trace": "f143d018d00de835688453d8dc55c9fd", "span": "f214167bf550afc3", "hello": "hi"}
 }
 
 func Example_multiple() {
-	l := sloghuman.Make(os.Stdout)
+	ctx := sloghuman.Make(context.Background(), os.Stdout)
 
 	f, err := os.OpenFile("stackdriver", os.O_WRONLY|os.O_APPEND|os.O_CREATE, 0644)
 	if err != nil {
-		l.Fatal(context.Background(), "failed to open stackdriver log file", slog.Error(err))
+		slog.Fatal(ctx, "failed to open stackdriver log file", slog.Err(err))
 	}
 
-	l = slog.Make(l, slogstackdriver.Make(f))
+	ctx = slog.Make(l, slogstackdriver.Make(ctx, f))
 
-	l.Info(context.Background(), "log to stdout and stackdriver")
+	slog.Info(ctx, "log to stdout and stackdriver")
 
 	// 2019-12-07 20:59:55.790 [INFO]	<example_test.go:46>	log to stdout and stackdriver
 }
 
 func ExampleWith() {
 	ctx := slog.With(context.Background(), slog.F("field", 1))
 
-	l := sloghuman.Make(os.Stdout)
-	l.Info(ctx, "msg")
+	ctx = sloghuman.Make(ctx, os.Stdout)
+	slog.Info(ctx, "msg")
 
 	// 2019-12-07 20:54:23.986 [INFO]	<example_test.go:20>	msg	{"field": 1}
 }
 
 func ExampleStdlib() {
 	ctx := slog.With(context.Background(), slog.F("field", 1))
-	l := slog.Stdlib(ctx, sloghuman.Make(os.Stdout))
+	l := slog.Stdlib(sloghuman.Make(ctx, os.Stdout))
 
 	l.Print("msg")
 
 	// 2019-12-07 20:54:23.986 [INFO]	(stdlib)	<example_test.go:29>	msg	{"field": 1}
 }
 
-func ExampleLogger_Named() {
+func ExampleNamed() {
 	ctx := context.Background()
 
-	l := sloghuman.Make(os.Stdout)
-	l = l.Named("http")
-	l.Info(ctx, "received request", slog.F("remote address", net.IPv4(127, 0, 0, 1)))
+	ctx = sloghuman.Make(ctx, os.Stdout)
+	ctx = slog.Named(ctx, "http")
+	slog.Info(ctx, "received request", slog.F("remote address", net.IPv4(127, 0, 0, 1)))
 
 	// 2019-12-07 21:20:56.974 [INFO]	(http)	<example_test.go:85>	received request	{"remote address": "127.0.0.1"}
 }
 
-func ExampleLogger_Leveled() {
+func ExampleLeveled() {
 	ctx := context.Background()
 
-	l := sloghuman.Make(os.Stdout)
-	l.Debug(ctx, "testing1")
-	l.Info(ctx, "received request")
+	ctx = sloghuman.Make(ctx, os.Stdout)
+	slog.Debug(ctx, "testing1")
+	slog.Info(ctx, "received request")
 
-	l = l.Leveled(slog.LevelDebug)
+	ctx = slog.Leveled(ctx, slog.LevelDebug)
 
-	l.Debug(ctx, "testing2")
+	slog.Debug(ctx, "testing2")
 
 	// 2019-12-07 21:26:20.945 [INFO]	<example_test.go:95>	received request
 	// 2019-12-07 21:26:20.945 [DEBUG]	<example_test.go:99>	testing2

export_test.go

@@ -1,5 +1,12 @@
 package slog
 
-func (l *Logger) SetExit(fn func(int)) {
+import "context"
+
+func SetExit(ctx context.Context, fn func(int)) context.Context {
+	l, ok := loggerFromContext(ctx)
+	if !ok {
+		return ctx
+	}
 	l.exit = fn
+	return contextWithLogger(ctx, l)
 }

map.go

@@ -128,7 +128,7 @@ func encodeJSON(v interface{}) []byte {
 	b, err := json.Marshal(v)
 	if err != nil {
 		return encode(M(
-			Error(xerrors.Errorf("failed to marshal to JSON: %w", err)),
+			Err(xerrors.Errorf("failed to marshal to JSON: %w", err)),
 			F("type", reflect.TypeOf(v)),
 			F("value", fmt.Sprintf("%+v", v)),
 		))

map_test.go

@@ -37,7 +37,7 @@ func TestMap(t *testing.T) {
 		}
 
 		test(t, slog.M(
-			slog.Error(
+			slog.Err(
 				xerrors.Errorf("wrap1: %w",
 					xerrors.Errorf("wrap2: %w",
 						io.EOF,
@@ -222,10 +222,6 @@ func TestMap(t *testing.T) {
 	})
 }
 
-type meow struct {
-	a int
-}
-
 func indentJSON(t *testing.T, j string) string {
 	b := &bytes.Buffer{}
 	err := json.Indent(b, []byte(j), "", strings.Repeat(" ", 4))

s.go

@@ -3,6 +3,7 @@ package slog
 import (
 	"context"
 	"log"
+	"os"
 	"strings"
 )
 
@@ -15,22 +16,26 @@ import (
 // You can redirect the stdlib default logger with log.SetOutput
 // to the Writer on the logger returned by this function.
 // See the example.
-func Stdlib(ctx context.Context, l Logger) *log.Logger {
-	l.skip += 3
+func Stdlib(ctx context.Context) *log.Logger {
+	ctx = Named(ctx, "stdlib")
 
-	l = l.Named("stdlib")
+	l, ok := loggerFromContext(ctx)
+	if !ok {
+		// Give stderr logger if no slog.
+		return log.New(os.Stderr, "", 0)
+	}
+	l.skip += 3
+	ctx = contextWithLogger(ctx, l)
 
 	w := &stdlogWriter{
 		ctx: ctx,
-		l:   l,
 	}
 
 	return log.New(w, "", 0)
 }
 
 type stdlogWriter struct {
 	ctx context.Context
-	l   Logger
 }
 
 func (w stdlogWriter) Write(p []byte) (n int, err error) {
@@ -39,7 +44,7 @@ func (w stdlogWriter) Write(p []byte) (n int, err error) {
 	// we do not want.
 	msg = strings.TrimSuffix(msg, "\n")
 
-	w.l.Info(w.ctx, msg)
+	Info(w.ctx, msg)
 
 	return len(p), nil
 }

s_test.go

@@ -2,6 +2,7 @@ package slog_test
 
 import (
 	"bytes"
+	"context"
 	"testing"
 
 	"cdr.dev/slog"
@@ -14,14 +15,16 @@ func TestStdlib(t *testing.T) {
 	t.Parallel()
 
 	b := &bytes.Buffer{}
-	l := slog.Make(sloghuman.Make(b)).With(
+	ctx := context.Background()
+	ctx = slog.Make(sloghuman.Make(ctx, b))
+	ctx = slog.With(ctx,
 		slog.F("hi", "we"),
 	)
-	stdlibLog := slog.Stdlib(bg, l)
+	stdlibLog := slog.Stdlib(ctx)
 	stdlibLog.Println("stdlib")
 
 	et, rest, err := entryhuman.StripTimestamp(b.String())
 	assert.Success(t, "strip timestamp", err)
 	assert.False(t, "timestamp", et.IsZero())
-	assert.Equal(t, "entry", " [INFO]\t(stdlib)\t<s_test.go:21>\tstdlib\t{\"hi\": \"we\"}\n", rest)
+	assert.Equal(t, "entry", " [INFO]\t(stdlib)\t<s_test.go:24>\tstdlib\t{\"hi\": \"we\"}\n", rest)
 }