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