log.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
	}
}