From 65fab012253d2d81868b0049cbacb3499a17ac50 Mon Sep 17 00:00:00 2001 From: jholdstock Date: Thu, 23 Jun 2022 11:56:33 +0100 Subject: [PATCH] Remove remaining global loggers. This removes all of the global loggers from the project and replaces them with loggers which are instantiated in vspd.go and passed down as params. To support this, the background package was removed. It only contained one file so it was a bit pointless anyway. It only existed so background tasks could have their own named logger. --- background/background.go => background.go | 7 +- background/log.go | 30 ------- config.go | 24 ++++- database/database.go | 30 ++++--- database/database_test.go | 13 ++- database/log.go | 30 ------- database/upgrades.go | 2 +- log.go | 101 +++------------------- rpc/client.go | 16 ++-- rpc/dcrd.go | 12 ++- rpc/dcrwallet.go | 32 +++---- rpc/log.go | 30 ------- rpc/notifs.go | 4 +- signal.go | 4 +- vspd.go | 39 +++++---- webapi/log.go | 30 ------- webapi/middleware.go | 2 +- webapi/setaltsignaddr_test.go | 6 +- webapi/webapi.go | 5 +- 19 files changed, 134 insertions(+), 283 deletions(-) rename background/background.go => background.go (98%) delete mode 100644 background/log.go delete mode 100644 database/log.go delete mode 100644 rpc/log.go delete mode 100644 webapi/log.go diff --git a/background/background.go b/background.go similarity index 98% rename from background/background.go rename to background.go index 1aef6d8..a974ee8 100644 --- a/background/background.go +++ b/background.go @@ -2,12 +2,13 @@ // Use of this source code is governed by an ISC // license that can be found in the LICENSE file. -package background +package main import ( "errors" "strings" + "github.com/decred/slog" "github.com/decred/vspd/database" "github.com/decred/vspd/rpc" "github.com/jrick/wsrpc/v2" @@ -22,7 +23,7 @@ const ( // BlockConnected is called once when vspd starts up, and once each time a // blockconnected notification is received from dcrd. -func BlockConnected(dcrdRPC rpc.DcrdConnect, walletRPC rpc.WalletConnect, db *database.VspDatabase) { +func BlockConnected(dcrdRPC rpc.DcrdConnect, walletRPC rpc.WalletConnect, db *database.VspDatabase, log slog.Logger) { const funcName = "BlockConnected" @@ -283,7 +284,7 @@ func BlockConnected(dcrdRPC rpc.DcrdConnect, walletRPC rpc.WalletConnect, db *da // CheckWalletConsistency will retrieve all votable tickets from the database // and ensure they are all added to voting wallets with the correct vote // choices. -func CheckWalletConsistency(dcrdRPC rpc.DcrdConnect, walletRPC rpc.WalletConnect, db *database.VspDatabase) { +func CheckWalletConsistency(dcrdRPC rpc.DcrdConnect, walletRPC rpc.WalletConnect, db *database.VspDatabase, log slog.Logger) { const funcName = "CheckWalletConsistency" diff --git a/background/log.go b/background/log.go deleted file mode 100644 index 428ea6d..0000000 --- a/background/log.go +++ /dev/null @@ -1,30 +0,0 @@ -// Copyright (c) 2020 The Decred developers -// Use of this source code is governed by an ISC -// license that can be found in the LICENSE file. - -package background - -import ( - "github.com/decred/slog" -) - -// 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. -var log slog.Logger - -// The default amount of logging is none. -func init() { - DisableLog() -} - -// DisableLog disables all library log output. Logging output is disabled -// by default until UseLogger is called. -func DisableLog() { - log = slog.Disabled -} - -// UseLogger uses a specified Logger to output package logging info. -func UseLogger(logger slog.Logger) { - log = logger -} diff --git a/config.go b/config.go index 0934280..6decdf5 100644 --- a/config.go +++ b/config.go @@ -35,7 +35,6 @@ var ( defaultNetwork = "testnet" defaultHomeDir = dcrutil.AppDataDir(appName, false) defaultConfigFilename = fmt.Sprintf("%s.conf", appName) - defaultLogFilename = fmt.Sprintf("%s.log", appName) defaultDBFilename = fmt.Sprintf("%s.db", appName) defaultConfigFile = filepath.Join(defaultHomeDir, defaultConfigFilename) defaultDcrdHost = "127.0.0.1" @@ -76,6 +75,9 @@ type config struct { HomeDir string `long:"homedir" no-ini:"true" description:"Path to application home directory. Used for storing VSP database and logs."` ConfigFile string `long:"configfile" no-ini:"true" description:"Path to configuration file."` + logBackend *slog.Backend + logLevel slog.Level + dbPath string netParams *netParams dcrdCert []byte @@ -406,8 +408,16 @@ func loadConfig() (*config, error) { // Initialize loggers and log rotation. logDir := filepath.Join(cfg.HomeDir, "logs", cfg.netParams.Name) - initLogRotator(filepath.Join(logDir, defaultLogFilename), cfg.MaxLogSize, cfg.LogsToKeep) - setLogLevels(cfg.LogLevel) + cfg.logBackend, err = NewLogBackend(logDir, appName, cfg.MaxLogSize, cfg.LogsToKeep) + if err != nil { + return nil, fmt.Errorf("failed to initialize logger: %w", err) + } + + var ok bool + cfg.logLevel, ok = slog.LevelFromString(cfg.LogLevel) + if !ok { + return nil, fmt.Errorf("unknown log level: %s", cfg.LogLevel) + } // Set the database path cfg.dbPath = filepath.Join(dataDir, defaultDBFilename) @@ -427,7 +437,7 @@ func loadConfig() (*config, error) { } // Create new database. - err = database.CreateNew(cfg.dbPath, cfg.FeeXPub) + err = database.CreateNew(cfg.dbPath, cfg.FeeXPub, cfg.Logger(" DB")) if err != nil { return nil, fmt.Errorf("error creating db file %s: %w", cfg.dbPath, err) } @@ -445,3 +455,9 @@ func loadConfig() (*config, error) { return &cfg, nil } + +func (cfg *config) Logger(subsystem string) slog.Logger { + log := cfg.logBackend.Logger(subsystem) + log.SetLevel(cfg.logLevel) + return log +} diff --git a/database/database.go b/database/database.go index 6c1e9e0..0463f0e 100644 --- a/database/database.go +++ b/database/database.go @@ -16,6 +16,7 @@ import ( "sync" "time" + "github.com/decred/slog" "github.com/decred/vspd/rpc" bolt "go.etcd.io/bbolt" ) @@ -25,6 +26,7 @@ import ( type VspDatabase struct { db *bolt.DB maxVoteChangeRecords int + log slog.Logger ticketsMtx sync.RWMutex } @@ -83,7 +85,8 @@ func (vdb *VspDatabase) writeHotBackupFile() error { return fmt.Errorf("os.Rename: %w", err) } - log.Tracef("Database backup written to %s", backupPath) + vdb.log.Tracef("Database backup written to %s", backupPath) + return err } @@ -92,7 +95,7 @@ func (vdb *VspDatabase) writeHotBackupFile() error { // - the provided extended pubkey (to be used for deriving fee addresses). // - an ed25519 keypair to sign API responses. // - a secret key to use for initializing a HTTP cookie store. -func CreateNew(dbFile, feeXPub string) error { +func CreateNew(dbFile, feeXPub string, log slog.Logger) error { log.Infof("Initializing new database at %s", dbFile) db, err := bolt.Open(dbFile, 0600, &bolt.Options{Timeout: 1 * time.Second}) @@ -172,7 +175,7 @@ func CreateNew(dbFile, feeXPub string) error { // Open initializes and returns an open database. An error is returned if no // database file is found at the provided path. -func Open(shutdownCtx context.Context, shutdownWg *sync.WaitGroup, dbFile string, +func Open(shutdownCtx context.Context, shutdownWg *sync.WaitGroup, log slog.Logger, dbFile string, backupInterval time.Duration, maxVoteChangeRecords int) (*VspDatabase, error) { // Error if db file does not exist. This is needed because bolt.Open will @@ -188,7 +191,10 @@ func Open(shutdownCtx context.Context, shutdownWg *sync.WaitGroup, dbFile string return nil, fmt.Errorf("unable to open db file: %w", err) } - vdb := &VspDatabase{db: db, maxVoteChangeRecords: maxVoteChangeRecords} + vdb := &VspDatabase{ + db: db, + log: log, + maxVoteChangeRecords: maxVoteChangeRecords} dbVersion, err := vdb.Version() if err != nil { @@ -242,14 +248,14 @@ func (vdb *VspDatabase) Close() { // closing the db and writing the file to disk. err := vdb.db.Close() if err != nil { - log.Errorf("Error closing database: %v", err) + vdb.log.Errorf("Error closing database: %v", err) // Return here because if there is an issue with the database, we // probably don't want to overwrite the backup file and potentially // break that too. return } - log.Debug("Database closed") + vdb.log.Debug("Database closed") // Ensure the database backup file is up-to-date. backupPath := dbPath + "-backup" @@ -260,32 +266,32 @@ func (vdb *VspDatabase) Close() { from, err := os.Open(dbPath) if err != nil { - log.Errorf("Failed to write a database backup (os.Open): %v", err) + vdb.log.Errorf("Failed to write a database backup (os.Open): %v", err) return } defer from.Close() to, err := os.OpenFile(tempPath, os.O_RDWR|os.O_CREATE, backupFileMode) if err != nil { - log.Errorf("Failed to write a database backup (os.OpenFile): %v", err) + vdb.log.Errorf("Failed to write a database backup (os.OpenFile): %v", err) return } defer to.Close() _, err = io.Copy(to, from) if err != nil { - log.Errorf("Failed to write a database backup (io.Copy): %v", err) + vdb.log.Errorf("Failed to write a database backup (io.Copy): %v", err) return } // Rename temporary file to actual backup file. err = os.Rename(tempPath, backupPath) if err != nil { - log.Errorf("Failed to write a database backup (os.Rename): %v", err) + vdb.log.Errorf("Failed to write a database backup (os.Rename): %v", err) return } - log.Tracef("Database backup written to %s", backupPath) + vdb.log.Tracef("Database backup written to %s", backupPath) } // KeyPair retrieves the keypair used to sign API responses from the database. @@ -426,7 +432,7 @@ func (vdb *VspDatabase) CheckIntegrity(dcrd rpc.DcrdConnect) error { } } - log.Infof("Added missing purchase height to %d tickets", len(missing)) + vdb.log.Infof("Added missing purchase height to %d tickets", len(missing)) return nil } diff --git a/database/database_test.go b/database/database_test.go index f39f0f2..d05ed90 100644 --- a/database/database_test.go +++ b/database/database_test.go @@ -1,4 +1,4 @@ -// Copyright (c) 2020-2021 The Decred developers +// Copyright (c) 2020-2022 The Decred developers // Use of this source code is governed by an ISC // license that can be found in the LICENSE file. @@ -16,6 +16,8 @@ import ( "sync" "testing" "time" + + "github.com/decred/slog" ) const ( @@ -82,15 +84,20 @@ func TestDatabase(t *testing.T) { } for testName, test := range tests { + // Set test logger to stdout. + backend := slog.NewBackend(os.Stdout) + log := backend.Logger("test") + log.SetLevel(slog.LevelTrace) + // Create a new blank database for each sub-test. var err error var wg sync.WaitGroup ctx, cancel := context.WithCancel(context.TODO()) - err = CreateNew(testDb, feeXPub) + err = CreateNew(testDb, feeXPub, log) if err != nil { t.Fatalf("error creating test database: %v", err) } - db, err = Open(ctx, &wg, testDb, time.Hour, maxVoteChangeRecords) + db, err = Open(ctx, &wg, log, testDb, time.Hour, maxVoteChangeRecords) if err != nil { t.Fatalf("error opening test database: %v", err) } diff --git a/database/log.go b/database/log.go deleted file mode 100644 index eff9ea0..0000000 --- a/database/log.go +++ /dev/null @@ -1,30 +0,0 @@ -// Copyright (c) 2020 The Decred developers -// Use of this source code is governed by an ISC -// license that can be found in the LICENSE file. - -package database - -import ( - "github.com/decred/slog" -) - -// 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. -var log slog.Logger - -// The default amount of logging is none. -func init() { - DisableLog() -} - -// DisableLog disables all library log output. Logging output is disabled -// by default until UseLogger is called. -func DisableLog() { - log = slog.Disabled -} - -// UseLogger uses a specified Logger to output package logging info. -func UseLogger(logger slog.Logger) { - log = logger -} diff --git a/database/upgrades.go b/database/upgrades.go index 9eec07e..946abe8 100644 --- a/database/upgrades.go +++ b/database/upgrades.go @@ -78,7 +78,7 @@ func (vdb *VspDatabase) Upgrade(currentVersion uint32) error { // Execute all necessary upgrades in order. for _, upgrade := range upgrades[currentVersion:] { - err := upgrade(vdb.db, log) + err := upgrade(vdb.db, vdb.log) if err != nil { return err } diff --git a/log.go b/log.go index 9b5955f..675a128 100644 --- a/log.go +++ b/log.go @@ -11,105 +11,32 @@ import ( "github.com/decred/slog" "github.com/jrick/logrotate/rotator" - - "github.com/decred/vspd/background" - "github.com/decred/vspd/database" - "github.com/decred/vspd/rpc" - "github.com/decred/vspd/webapi" ) // logWriter implements an io.Writer that outputs to both standard output and // the write-end pipe of an initialized log rotator. -type logWriter struct{} +type logWriter struct { + rotator *rotator.Rotator +} -func (logWriter) Write(p []byte) (n int, err error) { +func (lw logWriter) Write(p []byte) (n int, err error) { os.Stdout.Write(p) - return logRotator.Write(p) + return lw.rotator.Write(p) } -// Loggers per subsystem. A single backend logger is created and all subsytem -// 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 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 = slog.NewBackend(logWriter{}) - - // logRotator is one of the logging outputs. It should be closed on - // application shutdown. - logRotator *rotator.Rotator - - log = backendLog.Logger("VSP") - dbLog = backendLog.Logger(" DB") - bgLog = backendLog.Logger(" BG") - apiLog = backendLog.Logger("API") - rpcLog = backendLog.Logger("RPC") -) - -// Initialize package-global logger variables. -func init() { - database.UseLogger(dbLog) - background.UseLogger(bgLog) - webapi.UseLogger(apiLog) - rpc.UseLogger(rpcLog) -} - -// subsystemLoggers maps each subsystem identifier to its associated logger. -var subsystemLoggers = map[string]slog.Logger{ - "VSP": log, - " DB": dbLog, - " BG": bgLog, - "API": apiLog, - "RPC": rpcLog, -} - -// initLogRotator initializes the logging rotater to write logs to logFile and -// create roll files in the same directory. It must be called before the -// package-global log rotater variables are used. -func initLogRotator(logFile string, maxLogSize int64, logsToKeep int) { - logDir, _ := filepath.Split(logFile) +func NewLogBackend(logDir string, appName string, maxLogSize int64, logsToKeep int) (*slog.Backend, error) { err := os.MkdirAll(logDir, 0700) if err != nil { - fmt.Fprintf(os.Stderr, "failed to create log directory: %v\n", err) - os.Exit(1) + return nil, fmt.Errorf("failed to create log directory: %w", err) } - r, err := rotator.New(logFile, maxLogSize*1024, false, logsToKeep) + + logFileName := fmt.Sprintf("%s.log", appName) + logFilePath := filepath.Join(logDir, logFileName) + + r, err := rotator.New(logFilePath, maxLogSize*1024, false, logsToKeep) if err != nil { - fmt.Fprintf(os.Stderr, "failed to create file rotator: %v\n", err) - os.Exit(1) + return nil, fmt.Errorf("failed to create log rotator: %w", err) } - 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, _ := slog.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) - } + return slog.NewBackend(logWriter{r}), nil } diff --git a/rpc/client.go b/rpc/client.go index d3ac789..3b1341b 100644 --- a/rpc/client.go +++ b/rpc/client.go @@ -1,4 +1,4 @@ -// Copyright (c) 2020 The Decred developers +// Copyright (c) 2020-2022 The Decred developers // Use of this source code is governed by an ISC // license that can be found in the LICENSE file. @@ -10,6 +10,7 @@ import ( "crypto/x509" "sync" + "github.com/decred/slog" "github.com/jrick/wsrpc/v2" ) @@ -35,9 +36,10 @@ type client struct { tlsOpt wsrpc.Option authOpt wsrpc.Option notifier wsrpc.Notifier + log slog.Logger } -func setup(user, pass, addr string, cert []byte) *client { +func setup(user, pass, addr string, cert []byte, log slog.Logger) *client { // Create TLS options. pool := x509.NewCertPool() @@ -63,20 +65,20 @@ func setup(user, pass, addr string, cert []byte) *client { var mu sync.Mutex var c *wsrpc.Client fullAddr := "wss://" + addr + "/ws" - return &client{&mu, c, fullAddr, tlsOpt, authOpt, nil} + return &client{&mu, c, fullAddr, tlsOpt, authOpt, nil, log} } func (c *client) Close() { if c.client != nil { select { case <-c.client.Done(): - log.Tracef("RPC already closed (%s)", c.addr) + c.log.Tracef("RPC already closed (%s)", c.addr) default: if err := c.client.Close(); err != nil { - log.Errorf("Failed to close RPC (%s): %v", c.addr, err) + c.log.Errorf("Failed to close RPC (%s): %v", c.addr, err) } else { - log.Tracef("RPC closed (%s)", c.addr) + c.log.Tracef("RPC closed (%s)", c.addr) } } } @@ -92,7 +94,7 @@ func (c *client) dial(ctx context.Context) (Caller, bool, error) { if c.client != nil { select { case <-c.client.Done(): - log.Debugf("RPC client %s errored (%v); reconnecting...", c.addr, c.client.Err()) + c.log.Debugf("RPC client %s errored (%v); reconnecting...", c.addr, c.client.Err()) c.client = nil default: return c.client, false, nil diff --git a/rpc/dcrd.go b/rpc/dcrd.go index b183bd1..0dc9ce2 100644 --- a/rpc/dcrd.go +++ b/rpc/dcrd.go @@ -14,6 +14,7 @@ import ( "github.com/decred/dcrd/chaincfg/v3" dcrdtypes "github.com/decred/dcrd/rpc/jsonrpc/types/v3" "github.com/decred/dcrd/wire" + "github.com/decred/slog" "github.com/jrick/bitset" "github.com/jrick/wsrpc/v2" ) @@ -41,12 +42,14 @@ type DcrdRPC struct { type DcrdConnect struct { client *client params *chaincfg.Params + log slog.Logger } -func SetupDcrd(user, pass, addr string, cert []byte, params *chaincfg.Params) DcrdConnect { +func SetupDcrd(user, pass, addr string, cert []byte, params *chaincfg.Params, log slog.Logger) DcrdConnect { return DcrdConnect{ - client: setup(user, pass, addr, cert), + client: setup(user, pass, addr, cert, log), params: params, + log: log, } } @@ -56,12 +59,13 @@ func SetupDcrd(user, pass, addr string, cert []byte, params *chaincfg.Params) Dc func (d *DcrdConnect) BlockConnectedHandler(blockConnected chan *wire.BlockHeader) { d.client.notifier = &blockConnectedHandler{ blockConnected: blockConnected, + log: d.log, } } func (d *DcrdConnect) Close() { d.client.Close() - log.Debug("dcrd client closed") + d.log.Debug("dcrd client closed") } // Client creates a new DcrdRPC client instance. Returns an error if dialing @@ -132,7 +136,7 @@ func (d *DcrdConnect) Client() (*DcrdRPC, string, error) { } } - log.Debugf("Connected to dcrd") + d.log.Debugf("Connected to dcrd") return &DcrdRPC{c, ctx}, d.client.addr, nil } diff --git a/rpc/dcrwallet.go b/rpc/dcrwallet.go index 8e7f5b9..174bef6 100644 --- a/rpc/dcrwallet.go +++ b/rpc/dcrwallet.go @@ -12,6 +12,7 @@ import ( "github.com/decred/dcrd/chaincfg/v3" dcrdtypes "github.com/decred/dcrd/rpc/jsonrpc/types/v3" "github.com/decred/dcrd/wire" + "github.com/decred/slog" ) var ( @@ -28,18 +29,20 @@ type WalletRPC struct { type WalletConnect struct { clients []*client params *chaincfg.Params + log slog.Logger } -func SetupWallet(user, pass, addrs []string, cert [][]byte, params *chaincfg.Params) WalletConnect { +func SetupWallet(user, pass, addrs []string, cert [][]byte, params *chaincfg.Params, log slog.Logger) WalletConnect { clients := make([]*client, len(addrs)) for i := 0; i < len(addrs); i++ { - clients[i] = setup(user[i], pass[i], addrs[i], cert[i]) + clients[i] = setup(user[i], pass[i], addrs[i], cert[i], log) } return WalletConnect{ clients: clients, params: params, + log: log, } } @@ -47,7 +50,7 @@ func (w *WalletConnect) Close() { for _, client := range w.clients { client.Close() } - log.Debug("dcrwallet clients closed") + w.log.Debug("dcrwallet clients closed") } // Clients loops over each wallet and tries to establish a connection. It @@ -62,7 +65,7 @@ func (w *WalletConnect) Clients() ([]*WalletRPC, []string) { c, newConnection, err := connect.dial(ctx) if err != nil { - log.Errorf("dcrwallet dial error: %v", err) + w.log.Errorf("dcrwallet dial error: %v", err) failedConnections = append(failedConnections, connect.addr) continue } @@ -78,7 +81,7 @@ func (w *WalletConnect) Clients() ([]*WalletRPC, []string) { var verMap map[string]dcrdtypes.VersionResult err = c.Call(ctx, "version", &verMap) if err != nil { - log.Errorf("dcrwallet.Version error (wallet=%s): %v", c.String(), err) + w.log.Errorf("dcrwallet.Version error (wallet=%s): %v", c.String(), err) failedConnections = append(failedConnections, connect.addr) connect.Close() continue @@ -86,7 +89,7 @@ func (w *WalletConnect) Clients() ([]*WalletRPC, []string) { ver, exists := verMap["dcrwalletjsonrpcapi"] if !exists { - log.Errorf("dcrwallet.Version response missing 'dcrwalletjsonrpcapi' (wallet=%s)", + w.log.Errorf("dcrwallet.Version response missing 'dcrwalletjsonrpcapi' (wallet=%s)", c.String()) failedConnections = append(failedConnections, connect.addr) connect.Close() @@ -95,7 +98,7 @@ func (w *WalletConnect) Clients() ([]*WalletRPC, []string) { sVer := semver{ver.Major, ver.Minor, ver.Patch} if !semverCompatible(requiredWalletVersion, sVer) { - log.Errorf("dcrwallet has incompatible JSON-RPC version (wallet=%s): got %s, expected %s", + w.log.Errorf("dcrwallet has incompatible JSON-RPC version (wallet=%s): got %s, expected %s", c.String(), sVer, requiredWalletVersion) failedConnections = append(failedConnections, connect.addr) connect.Close() @@ -106,13 +109,13 @@ func (w *WalletConnect) Clients() ([]*WalletRPC, []string) { var netID wire.CurrencyNet err = c.Call(ctx, "getcurrentnet", &netID) if err != nil { - log.Errorf("dcrwallet.GetCurrentNet error (wallet=%s): %v", c.String(), err) + w.log.Errorf("dcrwallet.GetCurrentNet error (wallet=%s): %v", c.String(), err) failedConnections = append(failedConnections, connect.addr) connect.Close() continue } if netID != w.params.Net { - log.Errorf("dcrwallet on wrong network (wallet=%s): running on %s, expected %s", + w.log.Errorf("dcrwallet on wrong network (wallet=%s): running on %s, expected %s", c.String(), netID, w.params.Net) failedConnections = append(failedConnections, connect.addr) connect.Close() @@ -123,7 +126,7 @@ func (w *WalletConnect) Clients() ([]*WalletRPC, []string) { walletRPC := &WalletRPC{c, ctx} walletInfo, err := walletRPC.WalletInfo() if err != nil { - log.Errorf("dcrwallet.WalletInfo error (wallet=%s): %v", c.String(), err) + w.log.Errorf("dcrwallet.WalletInfo error (wallet=%s): %v", c.String(), err) failedConnections = append(failedConnections, connect.addr) connect.Close() continue @@ -133,17 +136,17 @@ func (w *WalletConnect) Clients() ([]*WalletRPC, []string) { // All wallet should not be adding tickets found via the network. This // misconfiguration should not have a negative impact on users, so just // log an error here. Don't count this as a failed connection. - log.Errorf("wallet does not have manual tickets enabled (wallet=%s)", c.String()) + w.log.Errorf("wallet does not have manual tickets enabled (wallet=%s)", c.String()) } if !walletInfo.Voting { // All wallet RPCs can still be used if voting is disabled, so just // log an error here. Don't count this as a failed connection. - log.Errorf("wallet is not voting (wallet=%s)", c.String()) + w.log.Errorf("wallet is not voting (wallet=%s)", c.String()) } if !walletInfo.Unlocked { // SetVoteChoice can still be used even if the wallet is locked, so // just log an error here. Don't count this as a failed connection. - log.Errorf("wallet is not unlocked (wallet=%s)", c.String()) + w.log.Errorf("wallet is not unlocked (wallet=%s)", c.String()) } walletClients = append(walletClients, walletRPC) @@ -209,9 +212,6 @@ func (c *WalletRPC) TicketInfo(startHeight int64) (map[string]*wallettypes.Ticke return nil, err } - log.Debugf("TicketInfo RPC returned %d tickets (wallet=%s, startHeight=%d)", - len(result), c.String(), startHeight) - // For easier access later on, store the tickets in a map using their hash // as the key. tickets := make(map[string]*wallettypes.TicketInfoResult, len(result)) diff --git a/rpc/log.go b/rpc/log.go deleted file mode 100644 index 4795dc8..0000000 --- a/rpc/log.go +++ /dev/null @@ -1,30 +0,0 @@ -// Copyright (c) 2020 The Decred developers -// Use of this source code is governed by an ISC -// license that can be found in the LICENSE file. - -package rpc - -import ( - "github.com/decred/slog" -) - -// 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. -var log slog.Logger - -// The default amount of logging is none. -func init() { - DisableLog() -} - -// DisableLog disables all library log output. Logging output is disabled -// by default until UseLogger is called. -func DisableLog() { - log = slog.Disabled -} - -// UseLogger uses a specified Logger to output package logging info. -func UseLogger(logger slog.Logger) { - log = logger -} diff --git a/rpc/notifs.go b/rpc/notifs.go index 70f5394..3602deb 100644 --- a/rpc/notifs.go +++ b/rpc/notifs.go @@ -8,10 +8,12 @@ import ( "fmt" "github.com/decred/dcrd/wire" + "github.com/decred/slog" ) type blockConnectedHandler struct { blockConnected chan *wire.BlockHeader + log slog.Logger } // Notify is called every time a notification is received from dcrd client. @@ -25,7 +27,7 @@ func (n *blockConnectedHandler) Notify(method string, msg json.RawMessage) error header, err := parseBlockConnected(msg) if err != nil { - log.Errorf("Failed to parse dcrd block notification: %v", err) + n.log.Errorf("Failed to parse dcrd block notification: %v", err) return nil } diff --git a/signal.go b/signal.go index b358aca..3f7090c 100644 --- a/signal.go +++ b/signal.go @@ -9,6 +9,8 @@ import ( "context" "os" "os/signal" + + "github.com/decred/slog" ) // shutdownRequestChannel is used to initiate shutdown from one of the @@ -45,7 +47,7 @@ func requestShutdown() { // shutdownListener listens for shutdown requests and cancels all contexts // created from withShutdownCancel. This function never returns and is intended // to be spawned in a new goroutine. -func shutdownListener() { +func shutdownListener(log slog.Logger) { interruptChannel := make(chan os.Signal, 1) signal.Notify(interruptChannel, interruptSignals...) diff --git a/vspd.go b/vspd.go index 367750a..04bf998 100644 --- a/vspd.go +++ b/vspd.go @@ -13,7 +13,6 @@ import ( "time" "github.com/decred/dcrd/wire" - "github.com/decred/vspd/background" "github.com/decred/vspd/database" "github.com/decred/vspd/rpc" "github.com/decred/vspd/version" @@ -30,29 +29,33 @@ const maxVoteChangeRecords = 10 const consistencyInterval = 30 * time.Minute func main() { - // Create a context that is cancelled when a shutdown request is received - // through an interrupt signal. - shutdownCtx := withShutdownCancel(context.Background()) - go shutdownListener() - // Run until an exit code is returned. - os.Exit(run(shutdownCtx)) + os.Exit(run()) } // run is the main startup and teardown logic performed by the main package. It // is responsible for parsing the config, creating dcrd and dcrwallet RPC clients, // opening the database, starting the webserver, and stopping all started -// services when the provided context is cancelled. -func run(shutdownCtx context.Context) int { +// services when a shutdown is requested. +func run() int { // Load config file and parse CLI args. cfg, err := loadConfig() if err != nil { - // Don't use logger here because it may not be initialized. fmt.Fprintf(os.Stderr, "Config error: %v\n", err) return 1 } + log := cfg.Logger("VSP") + dbLog := cfg.Logger(" DB") + apiLog := cfg.Logger("API") + rpcLog := cfg.Logger("RPC") + + // Create a context that is cancelled when a shutdown request is received + // through an interrupt signal. + shutdownCtx := withShutdownCancel(context.Background()) + go shutdownListener(log) + // Show version at startup. log.Criticalf("Version %s (Go version %s %s/%s)", version.String(), runtime.Version(), runtime.GOOS, runtime.GOARCH) @@ -75,7 +78,7 @@ func run(shutdownCtx context.Context) int { defer log.Criticalf("Shutdown complete") // Open database. - db, err := database.Open(shutdownCtx, &shutdownWg, cfg.dbPath, cfg.BackupInterval, maxVoteChangeRecords) + db, err := database.Open(shutdownCtx, &shutdownWg, dbLog, cfg.dbPath, cfg.BackupInterval, maxVoteChangeRecords) if err != nil { log.Errorf("Database error: %v", err) requestShutdown() @@ -86,11 +89,11 @@ func run(shutdownCtx context.Context) int { // Create RPC client for local dcrd instance (used for broadcasting and // checking the status of fee transactions). - dcrd := rpc.SetupDcrd(cfg.DcrdUser, cfg.DcrdPass, cfg.DcrdHost, cfg.dcrdCert, cfg.netParams.Params) + dcrd := rpc.SetupDcrd(cfg.DcrdUser, cfg.DcrdPass, cfg.DcrdHost, cfg.dcrdCert, cfg.netParams.Params, rpcLog) defer dcrd.Close() // Create RPC client for remote dcrwallet instance (used for voting). - wallets := rpc.SetupWallet(cfg.walletUsers, cfg.walletPasswords, cfg.walletHosts, cfg.walletCerts, cfg.netParams.Params) + wallets := rpc.SetupWallet(cfg.walletUsers, cfg.walletPasswords, cfg.walletHosts, cfg.walletCerts, cfg.netParams.Params, rpcLog) defer wallets.Close() // Create a channel to receive blockConnected notifications from dcrd. @@ -104,7 +107,7 @@ func run(shutdownCtx context.Context) int { return case header := <-notifChan: log.Debugf("Block notification %d (%s)", header.Height, header.BlockHash().String()) - background.BlockConnected(dcrd, wallets, db) + BlockConnected(dcrd, wallets, db, log) } } }() @@ -140,11 +143,11 @@ func run(shutdownCtx context.Context) int { // Run the block connected handler now to catch up with any blocks mined // while vspd was shut down. - background.BlockConnected(dcrd, wallets, db) + BlockConnected(dcrd, wallets, db, log) // Run voting wallet consistency check now to ensure all wallets are up to // date. - background.CheckWalletConsistency(dcrd, wallets, db) + CheckWalletConsistency(dcrd, wallets, db, log) // Run voting wallet consistency check periodically. shutdownWg.Add(1) @@ -155,7 +158,7 @@ func run(shutdownCtx context.Context) int { shutdownWg.Done() return case <-time.After(consistencyInterval): - background.CheckWalletConsistency(dcrd, wallets, db) + CheckWalletConsistency(dcrd, wallets, db, log) } } }() @@ -174,7 +177,7 @@ func run(shutdownCtx context.Context) int { MaxVoteChangeRecords: maxVoteChangeRecords, VspdVersion: version.String(), } - err = webapi.Start(shutdownCtx, requestShutdown, &shutdownWg, cfg.Listen, db, + err = webapi.Start(shutdownCtx, requestShutdown, &shutdownWg, cfg.Listen, db, apiLog, dcrd, wallets, apiCfg) if err != nil { log.Errorf("Failed to initialize webapi: %v", err) diff --git a/webapi/log.go b/webapi/log.go deleted file mode 100644 index f74ff84..0000000 --- a/webapi/log.go +++ /dev/null @@ -1,30 +0,0 @@ -// Copyright (c) 2020 The Decred developers -// Use of this source code is governed by an ISC -// license that can be found in the LICENSE file. - -package webapi - -import ( - "github.com/decred/slog" -) - -// 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. -var log slog.Logger - -// The default amount of logging is none. -func init() { - DisableLog() -} - -// DisableLog disables all library log output. Logging output is disabled -// by default until UseLogger is called. -func DisableLog() { - log = slog.Disabled -} - -// UseLogger uses a specified Logger to output package logging info. -func UseLogger(logger slog.Logger) { - log = logger -} diff --git a/webapi/middleware.go b/webapi/middleware.go index f070a8d..f2248b5 100644 --- a/webapi/middleware.go +++ b/webapi/middleware.go @@ -312,7 +312,7 @@ func (s *Server) vspAuth(c *gin.Context) { } else { commitmentAddress, err = getCommitmentAddress(hash, dcrdClient, s.cfg.NetParams) if err != nil { - log.Errorf("%s: Failed to get commitment address (clientIP=%s, ticketHash=%s): %v", + s.log.Errorf("%s: Failed to get commitment address (clientIP=%s, ticketHash=%s): %v", funcName, c.ClientIP(), hash, err) var apiErr *apiError diff --git a/webapi/setaltsignaddr_test.go b/webapi/setaltsignaddr_test.go index 1d856f0..232134c 100644 --- a/webapi/setaltsignaddr_test.go +++ b/webapi/setaltsignaddr_test.go @@ -55,7 +55,7 @@ func randBytes(n int) []byte { func TestMain(m *testing.M) { // Set test logger to stdout. backend := slog.NewBackend(os.Stdout) - log = backend.Logger("test") + log := backend.Logger("test") log.SetLevel(slog.LevelTrace) // Set up some global params. @@ -73,11 +73,11 @@ func TestMain(m *testing.M) { var err error var wg sync.WaitGroup ctx, cancel := context.WithCancel(context.Background()) - err = database.CreateNew(testDb, feeXPub) + err = database.CreateNew(testDb, feeXPub, log) if err != nil { panic(fmt.Errorf("error creating test database: %w", err)) } - db, err := database.Open(ctx, &wg, testDb, time.Hour, maxVoteChangeRecords) + db, err := database.Open(ctx, &wg, log, testDb, time.Hour, maxVoteChangeRecords) if err != nil { panic(fmt.Errorf("error opening test database: %w", err)) } diff --git a/webapi/webapi.go b/webapi/webapi.go index 9f45463..ae06e65 100644 --- a/webapi/webapi.go +++ b/webapi/webapi.go @@ -75,7 +75,8 @@ type Server struct { } func Start(shutdownCtx context.Context, requestShutdown func(), shutdownWg *sync.WaitGroup, - listen string, vdb *database.VspDatabase, dcrd rpc.DcrdConnect, wallets rpc.WalletConnect, config Config) error { + listen string, vdb *database.VspDatabase, log slog.Logger, dcrd rpc.DcrdConnect, + wallets rpc.WalletConnect, config Config) error { s := &Server{ cfg: config, @@ -216,7 +217,7 @@ func (s *Server) router(cookieSecret []byte, dcrd rpc.DcrdConnect, wallets rpc.W // Recovery middleware handles any go panics generated while processing web // requests. Ensures a 500 response is sent to the client rather than // sending no response at all. - router.Use(Recovery(log)) + router.Use(Recovery(s.log)) if s.cfg.Debug { // Logger middleware outputs very detailed logging of webserver requests