Merge pull request #3532 from guggero/refactor-log-writer

build+lnd: refactor reusable log file rotator code into build package
This commit is contained in:
Conner Fromknecht 2019-10-16 12:59:39 +02:00 committed by GitHub
commit c10eacaa24
No known key found for this signature in database
GPG Key ID: 4AEE18F83AFDEB23
6 changed files with 334 additions and 257 deletions

@ -1,7 +1,9 @@
package build
import (
"fmt"
"io"
"strings"
"github.com/btcsuite/btclog"
)
@ -93,3 +95,106 @@ func NewSubLogger(subsystem string,
// For any other configurations, we'll disable logging.
return btclog.Disabled
}
// SubLoggers is a type that holds a map of subsystem loggers keyed by their
// subsystem name.
type SubLoggers map[string]btclog.Logger
// LeveledSubLogger provides the ability to retrieve the subsystem loggers of
// a logger and set their log levels individually or all at once.
type LeveledSubLogger interface {
// SubLoggers returns the map of all registered subsystem loggers.
SubLoggers() SubLoggers
// SupportedSubsystems returns a slice of strings containing the names
// of the supported subsystems. Should ideally correspond to the keys
// of the subsystem logger map and be sorted.
SupportedSubsystems() []string
// SetLogLevel assigns an individual subsystem logger a new log level.
SetLogLevel(subsystemID string, logLevel string)
// SetLogLevels assigns all subsystem loggers the same new log level.
SetLogLevels(logLevel string)
}
// ParseAndSetDebugLevels attempts to parse the specified debug level and set
// the levels accordingly on the given logger. An appropriate error is returned
// if anything is invalid.
func ParseAndSetDebugLevels(level string, logger LeveledSubLogger) error {
// When the specified string doesn't have any delimiters, treat it as
// the log level for all subsystems.
if !strings.Contains(level, ",") && !strings.Contains(level, "=") {
// Validate debug log level.
if !validLogLevel(level) {
str := "the specified debug level [%v] is invalid"
return fmt.Errorf(str, level)
}
// Change the logging level for all subsystems.
logger.SetLogLevels(level)
return nil
}
// Split the specified string into subsystem/level pairs while detecting
// issues and update the log levels accordingly.
for _, logLevelPair := range strings.Split(level, ",") {
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, "=")
if len(fields) != 2 {
str := "the specified debug level has an invalid " +
"format [%v] -- use format subsystem1=level1," +
"subsystem2=level2"
return fmt.Errorf(str, logLevelPair)
}
subsysID, logLevel := fields[0], fields[1]
subLoggers := logger.SubLoggers()
// Validate subsystem.
if _, exists := subLoggers[subsysID]; !exists {
str := "the specified subsystem [%v] is invalid -- " +
"supported subsystems are %v"
return fmt.Errorf(
str, subsysID, logger.SupportedSubsystems(),
)
}
// Validate log level.
if !validLogLevel(logLevel) {
str := "the specified debug level [%v] is invalid"
return fmt.Errorf(str, logLevel)
}
logger.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
}

151
build/logrotator.go Normal file

@ -0,0 +1,151 @@
package build
import (
"fmt"
"io"
"os"
"path/filepath"
"sort"
"github.com/btcsuite/btclog"
"github.com/jrick/logrotate/rotator"
)
// RotatingLogWriter is a wrapper around the LogWriter that supports log file
// rotation.
type RotatingLogWriter struct {
// GenSubLogger is a function that returns a new logger for a subsystem
// belonging to the current RotatingLogWriter.
GenSubLogger func(string) btclog.Logger
logWriter *LogWriter
backendLog *btclog.Backend
logRotator *rotator.Rotator
subsystemLoggers SubLoggers
}
// A compile time check to ensure RotatingLogWriter implements the
// LeveledSubLogger interface.
var _ LeveledSubLogger = (*RotatingLogWriter)(nil)
// NewRotatingLogWriter creates a new file rotating log writer.
//
// NOTE: `InitLogRotator` must be called to set up log rotation after creating
// the writer.
func NewRotatingLogWriter() *RotatingLogWriter {
logWriter := &LogWriter{}
backendLog := btclog.NewBackend(logWriter)
return &RotatingLogWriter{
GenSubLogger: backendLog.Logger,
logWriter: logWriter,
backendLog: backendLog,
subsystemLoggers: SubLoggers{},
}
}
// RegisterSubLogger registers a new subsystem logger.
func (r *RotatingLogWriter) RegisterSubLogger(subsystem string,
logger btclog.Logger) {
r.subsystemLoggers[subsystem] = logger
}
// InitLogRotator initializes the log file rotator to write logs to logFile and
// create roll files in the same directory. It should be called as early on
// startup and possible and must be closed on shutdown by calling `Close`.
func (r *RotatingLogWriter) InitLogRotator(logFile string, maxLogFileSize int,
maxLogFiles int) error {
logDir, _ := filepath.Split(logFile)
err := os.MkdirAll(logDir, 0700)
if err != nil {
return fmt.Errorf("failed to create log directory: %v", err)
}
r.logRotator, err = rotator.New(
logFile, int64(maxLogFileSize*1024), false, maxLogFiles,
)
if err != nil {
return fmt.Errorf("failed to create file rotator: %v", err)
}
// Run rotator as a goroutine now but make sure we catch any errors
// that happen in case something with the rotation goes wrong during
// runtime (like running out of disk space or not being allowed to
// create a new logfile for whatever reason).
pr, pw := io.Pipe()
go func() {
err := r.logRotator.Run(pr)
if err != nil {
_, _ = fmt.Fprintf(os.Stderr,
"failed to run file rotator: %v\n", err)
}
}()
r.logWriter.RotatorPipe = pw
return nil
}
// Close closes the underlying log rotator if it has already been created.
func (r *RotatingLogWriter) Close() error {
if r.logRotator != nil {
return r.logRotator.Close()
}
return nil
}
// SubLoggers returns all currently registered subsystem loggers for this log
// writer.
//
// NOTE: This is part of the LeveledSubLogger interface.
func (r *RotatingLogWriter) SubLoggers() SubLoggers {
return r.subsystemLoggers
}
// SupportedSubsystems returns a sorted string slice of all keys in the
// subsystems map, corresponding to the names of the subsystems.
//
// NOTE: This is part of the LeveledSubLogger interface.
func (r *RotatingLogWriter) SupportedSubsystems() []string {
// Convert the subsystemLoggers map keys to a string slice.
subsystems := make([]string, 0, len(r.subsystemLoggers))
for subsysID := range r.subsystemLoggers {
subsystems = append(subsystems, subsysID)
}
// Sort the subsystems for stable display.
sort.Strings(subsystems)
return subsystems
}
// SetLogLevel sets the logging level for provided subsystem. Invalid
// subsystems are ignored. Uninitialized subsystems are dynamically created as
// needed.
//
// NOTE: This is part of the LeveledSubLogger interface.
func (r *RotatingLogWriter) SetLogLevel(subsystemID string, logLevel string) {
// Ignore invalid subsystems.
logger, ok := r.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.
//
// NOTE: This is part of the LeveledSubLogger interface.
func (r *RotatingLogWriter) SetLogLevels(logLevel string) {
// Configure all sub-systems with the new logging level. Dynamically
// create loggers as needed.
for subsystemID := range r.subsystemLoggers {
r.SetLogLevel(subsystemID, logLevel)
}
}

103
config.go

@ -14,7 +14,6 @@ import (
"path"
"path/filepath"
"regexp"
"sort"
"strconv"
"strings"
"time"
@ -953,19 +952,27 @@ func loadConfig() (*config, error) {
// Special show command to list supported subsystems and exit.
if cfg.DebugLevel == "show" {
fmt.Println("Supported subsystems", supportedSubsystems())
fmt.Println("Supported subsystems",
logWriter.SupportedSubsystems())
os.Exit(0)
}
// Initialize logging at the default logging level.
initLogRotator(
err = logWriter.InitLogRotator(
filepath.Join(cfg.LogDir, defaultLogFilename),
cfg.MaxLogFileSize, cfg.MaxLogFiles,
)
if err != nil {
str := "%s: log rotation setup failed: %v"
err = fmt.Errorf(str, funcName, err.Error())
fmt.Fprintln(os.Stderr, err)
return nil, err
}
// Parse, validate, and set debug log level(s).
if err := parseAndSetDebugLevels(cfg.DebugLevel); err != nil {
err := fmt.Errorf("%s: %v", funcName, err.Error())
err = build.ParseAndSetDebugLevels(cfg.DebugLevel, logWriter)
if err != nil {
err = fmt.Errorf("%s: %v", funcName, err.Error())
fmt.Fprintln(os.Stderr, err)
fmt.Fprintln(os.Stderr, usageMessage)
return nil, err
@ -1140,92 +1147,6 @@ func cleanAndExpandPath(path string) string {
return filepath.Clean(os.ExpandEnv(path))
}
// 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)
}
// Sort the subsystems for stable display.
sort.Strings(subsystems)
return subsystems
}
func parseRPCParams(cConfig *chainConfig, nodeConfig interface{}, net chainCode,
funcName string) error {

7
lnd.go

@ -124,9 +124,10 @@ func Main(lisCfg ListenerCfg) error {
}
cfg = loadedConfig
defer func() {
if logRotator != nil {
ltndLog.Info("Shutdown complete")
logRotator.Close()
ltndLog.Info("Shutdown complete")
err := logWriter.Close()
if err != nil {
ltndLog.Errorf("Could not close log rotator: %v", err)
}
}()

218
log.go

@ -2,14 +2,9 @@ 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"
@ -48,177 +43,78 @@ import (
//
// 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.
// calling logWriter.InitLogRotator.
var (
logWriter = &build.LogWriter{}
logWriter = build.NewRotatingLogWriter()
// 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)
// Loggers that need to be accessible from the lnd package can be placed
// here. Loggers that are only used in sub modules can be added directly
// by using the addSubLogger method.
ltndLog = build.NewSubLogger("LTND", logWriter.GenSubLogger)
peerLog = build.NewSubLogger("PEER", logWriter.GenSubLogger)
rpcsLog = build.NewSubLogger("RPCS", logWriter.GenSubLogger)
srvrLog = build.NewSubLogger("SRVR", logWriter.GenSubLogger)
fndgLog = build.NewSubLogger("FNDG", logWriter.GenSubLogger)
utxnLog = build.NewSubLogger("UTXN", logWriter.GenSubLogger)
brarLog = build.NewSubLogger("BRAR", logWriter.GenSubLogger)
atplLog = build.NewSubLogger("ATPL", logWriter.GenSubLogger)
)
// 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)
setSubLogger("LTND", ltndLog, signal.UseLogger)
setSubLogger("ATPL", atplLog, autopilot.UseLogger)
setSubLogger("PEER", peerLog, nil)
setSubLogger("RPCS", rpcsLog, nil)
setSubLogger("SRVR", srvrLog, nil)
setSubLogger("FNDG", fndgLog, nil)
setSubLogger("UTXN", utxnLog, nil)
setSubLogger("BRAR", brarLog, nil)
addSubLogger("LNWL", lnwallet.UseLogger)
addSubLogger("DISC", discovery.UseLogger)
addSubLogger("NTFN", chainntnfs.UseLogger)
addSubLogger("CHDB", channeldb.UseLogger)
addSubLogger("HSWC", htlcswitch.UseLogger)
addSubLogger("CMGR", connmgr.UseLogger)
addSubLogger("CRTR", routing.UseLogger)
addSubLogger("BTCN", neutrino.UseLogger)
addSubLogger("CNCT", contractcourt.UseLogger)
addSubLogger("SPHX", sphinx.UseLogger)
addSubLogger("SWPR", sweep.UseLogger)
addSubLogger("SGNR", signrpc.UseLogger)
addSubLogger("WLKT", walletrpc.UseLogger)
addSubLogger("ARPC", autopilotrpc.UseLogger)
addSubLogger("INVC", invoices.UseLogger)
addSubLogger("NANN", netann.UseLogger)
addSubLogger("WTWR", watchtower.UseLogger)
addSubLogger("NTFR", chainrpc.UseLogger)
addSubLogger("IRPC", invoicesrpc.UseLogger)
addSubLogger("CHNF", channelnotifier.UseLogger)
addSubLogger("CHBU", chanbackup.UseLogger)
addSubLogger("PROM", monitoring.UseLogger)
addSubLogger("WTCL", wtclient.UseLogger)
addSubLogger("PRNF", peernotifier.UseLogger)
addSubLogger(routerrpc.Subsystem, routerrpc.UseLogger)
addSubLogger(wtclientrpc.Subsystem, wtclientrpc.UseLogger)
}
// addSubLogger is a helper method to conveniently register the logger of a sub
// system.
// addSubLogger is a helper method to conveniently create and 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
logger := build.NewSubLogger(subsystem, logWriter.GenSubLogger)
setSubLogger(subsystem, logger, useLogger)
}
// 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,
}
// setSubLogger is a helper method to conveniently register the logger of a sub
// system.
func setSubLogger(subsystem string, logger btclog.Logger,
useLogger func(btclog.Logger)) {
// 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)
logWriter.RegisterSubLogger(subsystem, logger)
if useLogger != nil {
useLogger(logger)
}
}

@ -4348,7 +4348,9 @@ func (r *rpcServer) DebugLevel(ctx context.Context,
// sub-systems.
if req.Show {
return &lnrpc.DebugLevelResponse{
SubSystems: strings.Join(supportedSubsystems(), " "),
SubSystems: strings.Join(
logWriter.SupportedSubsystems(), " ",
),
}, nil
}
@ -4356,7 +4358,8 @@ func (r *rpcServer) DebugLevel(ctx context.Context,
// Otherwise, we'll attempt to set the logging level using the
// specified level spec.
if err := parseAndSetDebugLevels(req.LevelSpec); err != nil {
err := build.ParseAndSetDebugLevels(req.LevelSpec, logWriter)
if err != nil {
return nil, err
}