Add zerolog logging middleware

README.md

@@ -58,7 +58,7 @@ myServer := grpc.NewServer(
    * [`grpc_ctxtags`](tags/) - a library that adds a `Tag` map to context, with data populated from request body
    * [`grpc_zap`](logging/zap/) - integration of [zap](https://github.com/uber-go/zap) logging library into gRPC handlers.
    * [`grpc_logrus`](logging/logrus/) - integration of [logrus](https://github.com/sirupsen/logrus) logging library into gRPC handlers.
-
+   * [`grpc_zerolog`](logging/zerolog/) - integration of [zerolog](https://github.com/rs/zerolog) logging library into gRPC handlers.
 
 #### Monitoring
    * [`grpc_prometheus`⚡](https://github.com/grpc-ecosystem/go-grpc-prometheus) - Prometheus client-side and server-side monitoring middleware

logging/doc.go

@@ -28,7 +28,7 @@ https://github.com/opentracing/specification/blob/master/semantic_conventions.md
 
 Implementations
 
-There are two implementations at the moment: logrus and zap
+There are three implementations at the moment: logrus, zap and zerolog
 
 See relevant packages below.
 */

logging/zap/payload_interceptors.go

@@ -33,7 +33,7 @@ func PayloadUnaryServerInterceptor(logger *zap.Logger, decider grpc_logging.Serv
 		logProtoMessageAsJson(logEntry, req, "grpc.request.content", "server request payload logged as grpc.request.content field")
 		resp, err := handler(ctx, req)
 		if err == nil {
-			logProtoMessageAsJson(logEntry, resp, "grpc.response.content", "server response payload logged as grpc.request.content field")
+			logProtoMessageAsJson(logEntry, resp, "grpc.response.content", "server response payload logged as grpc.response.content field")
 		}
 		return resp, err
 	}

logging/zerolog/client_interceptors.go

@@ -0,0 +1,62 @@
+package zerolog
+
+import (
+	"context"
+	"github.com/grpc-ecosystem/go-grpc-middleware/logging/zerolog/ctxzr"
+	"github.com/rs/zerolog"
+	"google.golang.org/grpc"
+	"path"
+	"time"
+)
+
+// UnaryClientInterceptor returns a new unary client interceptor that optionally logs the execution of external gRPC calls.
+func UnaryClientInterceptor(logger *zerolog.Logger, opts ...Option) grpc.UnaryClientInterceptor {
+	o := evaluateClientOpt(opts)
+	return func(ctx context.Context, method string, req, reply interface{}, cc *grpc.ClientConn, invoker grpc.UnaryInvoker, opts ...grpc.CallOption) error {
+		fields := newClientLoggerFields(ctx, method)
+		startTime := time.Now()
+		err := invoker(ctx, method, req, reply, cc, opts...)
+		logFinalClientLine(o, &ctxzr.CtxLogger{Logger: logger, Fields: fields}, startTime, err, "finished client unary call")
+		return err
+	}
+}
+
+// StreamClientInterceptor returns a new streaming client interceptor that optionally logs the execution of external gRPC calls.
+func StreamClientInterceptor(logger *zerolog.Logger, opts ...Option) grpc.StreamClientInterceptor {
+	o := evaluateClientOpt(opts)
+	return func(ctx context.Context, desc *grpc.StreamDesc, cc *grpc.ClientConn, method string, streamer grpc.Streamer, opts ...grpc.CallOption) (grpc.ClientStream, error) {
+		fields := newClientLoggerFields(ctx, method)
+		startTime := time.Now()
+		clientStream, err := streamer(ctx, desc, cc, method, opts...)
+		logFinalClientLine(o, &ctxzr.CtxLogger{Logger: logger, Fields: fields}, startTime, err, "finished client streaming call")
+		return clientStream, err
+	}
+}
+
+func logFinalClientLine(o *options, logger *ctxzr.CtxLogger, startTime time.Time, err error, msg string) {
+	code  := o.codeFunc(err)
+	level := o.levelFunc(code)
+
+	clientLogger := logger.Logger.WithLevel(level).Err(err)
+	args := make(map[string]interface{})
+	args["grpc.code"] = code.String()
+
+	for k, v := range logger.Fields {
+		args[k] = v
+	}
+	args["msg"] = msg
+	clientLogger.Fields(args)
+	// Add Duration to Fields and Send
+	o.durationFunc(clientLogger.Fields(args), time.Since(startTime)).Send()
+}
+
+func newClientLoggerFields(ctx context.Context, fullMethodString string) map[string]interface{} {
+	service := path.Dir(fullMethodString)[1:]
+	method := path.Base(fullMethodString)
+	return map[string]interface{}{
+		"system":       "grpc",
+		"span.kind":    "client",
+		"grpc.service": service,
+		"grpc.method":  method,
+	}
+}

logging/zerolog/client_interceptors_test.go

@@ -0,0 +1,187 @@
+package grpc_zerolog_test
+
+import (
+	grpc_zerolog "github.com/grpc-ecosystem/go-grpc-middleware/logging/zerolog"
+	"github.com/rs/zerolog"
+	"io"
+	"runtime"
+	"strings"
+	"testing"
+
+	pb_testproto "github.com/grpc-ecosystem/go-grpc-middleware/testing/testproto"
+	"github.com/stretchr/testify/assert"
+	"github.com/stretchr/testify/require"
+	"github.com/stretchr/testify/suite"
+	"google.golang.org/grpc"
+	"google.golang.org/grpc/codes"
+)
+
+func customClientCodeToLevel(c codes.Code) zerolog.Level {
+	if c == codes.Unauthenticated {
+		// Make this a special case for tests, and an error.
+		return zerolog.ErrorLevel
+	}
+	return grpc_zerolog.DefaultClientCodeToLevel(c)
+}
+
+func TestZRClientSuite(t *testing.T) {
+	if strings.HasPrefix(runtime.Version(), "go1.7") {
+		t.Skipf("Skipping due to json.RawMessage incompatibility with go1.7")
+		return
+	}
+	opts := []grpc_zerolog.Option{
+		grpc_zerolog.WithLevels(customClientCodeToLevel),
+	}
+	b := newZRBaseSuite(t)
+	zerolog.SetGlobalLevel(zerolog.DebugLevel)
+	b.InterceptorTestSuite.ClientOpts = []grpc.DialOption{
+		grpc.WithUnaryInterceptor(grpc_zerolog.UnaryClientInterceptor(b.logger.Logger, opts...)),
+		grpc.WithStreamInterceptor(grpc_zerolog.StreamClientInterceptor(b.logger.Logger, opts...)),
+	}
+	suite.Run(t, &ZRClientSuite{b})
+}
+
+type ZRClientSuite struct {
+	*ZRBaseSuite
+}
+
+func (s *ZRClientSuite) TestPing() {
+	_, err := s.Client.Ping(s.SimpleCtx(), goodPing)
+	assert.NoError(s.T(), err, "there must be not be an on a successful call")
+
+	msgs := s.getOutputJSONs()
+	require.Len(s.T(), msgs, 1, "one log statement should be logged")
+
+	assert.Equal(s.T(), msgs[0]["grpc.service"], "mwitkow.testproto.TestService", "all lines must contain the correct service name")
+	assert.Equal(s.T(), msgs[0]["grpc.method"], "Ping", "all lines must contain the correct method name")
+	assert.Equal(s.T(), msgs[0]["msg"], "finished client unary call", "handler's message must contain the correct message")
+	assert.Equal(s.T(), msgs[0]["span.kind"], "client", "all lines must contain the kind of call (client)")
+	assert.Equal(s.T(), msgs[0]["level"], "debug", "OK codes must be logged on debug level.")
+
+	assert.Contains(s.T(), msgs[0], "grpc.time_ms", "interceptor log statement should contain execution time (duration in ms)")
+}
+
+func (s *ZRClientSuite) TestPingList() {
+	stream, err := s.Client.PingList(s.SimpleCtx(), goodPing)
+	require.NoError(s.T(), err, "should not fail on establishing the stream")
+	for {
+		_, err := stream.Recv()
+		if err == io.EOF {
+			break
+		}
+		require.NoError(s.T(), err, "reading stream should not fail")
+	}
+
+	msgs := s.getOutputJSONs()
+	require.Len(s.T(), msgs, 1, "one log statement should be logged")
+
+	assert.Equal(s.T(), msgs[0]["grpc.service"], "mwitkow.testproto.TestService", "all lines must contain the correct service name")
+	assert.Equal(s.T(), msgs[0]["grpc.method"], "PingList", "all lines must contain the correct method name")
+	assert.Equal(s.T(), msgs[0]["msg"], "finished client streaming call", "handler's message must contain the correct message")
+	assert.Equal(s.T(), msgs[0]["span.kind"], "client", "all lines must contain the kind of call (client)")
+	assert.Equal(s.T(), msgs[0]["level"], "debug", "OK codes must be logged on debug level.")
+	assert.Contains(s.T(), msgs[0], "grpc.time_ms", "interceptor log statement should contain execution time (duration in ms)")
+}
+
+func (s *ZRClientSuite) TestPingError_WithCustomLevels() {
+	for _, tcase := range []struct {
+		code  codes.Code
+		level zerolog.Level
+		msg   string
+	}{
+		{
+			code:  codes.Internal,
+			level: zerolog.WarnLevel,
+			msg:   "Internal must remap to WarnLevel in DefaultClientCodeToLevel",
+		},
+		{
+			code:  codes.NotFound,
+			level: zerolog.DebugLevel,
+			msg:   "NotFound must remap to DebugLevel in DefaultClientCodeToLevel",
+		},
+		{
+			code:  codes.FailedPrecondition,
+			level: zerolog.DebugLevel,
+			msg:   "FailedPrecondition must remap to DebugLevel in DefaultClientCodeToLevel",
+		},
+		{
+			code:  codes.Unauthenticated,
+			level: zerolog.ErrorLevel,
+			msg:   "Unauthenticated is overwritten to ErrorLevel with customClientCodeToLevel override, which probably didn't work",
+		},
+	} {
+		s.SetupTest()
+		_, err := s.Client.PingError(
+			s.SimpleCtx(),
+			&pb_testproto.PingRequest{Value: "something", ErrorCodeReturned: uint32(tcase.code)})
+
+		assert.Error(s.T(), err, "each call here must return an error")
+
+		msgs := s.getOutputJSONs()
+		require.Len(s.T(), msgs, 1, "only a single log message is printed")
+
+		assert.Equal(s.T(), msgs[0]["grpc.service"], "mwitkow.testproto.TestService", "all lines must contain the correct service name")
+		assert.Equal(s.T(), msgs[0]["grpc.method"], "PingError", "all lines must contain the correct method name")
+		assert.Equal(s.T(), msgs[0]["grpc.code"], tcase.code.String(), "all lines must contain a grpc code")
+		assert.Equal(s.T(), msgs[0]["level"], tcase.level.String(), tcase.msg)
+	}
+}
+
+func TestZRClientOverrideSuite(t *testing.T) {
+	if strings.HasPrefix(runtime.Version(), "go1.7") {
+		t.Skip("Skipping due to json.RawMessage incompatibility with go1.7")
+		return
+	}
+	opts := []grpc_zerolog.Option{
+		grpc_zerolog.WithDurationField(grpc_zerolog.DurationToDurationField),
+	}
+	b := newZRBaseSuite(t)
+	zerolog.SetGlobalLevel(zerolog.DebugLevel)
+	b.InterceptorTestSuite.ClientOpts = []grpc.DialOption{
+		grpc.WithUnaryInterceptor(grpc_zerolog.UnaryClientInterceptor(b.logger.Logger, opts...)),
+		grpc.WithStreamInterceptor(grpc_zerolog.StreamClientInterceptor(b.logger.Logger, opts...)),
+	}
+	suite.Run(t, &ZRClientOverrideSuite{b})
+}
+
+type ZRClientOverrideSuite struct {
+	*ZRBaseSuite
+}
+
+func (s *ZRClientOverrideSuite) TestPing_HasOverrides() {
+	_, err := s.Client.Ping(s.SimpleCtx(), goodPing)
+	assert.NoError(s.T(), err, "there must be not be an on a successful call")
+
+	msgs := s.getOutputJSONs()
+	require.Len(s.T(), msgs, 1, "one log statement should be logged")
+	assert.Equal(s.T(), msgs[0]["grpc.service"], "mwitkow.testproto.TestService", "all lines must contain the correct service name")
+	assert.Equal(s.T(), msgs[0]["grpc.method"], "Ping", "all lines must contain the correct method name")
+	assert.Equal(s.T(), msgs[0]["msg"], "finished client unary call", "handler's message must contain the correct message")
+
+	assert.NotContains(s.T(), msgs[0], "grpc.time_ms", "message must not contain default duration")
+	assert.Contains(s.T(), msgs[0], "grpc.duration", "message must contain overridden duration")
+}
+
+func (s *ZRClientOverrideSuite) TestPingList_HasOverrides() {
+	stream, err := s.Client.PingList(s.SimpleCtx(), goodPing)
+	require.NoError(s.T(), err, "should not fail on establishing the stream")
+	for {
+		_, err := stream.Recv()
+		if err == io.EOF {
+			break
+		}
+		require.NoError(s.T(), err, "reading stream should not fail")
+	}
+
+	msgs := s.getOutputJSONs()
+	require.Len(s.T(), msgs, 1, "one log statement should be logged")
+
+	assert.Equal(s.T(), msgs[0]["grpc.service"], "mwitkow.testproto.TestService", "all lines must contain the correct service name")
+	assert.Equal(s.T(), msgs[0]["grpc.method"], "PingList", "all lines must contain the correct method name")
+	assert.Equal(s.T(), msgs[0]["msg"], "finished client streaming call", "log message must be correct")
+	assert.Equal(s.T(), msgs[0]["span.kind"], "client", "all lines must contain the kind of call (client)")
+	assert.Equal(s.T(), msgs[0]["level"], "debug", "OK codes must be logged on debug level.")
+
+	assert.NotContains(s.T(), msgs[0], "grpc.time_ms", "message must not contain default duration")
+	assert.Contains(s.T(), msgs[0], "grpc.duration", "message must contain overridden duration")
+}

logging/zerolog/ctxzr/context.go

@@ -0,0 +1,80 @@
+package ctxzr
+
+import (
+	"context"
+	grpc_ctxtags "github.com/grpc-ecosystem/go-grpc-middleware/tags"
+	"github.com/rs/zerolog"
+)
+
+type ctxMarker struct{}
+
+type CtxLogger struct {
+	Logger *zerolog.Logger
+	Fields map[string]interface{}
+}
+
+var (
+	ctxMarkerKey = &ctxMarker{}
+	nullLogger   = &zerolog.Logger{}
+)
+
+func MergeFields(mp1 map[string]interface{}, mp2 map[string]interface{}) map[string]interface{} {
+
+	mp3 := make(map[string]interface{}, 0)
+	for k, v := range mp1 {
+		if _, ok := mp1[k]; ok {
+			mp3[k] = v
+		}
+	}
+
+	for k, v := range mp2 {
+		if _, ok := mp2[k]; ok {
+			mp3[k] = v
+		}
+	}
+	return mp3
+}
+
+// AddFields adds fields to the logger.
+func AddFields(ctx context.Context, fields map[string]interface{}) {
+	l, ok := ctx.Value(ctxMarkerKey).(*CtxLogger)
+	if !ok || l == nil {
+		return
+	}
+
+	for k, v := range fields {
+		l.Fields[k] = v
+	}
+
+}
+
+// Extract takes the call-scoped Logger from grpc middleware.
+//
+// It always returns a Logger that has all the grpc_ctxtags updated.
+func Extract(ctx context.Context) *CtxLogger {
+	l, ok := ctx.Value(ctxMarkerKey).(*CtxLogger)
+	if !ok || l == nil {
+		return &CtxLogger{Logger: nullLogger, Fields: make(map[string]interface{}, 0)}
+	}
+	// Add grpc_ctxtags tags metadata until now.
+	fields := TagsToFields(ctx)
+	// Addfields added until now.
+	fields = MergeFields(fields, l.Fields)
+	return &CtxLogger{Logger: l.Logger, Fields: fields}
+}
+
+// TagsToFields transforms the Tags on the supplied context into zap fields.
+func TagsToFields(ctx context.Context) map[string]interface{} {
+	fields := make(map[string]interface{}, 0)
+	tags := grpc_ctxtags.Extract(ctx)
+	for k, v := range tags.Values() {
+		fields[k] = v
+	}
+	return fields
+}
+
+// ToContext adds the zerolog.Logger to the context for extraction later.
+// Returning the new context that has been created.
+func ToContext(ctx context.Context, logger *CtxLogger) context.Context {
+	return context.WithValue(ctx, ctxMarkerKey, logger)
+}

logging/zerolog/ctxzr/examples_test.go

@@ -0,0 +1,23 @@
+package ctxzr_test
+
+import (
+	"context"
+	"github.com/grpc-ecosystem/go-grpc-middleware/logging/zerolog/ctxzr"
+	"github.com/grpc-ecosystem/go-grpc-middleware/tags"
+	pb_testproto "github.com/grpc-ecosystem/go-grpc-middleware/testing/testproto"
+)
+
+// Simple unary handler that adds custom fields to the requests's context. These will be used for all log statements.
+func ExampleExtract_unary() {
+	_ = func(ctx context.Context, ping *pb_testproto.PingRequest) (*pb_testproto.PingResponse, error) {
+		// Add fields the ctxtags of the request which will be added to all extracted loggers.
+		grpc_ctxtags.Extract(ctx).Set("custom_tags.string", "something").Set("custom_tags.int", 1337)
+
+		// Extract a single request-scoped zap.Logger and log messages.
+		l := ctxzr.Extract(ctx)
+		l.Fields["msg1"] = "some ping"
+		l.Fields["msg1"] = "another ping"
+		l.Logger.Info().Fields(l.Fields).Send()
+		return &pb_testproto.PingResponse{Value: ping.Value}, nil
+	}
+}