Skip to content

Commit

Permalink
Add common logger with specific fields (#188)
Browse files Browse the repository at this point in the history
* Add common logger with specific fields

* Add common logger, interceptors with customizable fields

* Fix populating context

* Fix unused arguments

* Fix duplicate append ctx call, rename auxilary func name

* Add custom fields from request headers

* Add err handling if subject key is missing

* Add err handling in case request_id missing
  • Loading branch information
addudko committed Apr 30, 2020
1 parent 47e34f8 commit 6bd86d4
Show file tree
Hide file tree
Showing 3 changed files with 279 additions and 25 deletions.
32 changes: 8 additions & 24 deletions logging/gateway_interceptor.go
Original file line number Diff line number Diff line change
Expand Up @@ -7,14 +7,16 @@ import (

jwt "github.com/dgrijalva/jwt-go"
"github.com/google/uuid"
"github.com/grpc-ecosystem/go-grpc-middleware/logging/logrus"
grpc_logrus "github.com/grpc-ecosystem/go-grpc-middleware/logging/logrus"
"github.com/grpc-ecosystem/go-grpc-middleware/logging/logrus/ctxlogrus"
"github.com/infobloxopen/atlas-app-toolkit/auth"
"github.com/infobloxopen/atlas-app-toolkit/gateway"
"github.com/infobloxopen/atlas-app-toolkit/requestid"
"github.com/sirupsen/logrus"
"google.golang.org/grpc"
"google.golang.org/grpc/metadata"
"google.golang.org/grpc/status"

"github.com/infobloxopen/atlas-app-toolkit/auth"
"github.com/infobloxopen/atlas-app-toolkit/gateway"
"github.com/infobloxopen/atlas-app-toolkit/requestid"
)

type gwLogCfg struct {
Expand Down Expand Up @@ -160,7 +162,7 @@ func GatewayLoggingInterceptor(logger *logrus.Logger, opts ...GWLogOption) grpc.
durField, durVal := grpc_logrus.DurationToTimeMillisField(time.Now().Sub(startTime))
fields = logrus.Fields{
durField: durVal,
"grpc.code": grpc.Code(err).String(),
"grpc.code": status.Code(err).String(),
}
// set error message field
if err != nil {
Expand All @@ -169,7 +171,7 @@ func GatewayLoggingInterceptor(logger *logrus.Logger, opts ...GWLogOption) grpc.

// print log message with all fields
resLogger = resLogger.WithFields(fields)
levelLogf(resLogger, cfg.codeToLevel(grpc.Code(err)), "finished client unary call with code "+grpc.Code(err).String())
levelLogf(resLogger, cfg.codeToLevel(status.Code(err)), "finished client unary call with code "+status.Code(err).String())

return
}
Expand All @@ -192,21 +194,3 @@ func GatewayLoggingSentinelInterceptor() grpc.UnaryClientInterceptor {
return invoker(ctx, method, req, reply, cc, opts...)
}
}

// From https://github.com/grpc-ecosystem/go-grpc-middleware/blob/cfaf5686ec79ff8344257723b6f5ba1ae0ffeb4d/logging/logrus/server_interceptors.go#L91
func levelLogf(entry *logrus.Entry, level logrus.Level, format string, args ...interface{}) {
switch level {
case logrus.DebugLevel:
entry.Debugf(format, args...)
case logrus.InfoLevel:
entry.Infof(format, args...)
case logrus.WarnLevel:
entry.Warningf(format, args...)
case logrus.ErrorLevel:
entry.Errorf(format, args...)
case logrus.FatalLevel:
entry.Fatalf(format, args...)
case logrus.PanicLevel:
entry.Panicf(format, args...)
}
}
180 changes: 179 additions & 1 deletion logging/interceptor.go
Original file line number Diff line number Diff line change
Expand Up @@ -2,11 +2,34 @@ package logging

import (
"context"
"fmt"
"path"
"strings"
"time"

grpc_logrus "github.com/grpc-ecosystem/go-grpc-middleware/logging/logrus"
"github.com/grpc-ecosystem/go-grpc-middleware/logging/logrus/ctxlogrus"
"github.com/infobloxopen/atlas-app-toolkit/gateway"
"github.com/sirupsen/logrus"
"google.golang.org/grpc"
"google.golang.org/grpc/metadata"
"google.golang.org/grpc/status"

"github.com/infobloxopen/atlas-app-toolkit/auth"
"github.com/infobloxopen/atlas-app-toolkit/gateway"
"github.com/infobloxopen/atlas-app-toolkit/requestid"
)

const (
DefaultAccountIDKey = "account_id"
DefaultRequestIDKey = "request_id"
DefaultSubjectKey = "subject" // Might be used for different purposes
DefaultDurationKey = "grpc.time_ms"
DefaultGRPCCodeKey = "grpc.code"
DefaultGRPCMethodKey = "grpc.method"
DefaultGRPCServiceKey = "grpc.service"
DefaultGRPCStartTimeKey = "grpc.start_time"
DefaultClientKindValue = "client"
DefaultServerKindValue = "server"
)

// LogLevelInterceptor sets the level of the logger in the context to either
Expand Down Expand Up @@ -39,6 +62,161 @@ func LogLevelInterceptor(defaultLevel logrus.Level) grpc.UnaryServerInterceptor
}
}

func UnaryClientInterceptor(logger *logrus.Logger, opts ...Option) grpc.UnaryClientInterceptor {
options := initOptions(opts)

return func(ctx context.Context, method string, req, reply interface{}, cc *grpc.ClientConn, invoker grpc.UnaryInvoker, opts ...grpc.CallOption) error {
startTime := time.Now()
fields := newLoggerFields(method, startTime, DefaultClientKindValue)

ctx = setInterceptorFields(ctx, fields, logger, options, startTime)

err := invoker(ctx, method, req, reply, cc, opts...)
if err != nil {
fields[logrus.ErrorKey] = err
}

code := status.Code(err)
fields[DefaultGRPCCodeKey] = code.String()

levelLogf(
logrus.NewEntry(logger).WithFields(fields),
options.codeToLevel(code),
"finished unary call with code "+code.String())

return err
}
}

func UnaryServerInterceptor(logger *logrus.Logger, opts ...Option) grpc.UnaryServerInterceptor {
options := initOptions(opts)

return func(ctx context.Context, req interface{}, info *grpc.UnaryServerInfo, handler grpc.UnaryHandler) (interface{}, error) {
startTime := time.Now()
fields := newLoggerFields(info.FullMethod, startTime, DefaultServerKindValue)
newCtx := newLoggerForCall(ctx, logrus.NewEntry(logger), fields)

newCtx = setInterceptorFields(newCtx, fields, logger, options, startTime)

resp, err := handler(newCtx, req)
if err != nil {
fields[logrus.ErrorKey] = err
}

code := status.Code(err)
fields[DefaultGRPCCodeKey] = code.String()

levelLogf(
ctxlogrus.Extract(newCtx).WithFields(fields),
options.codeToLevel(code),
"finished unary call with code "+code.String())

return resp, err
}
}

func setInterceptorFields(ctx context.Context, fields logrus.Fields, logger *logrus.Logger, options *options, start time.Time) context.Context {
// In latest versions of Go use
// https://golang.org/src/time/time.go?s=25178:25216#L780
duration := int64(time.Since(start) / 1e6)
fields[DefaultDurationKey] = duration

ctx, err := addRequestIDField(ctx, fields)
if err != nil {
logger.Warn(err)
}

ctx, err = addAccountIDField(ctx, fields)
if err != nil {
logger.Warn(err)
}

ctx, err = addCustomField(ctx, fields, DefaultSubjectKey)
if err != nil {
logger.Warn(err)
}

for _, v := range options.fields {
ctx, err = addCustomField(ctx, fields, v)
if err != nil {
logger.Warn(err)
}
}

for _, v := range options.headers {
ctx, err = addHeaderField(ctx, fields, v)
if err != nil {
logger.Warn(err)
}
}

return ctx
}

func addRequestIDField(ctx context.Context, fields logrus.Fields) (context.Context, error) {
reqID, exists := requestid.FromContext(ctx)
if !exists || reqID == "" {
return ctx, fmt.Errorf("Unable to get %q from context", DefaultRequestIDKey)
}

fields[DefaultRequestIDKey] = reqID

return metadata.AppendToOutgoingContext(ctx, DefaultRequestIDKey, reqID), nil
}

func addAccountIDField(ctx context.Context, fields logrus.Fields) (context.Context, error) {
accountID, err := auth.GetAccountID(ctx, nil)
if err != nil {
return ctx, fmt.Errorf("Unable to get %q from context", DefaultAccountIDKey)
}

fields[DefaultAccountIDKey] = accountID

return metadata.AppendToOutgoingContext(ctx, DefaultAccountIDKey, accountID), err
}

func addCustomField(ctx context.Context, fields logrus.Fields, customField string) (context.Context, error) {
field, err := auth.GetJWTField(ctx, customField, nil)
if err != nil {
return ctx, fmt.Errorf("Unable to get custom %q field from context", customField)
}

fields[customField] = field

return metadata.AppendToOutgoingContext(ctx, customField, field), err
}

func addHeaderField(ctx context.Context, fields logrus.Fields, header string) (context.Context, error) {
field, ok := gateway.Header(ctx, header)
if !ok {
return ctx, fmt.Errorf("Unable to get custom header %q from context", header)
}

fields[strings.ToLower(header)] = field

return metadata.AppendToOutgoingContext(ctx, header, field), nil
}

func newLoggerFields(fullMethodString string, start time.Time, kind string) logrus.Fields {
service := path.Dir(fullMethodString)[1:]
method := path.Base(fullMethodString)

return logrus.Fields{
grpc_logrus.SystemField: "grpc",
grpc_logrus.KindField: kind,
DefaultGRPCServiceKey: service,
DefaultGRPCMethodKey: method,
DefaultGRPCStartTimeKey: start.Format(time.RFC3339Nano),
}
}

func newLoggerForCall(ctx context.Context, entry *logrus.Entry, fields logrus.Fields) context.Context {
callLog := entry.WithFields(fields)
callLog = callLog.WithFields(ctxlogrus.Extract(ctx).Data)

return ctxlogrus.ToContext(ctx, callLog)
}

// CopyLoggerWithLevel makes a copy of the given (logrus) logger at the logger
// level. If copying an entry, use CopyLoggerWithLevel(entry.Logger, level).WithFields(entry.Data)
// on the result (changes to these entries' fields will not affect each other).
Expand Down
92 changes: 92 additions & 0 deletions logging/log.go
Original file line number Diff line number Diff line change
@@ -0,0 +1,92 @@
package logging

import (
"time"

grpc_logrus "github.com/grpc-ecosystem/go-grpc-middleware/logging/logrus"
"github.com/sirupsen/logrus"
"google.golang.org/grpc/codes"
)

func New(level string) *logrus.Logger {
log := logrus.New()

// Default timeFormat
log.SetFormatter(&logrus.JSONFormatter{
TimestampFormat: time.RFC3339Nano,
})

parsedLevel, err := logrus.ParseLevel(level)
if err != nil {
log.Errorf("Invalid %q level provided for log", level)
log.SetLevel(logrus.InfoLevel)
return log
}

log.SetLevel(parsedLevel)
return log
}

type options struct {
codeToLevel CodeToLevel
fields []string
headers []string
}

type Option func(*options)

func initOptions(opts []Option) *options {
o := &options{
codeToLevel: grpc_logrus.DefaultCodeToLevel,
}

for _, opt := range opts {
opt(o)
}

return o
}

// CodeToLevel function defines the mapping between gRPC return codes and interceptor log level.
// From https://github.com/grpc-ecosystem/go-grpc-middleware/blob/06f64829ca1f521d41cd6235a7a204a6566fb0dc/logging/logrus/options.go#L57
type CodeToLevel func(code codes.Code) logrus.Level

// WithLevels customizes the function for mapping gRPC return codes and interceptor log level statements.
// From https://github.com/grpc-ecosystem/go-grpc-middleware/blob/06f64829ca1f521d41cd6235a7a204a6566fb0dc/logging/logrus/options.go#L70
func WithLevels(f CodeToLevel) Option {
return func(o *options) {
o.codeToLevel = f
}
}

// Allows to provide custom fields for logging which are expected to be in JWT token
func WithCustomFields(fields []string) Option {
return func(o *options) {
o.fields = fields
}
}

// Allows to provide custom fields for logging from request headers
func WithCustomHeaders(headers []string) Option {
return func(o *options) {
o.headers = headers
}
}

// From https://github.com/grpc-ecosystem/go-grpc-middleware/blob/cfaf5686ec79ff8344257723b6f5ba1ae0ffeb4d/logging/logrus/server_interceptors.go#L91
func levelLogf(entry *logrus.Entry, level logrus.Level, format string, args ...interface{}) {
switch level {
case logrus.DebugLevel:
entry.Debugf(format, args...)
case logrus.InfoLevel:
entry.Infof(format, args...)
case logrus.WarnLevel:
entry.Warningf(format, args...)
case logrus.ErrorLevel:
entry.Errorf(format, args...)
case logrus.FatalLevel:
entry.Fatalf(format, args...)
case logrus.PanicLevel:
entry.Panicf(format, args...)
}
}

0 comments on commit 6bd86d4

Please sign in to comment.