From ed954785b264d2578383f7c91daa40749c430bed Mon Sep 17 00:00:00 2001 From: Olaoluwa Osuntokun Date: Tue, 6 Aug 2019 17:57:02 -0700 Subject: [PATCH] rpc: add unary+streaming interceptors to log all errors Not all errors that occur when serving client requests in the gRPC server are logged. As a result, at times, we can be lacking critic information that can be used to debug issues that pop up. With this PR, we create a basic streaming+unary interceptor that will log all errors that occur when servicing calls. The current format looks something like this in the logs when an error occurs: ``` [ERR] RPCS: [/lnrpc.Lightning/SendCoins]: decoded address is of unknown format ``` --- log.go | 35 +++++++++++++++++++++++++++++++++++ rpcserver.go | 9 +++++++++ 2 files changed, 44 insertions(+) diff --git a/log.go b/log.go index 7c0b429c..a59e96ad 100644 --- a/log.go +++ b/log.go @@ -1,6 +1,7 @@ package lnd import ( + "context" "fmt" "io" "os" @@ -37,6 +38,7 @@ import ( "github.com/lightningnetwork/lnd/sweep" "github.com/lightningnetwork/lnd/watchtower" "github.com/lightningnetwork/lnd/watchtower/wtclient" + "google.golang.org/grpc" ) // Loggers per subsystem. A single backend logger is created and all subsystem @@ -235,3 +237,36 @@ func (c logClosure) String() string { func newLogClosure(c func() string) logClosure { return logClosure(c) } + +// errorLogUnaryServerInterceptor is a simple UnaryServerInterceptor that will +// automatically log any errors that occur when serving a client's unary +// request. +func errorLogUnaryServerInterceptor(logger btclog.Logger) grpc.UnaryServerInterceptor { + return func(ctx context.Context, req interface{}, info *grpc.UnaryServerInfo, + handler grpc.UnaryHandler) (interface{}, error) { + + resp, err := handler(ctx, req) + if err != nil { + // TODO(roasbeef): also log request details? + logger.Errorf("[%v]: %v", info.FullMethod, err) + } + + return resp, err + } +} + +// errorLogStreamServerInterceptor is a simple StreamServerInterceptor that +// will log any errors that occur while processing a client or server streaming +// RPC. +func errorLogStreamServerInterceptor(logger btclog.Logger) grpc.StreamServerInterceptor { + return func(srv interface{}, ss grpc.ServerStream, + info *grpc.StreamServerInfo, handler grpc.StreamHandler) error { + + err := handler(srv, ss) + if err != nil { + logger.Errorf("[%v]: %v", info.FullMethod, err) + } + + return err + } +} diff --git a/rpcserver.go b/rpcserver.go index 1363df26..61e86d9d 100644 --- a/rpcserver.go +++ b/rpcserver.go @@ -560,6 +560,15 @@ func newRPCServer(s *server, macService *macaroons.Service, unaryInterceptors := append(macUnaryInterceptors, promUnaryInterceptors...) strmInterceptors := append(macStrmInterceptors, promStrmInterceptors...) + // We'll also add our logging interceptors as well, so we can + // automatically log all errors that happen during RPC calls. + unaryInterceptors = append( + unaryInterceptors, errorLogUnaryServerInterceptor(rpcsLog), + ) + strmInterceptors = append( + strmInterceptors, errorLogStreamServerInterceptor(rpcsLog), + ) + // If any interceptors have been set up, add them to the server options. if len(unaryInterceptors) != 0 && len(strmInterceptors) != 0 { chainedUnary := grpc_middleware.WithUnaryServerChain(