From 6ddf0fa5237294062e7d287f365895c2c5f1bf67 Mon Sep 17 00:00:00 2001 From: Olaoluwa Osuntokun Date: Fri, 22 Mar 2019 17:24:17 -0700 Subject: [PATCH] cmd/loopd: add persistent logging, debug level toggle In this commit, we add persistent logic to the loopd daemon. Users can now designate a default logging directory, as well as log rotation options. Additionally, we've added a new `--debuglevel` command which allows users to crank up the logging for particular sub-systems on start up. Fixes #5. --- cmd/loopd/config.go | 30 +++++ cmd/loopd/daemon.go | 22 ++-- cmd/loopd/log.go | 205 +++++++++++++++++++++++++++++++-- cmd/loopd/main.go | 30 ++++- cmd/loopd/swapclient_server.go | 10 +- 5 files changed, 265 insertions(+), 32 deletions(-) diff --git a/cmd/loopd/config.go b/cmd/loopd/config.go index 53b82f1..25e14f2 100644 --- a/cmd/loopd/config.go +++ b/cmd/loopd/config.go @@ -1,5 +1,25 @@ package main +import ( + "path/filepath" + + "github.com/btcsuite/btcutil" +) + +var ( + loopDirBase = btcutil.AppDataDir("loop", false) + + defaultConfigFilename = "loopd.conf" + + defaultLogLevel = "info" + defaultLogDirname = "logs" + defaultLogFilename = "loopd.log" + defaultLogDir = filepath.Join(loopDirBase, defaultLogDirname) + + defaultMaxLogFiles = 3 + defaultMaxLogFileSize = 10 +) + type lndConfig struct { Host string `long:"host" description:"lnd instance rpc address"` MacaroonPath string `long:"macaroonpath" description:"Path to lnd macaroon"` @@ -19,6 +39,12 @@ type config struct { Lnd *lndConfig `group:"lnd" namespace:"lnd"` View viewParameters `command:"view" alias:"v" description:"View all swaps in the database. This command can only be executed when loopd is not running."` + + LogDir string `long:"logdir" description:"Directory to log output."` + MaxLogFiles int `long:"maxlogfiles" description:"Maximum logfiles to keep (0 for no rotation)"` + MaxLogFileSize int `long:"maxlogfilesize" description:"Maximum logfile size in MB"` + + DebugLevel string `short:"d" long:"debuglevel" description:"Logging level for all subsystems {trace, debug, info, warn, error, critical} -- You may also specify =,=,... to set the log level for individual subsystems -- Use show to list available subsystems"` } var defaultConfig = config{ @@ -30,4 +56,8 @@ var defaultConfig = config{ Lnd: &lndConfig{ Host: "localhost:10009", }, + MaxLogFiles: defaultMaxLogFiles, + MaxLogFileSize: defaultMaxLogFileSize, + DebugLevel: defaultLogLevel, + LogDir: defaultLogDir, } diff --git a/cmd/loopd/daemon.go b/cmd/loopd/daemon.go index dd5875d..f344925 100644 --- a/cmd/loopd/daemon.go +++ b/cmd/loopd/daemon.go @@ -62,7 +62,7 @@ func daemon(config *config) error { looprpc.RegisterSwapClientServer(grpcServer, &server) // Next, start the gRPC server listening for HTTP/2 connections. - logger.Infof("Starting gRPC listener") + loopdLog.Infof("Starting gRPC listener") grpcListener, err := net.Listen("tcp", config.RPCListen) if err != nil { return fmt.Errorf("RPC server unable to listen on %s", @@ -84,7 +84,7 @@ func daemon(config *config) error { return err } - logger.Infof("Starting REST proxy listener") + loopdLog.Infof("Starting REST proxy listener") restListener, err := net.Listen("tcp", config.RESTListen) if err != nil { return fmt.Errorf("REST proxy unable to listen on %s", @@ -104,14 +104,14 @@ func daemon(config *config) error { go func() { defer wg.Done() - logger.Infof("Starting swap client") + loopdLog.Infof("Starting swap client") err := swapClient.Run(mainCtx, statusChan) if err != nil { - logger.Error(err) + loopdLog.Error(err) } - logger.Infof("Swap client stopped") + loopdLog.Infof("Swap client stopped") - logger.Infof("Stopping gRPC server") + loopdLog.Infof("Stopping gRPC server") grpcServer.Stop() cancel() @@ -122,7 +122,7 @@ func daemon(config *config) error { go func() { defer wg.Done() - logger.Infof("Waiting for updates") + loopdLog.Infof("Waiting for updates") for { select { case swap := <-statusChan: @@ -149,12 +149,12 @@ func daemon(config *config) error { go func() { defer wg.Done() - logger.Infof("RPC server listening on %s", grpcListener.Addr()) - logger.Infof("REST proxy listening on %s", restListener.Addr()) + loopdLog.Infof("RPC server listening on %s", grpcListener.Addr()) + loopdLog.Infof("REST proxy listening on %s", restListener.Addr()) err = grpcServer.Serve(grpcListener) if err != nil { - logger.Error(err) + loopdLog.Error(err) } }() @@ -164,7 +164,7 @@ func daemon(config *config) error { // Run until the users terminates loopd or an error occurred. select { case <-interruptChannel: - logger.Infof("Received SIGINT (Ctrl+C).") + loopdLog.Infof("Received SIGINT (Ctrl+C).") // TODO: Remove debug code. // Debug code to dump goroutines on hanging exit. diff --git a/cmd/loopd/log.go b/cmd/loopd/log.go index 5ec7eef..38b1525 100644 --- a/cmd/loopd/log.go +++ b/cmd/loopd/log.go @@ -1,24 +1,207 @@ package main import ( + "fmt" + "io" "os" + "path/filepath" + "sort" + "strings" "github.com/btcsuite/btclog" + "github.com/jrick/logrotate/rotator" + "github.com/lightninglabs/loop" + "github.com/lightninglabs/loop/lndclient" + "github.com/lightningnetwork/lnd/build" ) -// log is a logger that is initialized with no output filters. This means the -// package will not perform any logging by default until the caller requests -// it. +// 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 ( - backendLog = btclog.NewBackend(logWriter{}) - logger = backendLog.Logger("LOOPD") + 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 + + loopdLog = build.NewSubLogger("LOOPD", backendLog.Logger) + loopLog = build.NewSubLogger("LOOP", backendLog.Logger) + lndClientLog = build.NewSubLogger("LNDC", backendLog.Logger) ) -// logWriter implements an io.Writer that outputs to both standard output and -// the write-end pipe of an initialized log rotator. -type logWriter struct{} +func init() { + loop.UseLogger(loopLog) + lndclient.UseLogger(lndClientLog) +} + +// 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 +} + +// subsystemLoggers maps each subsystem identifier to its associated logger. +var subsystemLoggers = map[string]btclog.Logger{ + "LOOPD": loopdLog, + "LOOP": loopLog, + "LNDC": lndClientLog, +} + +// 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) +} + +// parseAndSetDebugLevels attempts to parse the specified debug level and set +// the levels accordingly. An appropriate error is returned if anything is +// invalid. +func parseAndSetDebugLevels(debugLevel string) error { + // When the specified string doesn't have any delimiters, treat it as + // the log level for all subsystems. + if !strings.Contains(debugLevel, ",") && !strings.Contains(debugLevel, "=") { + // Validate debug log level. + if !validLogLevel(debugLevel) { + str := "The specified debug level [%v] is invalid" + return fmt.Errorf(str, debugLevel) + } + + // Change the logging level for all subsystems. + setLogLevels(debugLevel) + + return nil + } + + // Split the specified string into subsystem/level pairs while detecting + // issues and update the log levels accordingly. + for _, logLevelPair := range strings.Split(debugLevel, ",") { + if !strings.Contains(logLevelPair, "=") { + str := "The specified debug level contains an invalid " + + "subsystem/level pair [%v]" + return fmt.Errorf(str, logLevelPair) + } + + // Extract the specified subsystem and log level. + fields := strings.Split(logLevelPair, "=") + subsysID, logLevel := fields[0], fields[1] + + // Validate subsystem. + if _, exists := subsystemLoggers[subsysID]; !exists { + str := "The specified subsystem [%v] is invalid -- " + + "supported subsystems %v" + return fmt.Errorf(str, subsysID, supportedSubsystems()) + } + + // Validate log level. + if !validLogLevel(logLevel) { + str := "The specified debug level [%v] is invalid" + return fmt.Errorf(str, logLevel) + } + + setLogLevel(subsysID, logLevel) + } + + return nil +} + +// validLogLevel returns whether or not logLevel is a valid debug log level. +func validLogLevel(logLevel string) bool { + switch logLevel { + case "trace": + fallthrough + case "debug": + fallthrough + case "info": + fallthrough + case "warn": + fallthrough + case "error": + fallthrough + case "critical": + fallthrough + case "off": + return true + } + return false +} + +// supportedSubsystems returns a sorted slice of the supported subsystems for +// logging purposes. +func supportedSubsystems() []string { + // Convert the subsystemLoggers map keys to a slice. + subsystems := make([]string, 0, len(subsystemLoggers)) + for subsysID := range subsystemLoggers { + subsystems = append(subsystems, subsysID) + } -func (logWriter) Write(p []byte) (n int, err error) { - os.Stdout.Write(p) - return len(p), nil + // Sort the subsystems for stable display. + sort.Strings(subsystems) + return subsystems } diff --git a/cmd/loopd/main.go b/cmd/loopd/main.go index fd78fb8..77c244a 100644 --- a/cmd/loopd/main.go +++ b/cmd/loopd/main.go @@ -9,7 +9,6 @@ import ( flags "github.com/jessevdk/go-flags" - "github.com/btcsuite/btcutil" "github.com/lightninglabs/loop" "github.com/lightningnetwork/lnd/lntypes" ) @@ -19,9 +18,6 @@ const ( ) var ( - loopDirBase = btcutil.AppDataDir("loop", false) - defaultConfigFilename = "loopd.conf" - swaps = make(map[lntypes.Hash]loop.SwapInfo) subscribers = make(map[int]chan<- interface{}) nextSubscriberID int @@ -81,8 +77,32 @@ func start() error { os.Exit(0) } + // Special show command to list supported subsystems and exit. + if config.DebugLevel == "show" { + fmt.Println("Supported subsystems", supportedSubsystems()) + os.Exit(0) + } + + // Append the network type to the log directory so it is "namespaced" + // per network in the same fashion as the data directory. + config.LogDir = filepath.Join(config.LogDir, config.Network) + + // Parse, validate, and set debug log level(s). + usageMessage := fmt.Sprintf("Use %s -h to show usage", appName) + if err := parseAndSetDebugLevels(config.DebugLevel); err != nil { + fmt.Fprintln(os.Stderr, err) + fmt.Fprintln(os.Stderr, usageMessage) + return err + } + + // Initialize logging at the default logging level. + initLogRotator( + filepath.Join(config.LogDir, defaultLogFilename), + config.MaxLogFileSize, config.MaxLogFiles, + ) + // Print the version before executing either primary directive. - logger.Infof("Version: %v", loop.Version()) + loopdLog.Infof("Version: %v", loop.Version()) // Execute command. if parser.Active == nil { diff --git a/cmd/loopd/swapclient_server.go b/cmd/loopd/swapclient_server.go index 6678fb0..0f1ad99 100644 --- a/cmd/loopd/swapclient_server.go +++ b/cmd/loopd/swapclient_server.go @@ -32,7 +32,7 @@ func (s *swapClientServer) LoopOut(ctx context.Context, in *looprpc.LoopOutRequest) ( *looprpc.SwapResponse, error) { - logger.Infof("LoopOut request received") + loopdLog.Infof("LoopOut request received") var sweepAddr btcutil.Address if in.Dest == "" { @@ -65,7 +65,7 @@ func (s *swapClientServer) LoopOut(ctx context.Context, } hash, err := s.impl.LoopOut(ctx, req) if err != nil { - logger.Errorf("LoopOut: %v", err) + loopdLog.Errorf("LoopOut: %v", err) return nil, err } @@ -118,7 +118,7 @@ func (s *swapClientServer) marshallSwap(loopSwap *loop.SwapInfo) ( func (s *swapClientServer) Monitor(in *looprpc.MonitorRequest, server looprpc.SwapClient_MonitorServer) error { - logger.Infof("Monitor request received") + loopdLog.Infof("Monitor request received") send := func(info loop.SwapInfo) error { rpcSwap, err := s.marshallSwap(&info) @@ -212,11 +212,11 @@ func (s *swapClientServer) Monitor(in *looprpc.MonitorRequest, func (s *swapClientServer) LoopOutTerms(ctx context.Context, req *looprpc.TermsRequest) (*looprpc.TermsResponse, error) { - logger.Infof("Terms request received") + loopdLog.Infof("Terms request received") terms, err := s.impl.LoopOutTerms(ctx) if err != nil { - logger.Errorf("Terms request: %v", err) + loopdLog.Errorf("Terms request: %v", err) return nil, err }