lnd.xprv/log.go
Olaoluwa Osuntokun ed954785b2
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
```
2019-08-06 19:41:41 -07:00

273 lines
9.1 KiB
Go

package lnd
import (
"context"
"fmt"
"io"
"os"
"path/filepath"
"github.com/btcsuite/btcd/connmgr"
"github.com/btcsuite/btclog"
"github.com/jrick/logrotate/rotator"
"github.com/lightninglabs/neutrino"
sphinx "github.com/lightningnetwork/lightning-onion"
"github.com/lightningnetwork/lnd/autopilot"
"github.com/lightningnetwork/lnd/build"
"github.com/lightningnetwork/lnd/chainntnfs"
"github.com/lightningnetwork/lnd/chanbackup"
"github.com/lightningnetwork/lnd/channeldb"
"github.com/lightningnetwork/lnd/channelnotifier"
"github.com/lightningnetwork/lnd/contractcourt"
"github.com/lightningnetwork/lnd/discovery"
"github.com/lightningnetwork/lnd/htlcswitch"
"github.com/lightningnetwork/lnd/invoices"
"github.com/lightningnetwork/lnd/lnrpc/autopilotrpc"
"github.com/lightningnetwork/lnd/lnrpc/chainrpc"
"github.com/lightningnetwork/lnd/lnrpc/invoicesrpc"
"github.com/lightningnetwork/lnd/lnrpc/routerrpc"
"github.com/lightningnetwork/lnd/lnrpc/signrpc"
"github.com/lightningnetwork/lnd/lnrpc/walletrpc"
"github.com/lightningnetwork/lnd/lnrpc/wtclientrpc"
"github.com/lightningnetwork/lnd/lnwallet"
"github.com/lightningnetwork/lnd/monitoring"
"github.com/lightningnetwork/lnd/netann"
"github.com/lightningnetwork/lnd/peernotifier"
"github.com/lightningnetwork/lnd/routing"
"github.com/lightningnetwork/lnd/signal"
"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
// loggers created from it will write to the backend. When adding new
// subsystems, add the subsystem logger variable here and to the
// subsystemLoggers map.
//
// Loggers can not be used before the log rotator has been initialized with a
// log file. This must be performed early during application startup by
// calling initLogRotator.
var (
logWriter = &build.LogWriter{}
// backendLog is the logging backend used to create all subsystem
// loggers. The backend must not be used before the log rotator has
// been initialized, or data races and/or nil pointer dereferences will
// occur.
backendLog = btclog.NewBackend(logWriter)
// logRotator is one of the logging outputs. It should be closed on
// application shutdown.
logRotator *rotator.Rotator
ltndLog = build.NewSubLogger("LTND", backendLog.Logger)
lnwlLog = build.NewSubLogger("LNWL", backendLog.Logger)
peerLog = build.NewSubLogger("PEER", backendLog.Logger)
discLog = build.NewSubLogger("DISC", backendLog.Logger)
rpcsLog = build.NewSubLogger("RPCS", backendLog.Logger)
srvrLog = build.NewSubLogger("SRVR", backendLog.Logger)
ntfnLog = build.NewSubLogger("NTFN", backendLog.Logger)
chdbLog = build.NewSubLogger("CHDB", backendLog.Logger)
fndgLog = build.NewSubLogger("FNDG", backendLog.Logger)
hswcLog = build.NewSubLogger("HSWC", backendLog.Logger)
utxnLog = build.NewSubLogger("UTXN", backendLog.Logger)
brarLog = build.NewSubLogger("BRAR", backendLog.Logger)
cmgrLog = build.NewSubLogger("CMGR", backendLog.Logger)
crtrLog = build.NewSubLogger("CRTR", backendLog.Logger)
btcnLog = build.NewSubLogger("BTCN", backendLog.Logger)
atplLog = build.NewSubLogger("ATPL", backendLog.Logger)
cnctLog = build.NewSubLogger("CNCT", backendLog.Logger)
sphxLog = build.NewSubLogger("SPHX", backendLog.Logger)
swprLog = build.NewSubLogger("SWPR", backendLog.Logger)
sgnrLog = build.NewSubLogger("SGNR", backendLog.Logger)
wlktLog = build.NewSubLogger("WLKT", backendLog.Logger)
arpcLog = build.NewSubLogger("ARPC", backendLog.Logger)
invcLog = build.NewSubLogger("INVC", backendLog.Logger)
nannLog = build.NewSubLogger("NANN", backendLog.Logger)
wtwrLog = build.NewSubLogger("WTWR", backendLog.Logger)
ntfrLog = build.NewSubLogger("NTFR", backendLog.Logger)
irpcLog = build.NewSubLogger("IRPC", backendLog.Logger)
chnfLog = build.NewSubLogger("CHNF", backendLog.Logger)
chbuLog = build.NewSubLogger("CHBU", backendLog.Logger)
promLog = build.NewSubLogger("PROM", backendLog.Logger)
wtclLog = build.NewSubLogger("WTCL", backendLog.Logger)
prnfLog = build.NewSubLogger("PRNF", backendLog.Logger)
)
// Initialize package-global logger variables.
func init() {
lnwallet.UseLogger(lnwlLog)
discovery.UseLogger(discLog)
chainntnfs.UseLogger(ntfnLog)
channeldb.UseLogger(chdbLog)
htlcswitch.UseLogger(hswcLog)
connmgr.UseLogger(cmgrLog)
routing.UseLogger(crtrLog)
neutrino.UseLogger(btcnLog)
autopilot.UseLogger(atplLog)
contractcourt.UseLogger(cnctLog)
sphinx.UseLogger(sphxLog)
signal.UseLogger(ltndLog)
sweep.UseLogger(swprLog)
signrpc.UseLogger(sgnrLog)
walletrpc.UseLogger(wlktLog)
autopilotrpc.UseLogger(arpcLog)
invoices.UseLogger(invcLog)
netann.UseLogger(nannLog)
watchtower.UseLogger(wtwrLog)
chainrpc.UseLogger(ntfrLog)
invoicesrpc.UseLogger(irpcLog)
channelnotifier.UseLogger(chnfLog)
chanbackup.UseLogger(chbuLog)
monitoring.UseLogger(promLog)
wtclient.UseLogger(wtclLog)
peernotifier.UseLogger(prnfLog)
addSubLogger(routerrpc.Subsystem, routerrpc.UseLogger)
addSubLogger(wtclientrpc.Subsystem, wtclientrpc.UseLogger)
}
// addSubLogger is a helper method to conveniently register the logger of a sub
// system.
func addSubLogger(subsystem string, useLogger func(btclog.Logger)) {
logger := build.NewSubLogger(subsystem, backendLog.Logger)
useLogger(logger)
subsystemLoggers[subsystem] = logger
}
// subsystemLoggers maps each subsystem identifier to its associated logger.
var subsystemLoggers = map[string]btclog.Logger{
"LTND": ltndLog,
"LNWL": lnwlLog,
"PEER": peerLog,
"DISC": discLog,
"RPCS": rpcsLog,
"SRVR": srvrLog,
"NTFN": ntfnLog,
"CHDB": chdbLog,
"FNDG": fndgLog,
"HSWC": hswcLog,
"UTXN": utxnLog,
"BRAR": brarLog,
"CMGR": cmgrLog,
"CRTR": crtrLog,
"BTCN": btcnLog,
"ATPL": atplLog,
"CNCT": cnctLog,
"SPHX": sphxLog,
"SWPR": swprLog,
"SGNR": sgnrLog,
"WLKT": wlktLog,
"ARPC": arpcLog,
"INVC": invcLog,
"NANN": nannLog,
"WTWR": wtwrLog,
"NTFR": ntfrLog,
"IRPC": irpcLog,
"CHNF": chnfLog,
"CHBU": chbuLog,
"PROM": promLog,
"WTCL": wtclLog,
"PRNF": prnfLog,
}
// initLogRotator initializes the logging rotator to write logs to logFile and
// create roll files in the same directory. It must be called before the
// package-global log rotator variables are used.
func initLogRotator(logFile string, MaxLogFileSize int, MaxLogFiles int) {
logDir, _ := filepath.Split(logFile)
err := os.MkdirAll(logDir, 0700)
if err != nil {
fmt.Fprintf(os.Stderr, "failed to create log directory: %v\n", err)
os.Exit(1)
}
r, err := rotator.New(logFile, int64(MaxLogFileSize*1024), false, MaxLogFiles)
if err != nil {
fmt.Fprintf(os.Stderr, "failed to create file rotator: %v\n", err)
os.Exit(1)
}
pr, pw := io.Pipe()
go r.Run(pr)
logWriter.RotatorPipe = pw
logRotator = r
}
// setLogLevel sets the logging level for provided subsystem. Invalid
// subsystems are ignored. Uninitialized subsystems are dynamically created as
// needed.
func setLogLevel(subsystemID string, logLevel string) {
// Ignore invalid subsystems.
logger, ok := subsystemLoggers[subsystemID]
if !ok {
return
}
// Defaults to info if the log level is invalid.
level, _ := btclog.LevelFromString(logLevel)
logger.SetLevel(level)
}
// setLogLevels sets the log level for all subsystem loggers to the passed
// level. It also dynamically creates the subsystem loggers as needed, so it
// can be used to initialize the logging system.
func setLogLevels(logLevel string) {
// Configure all sub-systems with the new logging level. Dynamically
// create loggers as needed.
for subsystemID := range subsystemLoggers {
setLogLevel(subsystemID, logLevel)
}
}
// logClosure is used to provide a closure over expensive logging operations so
// don't have to be performed when the logging level doesn't warrant it.
type logClosure func() string
// String invokes the underlying function and returns the result.
func (c logClosure) String() string {
return c()
}
// newLogClosure returns a new closure over a function that returns a string
// which itself provides a Stringer interface so that it can be used with the
// logging system.
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
}
}