Request Logging

interceptors/logging/interceptors.go

@@ -25,34 +25,55 @@ type reporter struct {
 	ctx             context.Context
 	typ             interceptors.GRPCType
 	service, method string
+	startCallLogged bool
+	opts            *options
+	logger          Logger
+	kind            string
+}
 
-	opts   *options
-	logger Logger
-
-	kind string
+func (c *reporter) logMessage(logger Logger, err error, msg string, duration time.Duration) {
+	code := c.opts.codeFunc(err)
+	logger = logger.With("grpc.code", code.String())
+	if err != nil {
+		logger = logger.With("grpc.error", fmt.Sprintf("%v", err))
+	}
+	logger = logger.With(extractFields(tags.Extract(c.ctx))...)
+	logger.With(c.opts.durationFieldFunc(duration)...).Log(c.opts.levelFunc(code), msg)
 }
 
 func (c *reporter) PostCall(err error, duration time.Duration) {
-	if !c.opts.shouldLog(interceptors.FullMethod(c.service, c.method), err) {
+	switch c.opts.shouldLog(interceptors.FullMethod(c.service, c.method)) {
+	case LogFinishCall, LogStartAndFinishCall:
+		if err == io.EOF {
+			err = nil
+		}
+		c.logMessage(c.logger, err, "finished call", duration)
+	default:
 		return
 	}
-	if err == io.EOF {
-		err = nil
-	}
-	// Get optional, fresh tags.
-	logger := c.logger.With(extractFields(tags.Extract(c.ctx))...)
+}
 
-	code := c.opts.codeFunc(err)
-	logger = logger.With("grpc.code", code.String())
-	if err != nil {
-		logger = logger.With("error", fmt.Sprintf("%v", err))
+func (c *reporter) PostMsgSend(_ interface{}, err error, duration time.Duration) {
+	if c.startCallLogged {
+		return
+	}
+	switch c.opts.shouldLog(interceptors.FullMethod(c.service, c.method)) {
+	case LogStartAndFinishCall:
+		c.startCallLogged = true
+		c.logMessage(c.logger, err, "started call", duration)
 	}
-	logger.With(c.opts.durationFieldFunc(duration)...).Log(c.opts.levelFunc(code), fmt.Sprintf("finished %s %s call", c.kind, c.typ))
 }
 
-func (c *reporter) PostMsgSend(interface{}, error, time.Duration) {}
-
-func (c *reporter) PostMsgReceive(interface{}, error, time.Duration) {}
+func (c *reporter) PostMsgReceive(_ interface{}, err error, duration time.Duration) {
+	if c.startCallLogged {
+		return
+	}
+	switch c.opts.shouldLog(interceptors.FullMethod(c.service, c.method)) {
+	case LogStartAndFinishCall:
+		c.startCallLogged = true
+		c.logMessage(c.logger, err, "started call", duration)
+	}
+}
 
 type reportable struct {
 	opts   *options
@@ -74,13 +95,14 @@ func (r *reportable) reporter(ctx context.Context, typ interceptors.GRPCType, se
 		fields = append(fields, "grpc.request.deadline", d.Format(time.RFC3339))
 	}
 	return &reporter{
-		ctx:     ctx,
-		typ:     typ,
-		service: service,
-		method:  method,
-		opts:    r.opts,
-		logger:  r.logger.With(fields...),
-		kind:    kind,
+		ctx:             ctx,
+		typ:             typ,
+		service:         service,
+		method:          method,
+		startCallLogged: false,
+		opts:            r.opts,
+		logger:          r.logger.With(fields...),
+		kind:            kind,
 	}, ctx
 }
 

interceptors/logging/logging.go

@@ -14,10 +14,23 @@ import (
 	"github.com/grpc-ecosystem/go-grpc-middleware/v2/interceptors"
 )
 
+// Decision defines rules for enabling start and end of logging.
+type Decision int
+
+const (
+	// NoLogCall - Logging is disabled.
+	NoLogCall Decision = iota
+	// LogFinishCall - Only finish logs of request is enabled.
+	LogFinishCall
+	// LogStartAndFinishCall - Logging of start and end of request is enabled.
+	LogStartAndFinishCall
+)
+
 var (
 	// SystemTag is tag representing an event inside gRPC call.
-	SystemTag            = []string{"system", "grpc"}
-	KindFieldKey         = "kind"
+	SystemTag = []string{"protocol", "grpc"}
+	// ComponentFieldKey is a tag representing the client/server that is calling.
+	ComponentFieldKey    = "grpc.component"
 	KindServerFieldValue = "server"
 	KindClientFieldValue = "client"
 	ServiceFieldKey      = "grpc.service"
@@ -28,7 +41,7 @@ var (
 func commonFields(kind string, typ interceptors.GRPCType, service string, method string) Fields {
 	return Fields{
 		SystemTag[0], SystemTag[1],
-		KindFieldKey, kind,
+		ComponentFieldKey, kind,
 		ServiceFieldKey, service,
 		MethodFieldKey, method,
 		MethodTypeFieldKey, string(typ),
@@ -47,12 +60,12 @@ func DefaultErrorToCode(err error) codes.Code {
 }
 
 // Decider function defines rules for suppressing any interceptor logs
-type Decider func(fullMethodName string, err error) bool
+type Decider func(fullMethodName string) Decision
 
 // DefaultDeciderMethod is the default implementation of decider to see if you should log the call
 // by default this if always true so all calls are logged
-func DefaultDeciderMethod(_ string, _ error) bool {
-	return true
+func DefaultDeciderMethod(_ string) Decision {
+	return LogStartAndFinishCall
 }
 
 // ServerPayloadLoggingDecider is a user-provided function for deciding whether to log the server-side

providers/kit/examples_test.go

@@ -79,14 +79,13 @@ func ExampleWithDecider() {
 	logger := log.NewNopLogger()
 	// Shared options for the logger, with a custom decider that log everything except successful calls from "/blah.foo.healthcheck/Check" method.
 	opts := []logging.Option{
-		logging.WithDecider(func(methodFullName string, err error) bool {
+		logging.WithDecider(func(methodFullName string) logging.Decision {
 			// will not log gRPC calls if it was a call to healthcheck and no error was raised
-			if err == nil && methodFullName == "/blah.foo.healthcheck/Check" {
-				return false
+			if methodFullName == "/blah.foo.healthcheck/Check" {
+				return logging.NoLogCall
 			}
-
 			// by default you will log all calls
-			return true
+			return logging.LogStartAndFinishCall
 		}),
 	}
 	// Create a server, make sure we put the tags context before everything else.

providers/logrus/examples_test.go

@@ -79,14 +79,14 @@ func ExampleWithDecider() {
 	logger := logrus.New()
 	// Shared options for the logger, with a custom decider that log everything except successful calls from "/blah.foo.healthcheck/Check" method.
 	opts := []logging.Option{
-		logging.WithDecider(func(methodFullName string, err error) bool {
+		logging.WithDecider(func(methodFullName string) logging.Decision {
 			// will not log gRPC calls if it was a call to healthcheck and no error was raised
-			if err == nil && methodFullName == "/blah.foo.healthcheck/Check" {
-				return false
+			if methodFullName == "/blah.foo.healthcheck/Check" {
+				return logging.NoLogCall
 			}
 
 			// by default you will log all calls
-			return true
+			return logging.LogStartAndFinishCall
 		}),
 	}
 	// Create a server, make sure we put the tags context before everything else.

providers/zap/examples_test.go

@@ -79,14 +79,14 @@ func ExampleWithDecider() {
 	logger := zap.NewNop()
 	// Shared options for the logger, with a custom decider that log everything except successful calls from "/blah.foo.healthcheck/Check" method.
 	opts := []logging.Option{
-		logging.WithDecider(func(methodFullName string, err error) bool {
+		logging.WithDecider(func(methodFullName string) logging.Decision {
 			// will not log gRPC calls if it was a call to healthcheck and no error was raised
-			if err == nil && methodFullName == "/blah.foo.healthcheck/Check" {
-				return false
+			if methodFullName == "/blah.foo.healthcheck/Check" {
+				return logging.NoLogCall
 			}
 
 			// by default you will log all calls
-			return true
+			return logging.LogStartAndFinishCall
 		}),
 	}
 	// Create a server, make sure we put the tags context before everything else.

providers/zerolog/examples_test.go

@@ -81,14 +81,14 @@ func ExampleWithDecider() {
 	// Shared options for the logger, with a custom decider that log everything except successful
 	// calls from "/blah.foo.healthcheck/Check" method.
 	opts := []logging.Option{
-		logging.WithDecider(func(methodFullName string, err error) bool {
+		logging.WithDecider(func(methodFullName string) logging.Decision {
 			// will not log gRPC calls if it was a call to healthcheck and no error was raised
-			if err == nil && methodFullName == "/blah.foo.healthcheck/Check" {
-				return false
+			if methodFullName == "/blah.foo.healthcheck/Check" {
+				return logging.NoLogCall
 			}
 
 			// by default you will log all calls
-			return true
+			return logging.LogStartAndFinishCall
 		}),
 	}
 	// Create a server, make sure we put the tags context before everything else.