diff --git a/cmd.go b/cmd.go index 4515cfe..763d0dd 100644 --- a/cmd.go +++ b/cmd.go @@ -128,25 +128,14 @@ func clientConnect(certs []byte, newClient chan<- *rpcClient) { } func main() { - // Initialize logging and setup deferred flushing to ensure all - // outstanding messages are written on shutdown - loggers := setLogLevel(defaultLogLevel) - defer func() { - for _, logger := range loggers { - logger.Flush() - } - }() - + // Load configuration and parse command line. This function also + // initializes logging and configures it accordingly. tcfg, _, err := loadConfig() if err != nil { os.Exit(1) } cfg = tcfg - - // Change the logging level if needed. - if cfg.DebugLevel != defaultLogLevel { - loggers = setLogLevel(cfg.DebugLevel) - } + defer backendLog.Flush() if cfg.Profile != "" { go func() { diff --git a/config.go b/config.go index 08873e5..d111826 100644 --- a/config.go +++ b/config.go @@ -24,6 +24,7 @@ import ( "net" "os" "path/filepath" + "sort" "strings" ) @@ -32,6 +33,8 @@ const ( defaultConfigFilename = "btcwallet.conf" defaultBtcNet = btcwire.TestNet3 defaultLogLevel = "info" + defaultLogDirname = "logs" + defaultLogFilename = "btcwallet.log" defaultKeypoolSize = 100 defaultDisallowFree = false ) @@ -44,6 +47,7 @@ var ( defaultDataDir = btcwalletHomeDir defaultRPCKeyFile = filepath.Join(btcwalletHomeDir, "rpc.key") defaultRPCCertFile = filepath.Join(btcwalletHomeDir, "rpc.cert") + defaultLogDir = filepath.Join(btcwalletHomeDir, defaultLogDirname) ) type config struct { @@ -54,6 +58,7 @@ type config struct { ConfigFile string `short:"C" long:"configfile" description:"Path to configuration file"` SvrListeners []string `long:"rpclisten" description:"Listen for RPC/websocket connections on this interface/port (default port: 18332, mainnet: 8332, simnet: 18554)"` DataDir string `short:"D" long:"datadir" description:"Directory to store wallets and transactions"` + LogDir string `"long:"logdir" description:"Directory to log output."` Username string `short:"u" long:"username" description:"Username for client and btcd authorization"` Password string `short:"P" long:"password" default-mask:"-" description:"Password for client and btcd authorization"` BtcdUsername string `long:"btcdusername" description:"Alternative username for btcd authorization"` @@ -84,6 +89,90 @@ func cleanAndExpandPath(path string) string { return filepath.Clean(os.ExpandEnv(path)) } +// 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": + 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 subsytems for stable display. + sort.Strings(subsystems) + return subsystems +} + +// 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 delimters, 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 subsytems %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 +} + // removeDuplicateAddresses returns a new slice with all duplicate entries in // addrs removed. func removeDuplicateAddresses(addrs []string) []string { @@ -146,6 +235,7 @@ func loadConfig() (*config, []string, error) { DebugLevel: defaultLogLevel, ConfigFile: defaultConfigFile, DataDir: defaultDataDir, + LogDir: defaultLogDir, RPCKey: defaultRPCKeyFile, RPCCert: defaultRPCCertFile, KeypoolSize: defaultKeypoolSize, @@ -243,10 +333,19 @@ func loadConfig() (*config, []string, error) { activeNet = &simNetParams } - // Validate debug log level - if !validLogLevel(cfg.DebugLevel) { - str := "%s: The specified debug level [%v] is invalid" - err := fmt.Errorf(str, "loadConfig", cfg.DebugLevel) + // Special show command to list supported subsystems and exit. + if cfg.DebugLevel == "show" { + fmt.Println("Supported subsystems", supportedSubsystems()) + os.Exit(0) + } + + // Initialize logging at the default logging level. + initSeelogLogger(filepath.Join(cfg.LogDir, defaultLogFilename)) + setLogLevels(defaultLogLevel) + + // Parse, validate, and set debug log level(s). + if err := parseAndSetDebugLevels(cfg.DebugLevel); err != nil { + err := fmt.Errorf("%s: %v", "loadConfig", err.Error()) fmt.Fprintln(os.Stderr, err) parser.WriteHelp(os.Stderr) return nil, nil, err @@ -318,22 +417,3 @@ func loadConfig() (*config, []string, error) { return &cfg, remainingArgs, 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": - return true - } - return false -} diff --git a/log.go b/log.go index bd93f6f..bfde3be 100644 --- a/log.go +++ b/log.go @@ -18,14 +18,37 @@ package main import ( "fmt" + "github.com/conformal/btclog" + "github.com/conformal/btcwallet/txstore" "github.com/conformal/seelog" "os" ) -var ( - log = seelog.Disabled +const ( + // lockTimeThreshold is the number below which a lock time is + // interpreted to be a block number. Since an average of one block + // is generated per 10 minutes, this allows blocks for about 9,512 + // years. However, if the field is interpreted as a timestamp, given + // the lock time is a uint32, the max is sometime around 2106. + lockTimeThreshold uint32 = 5e8 // Tue Nov 5 00:53:20 1985 UTC ) +// Loggers per subsytem. Note that backendLog is a seelog logger that all of +// the subsystem loggers route their messages to. When adding new subsystems, +// add a reference here, to the subsystemLoggers map, and the useLogger +// function. +var ( + backendLog = seelog.Disabled + log = btclog.Disabled + txstLog = btclog.Disabled +) + +// subsystemLoggers maps each subsystem identifier to its associated logger. +var subsystemLoggers = map[string]btclog.Logger{ + "BTCW": log, + "TXST": txstLog, +} + // 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 @@ -42,22 +65,38 @@ func newLogClosure(c func() string) logClosure { return logClosure(c) } -// newLogger creates a new seelog logger using the provided logging level and -// log message prefix. -func newLogger(level string, prefix string) seelog.LoggerInterface { - // +// useLogger updates the logger references for subsystemID to logger. Invalid +// subsystems are ignored. +func useLogger(subsystemID string, logger btclog.Logger) { + if _, ok := subsystemLoggers[subsystemID]; !ok { + return + } + subsystemLoggers[subsystemID] = logger - fmtstring := ` - + switch subsystemID { + case "BTCW": + log = logger + case "TXST": + txstLog = logger + txstore.UseLogger(logger) + } +} + +// initSeelogLogger initializes a new seelog logger that is used as the backend +// for all logging subsytems. +func initSeelogLogger(logFile string) { + config := ` + - + + - + ` - config := fmt.Sprintf(fmtstring, level, prefix) + config = fmt.Sprintf(config, logFile) logger, err := seelog.LoggerFromConfigAsString(config) if err != nil { @@ -65,37 +104,42 @@ func newLogger(level string, prefix string) seelog.LoggerInterface { os.Exit(1) } - return logger + backendLog = logger } -// useLogger sets the btcd logger to the passed logger. -func useLogger(logger seelog.LoggerInterface) { - log = logger +// 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 + } + + // Default to info if the log level is invalid. + level, ok := btclog.LogLevelFromString(logLevel) + if !ok { + level = btclog.InfoLvl + } + + // Create new logger for the subsystem if needed. + if logger == btclog.Disabled { + logger = btclog.NewSubsystemLogger(backendLog, subsystemID+": ") + useLogger(subsystemID, logger) + } + logger.SetLevel(level) } -// setLogLevel sets the log level for the logging system. It initializes a -// logger for each subsystem at the provided level. -func setLogLevel(logLevel string) []seelog.LoggerInterface { - var loggers []seelog.LoggerInterface - - // Define sub-systems. - subSystems := []struct { - level string - prefix string - useLogger func(seelog.LoggerInterface) - }{ - {logLevel, "BTCW", useLogger}, +// 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) } - - // Configure all sub-systems with new loggers while keeping track of - // the created loggers to return so they can be flushed. - for _, s := range subSystems { - newLog := newLogger(s.level, s.prefix) - loggers = append(loggers, newLog) - s.useLogger(newLog) - } - - return loggers } // pickNoun returns the singular or plural form of a noun depending diff --git a/txstore/log.go b/txstore/log.go new file mode 100644 index 0000000..0012473 --- /dev/null +++ b/txstore/log.go @@ -0,0 +1,68 @@ +/* + * Copyright (c) 2013, 2014 Conformal Systems LLC + * + * Permission to use, copy, modify, and distribute this software for any + * purpose with or without fee is hereby granted, provided that the above + * copyright notice and this permission notice appear in all copies. + * + * THE SOFTWARE IS PROVIDED "AS IS" AND THE AUTHOR DISCLAIMS ALL WARRANTIES + * WITH REGARD TO THIS SOFTWARE INCLUDING ALL IMPLIED WARRANTIES OF + * MERCHANTABILITY AND FITNESS. IN NO EVENT SHALL THE AUTHOR BE LIABLE FOR + * ANY SPECIAL, DIRECT, INDIRECT, OR CONSEQUENTIAL DAMAGES OR ANY DAMAGES + * WHATSOEVER RESULTING FROM LOSS OF USE, DATA OR PROFITS, WHETHER IN AN + * ACTION OF CONTRACT, NEGLIGENCE OR OTHER TORTIOUS ACTION, ARISING OUT OF + * OR IN CONNECTION WITH THE USE OR PERFORMANCE OF THIS SOFTWARE. + */ + +package txstore + +import "github.com/conformal/btclog" + +// 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 btclog.Logger + +// The default amount of logging is none. +func init() { + DisableLog() +} + +// DisableLog disables all library log output. Logging output is disabled +// by default until either UseLogger or SetLogWriter are called. +func DisableLog() { + log = btclog.Disabled +} + +// UseLogger uses a specified Logger to output package logging info. +// This should be used in preference to SetLogWriter if the caller is also +// using btclog. +func UseLogger(logger btclog.Logger) { + log = logger +} + +// LogClosure is a closure that can be printed with %v to be used to +// generate expensive-to-create data for a detailed log level and avoid doing +// the work if the data isn't printed. +type logClosure func() string + +// String invokes the log closure and returns the results string. +func (c logClosure) String() string { + return c() +} + +// newLogClosure returns a new closure over the passed function which allows +// it to be used as a parameter in a logging function that is only invoked when +// the logging level is such that the message will actually be logged. +func newLogClosure(c func() string) logClosure { + return logClosure(c) +} + +// pickNoun returns the singular or plural form of a noun depending +// on the count n. +func pickNoun(n int, singular, plural string) string { + if n == 1 { + return singular + } + return plural +} diff --git a/txstore/tx.go b/txstore/tx.go index 3f9c0eb..1dfb0d8 100644 --- a/txstore/tx.go +++ b/txstore/tx.go @@ -362,6 +362,8 @@ func (c *blockTxCollection) txRecordForInserts(tx *btcutil.Tx) *txRecord { if i, ok := c.txIndexes[tx.Index()]; ok { return c.txs[i] } + + log.Infof("Inserting transaction %v from block %d", tx.Sha(), c.Height) record := &txRecord{tx: tx} // If this new transaction record cannot be appended to the end of the @@ -395,6 +397,7 @@ func (s *Store) blockTxRecordForInserts(tx *btcutil.Tx, block *Block) *txRecord func (u *unconfirmedStore) txRecordForInserts(tx *btcutil.Tx) *txRecord { r, ok := u.txs[*tx.Sha()] if !ok { + log.Infof("Inserting unconfirmed transaction %v", tx.Sha()) r = &txRecord{tx: tx} u.txs[*tx.Sha()] = r for _, input := range r.Tx().MsgTx().TxIn { @@ -405,6 +408,9 @@ func (u *unconfirmedStore) txRecordForInserts(tx *btcutil.Tx) *txRecord { } func (s *Store) moveMinedTx(r *txRecord, block *Block) error { + log.Infof("Marking unconfirmed transaction %v mined in block %d", + r.tx.Sha(), block.Height) + delete(s.unconfirmed.txs, *r.Tx().Sha()) // Find collection and insert records. Error out if there are records @@ -596,6 +602,10 @@ func (t *TxRecord) AddDebits(spent []Credit) (Debits, error) { return Debits{}, err } t.debits = &debits{amount: debitAmount} + + log.Debugf("Transaction %v spends %d previously-unspent "+ + "%s totaling %v", t.tx.Sha(), len(spent), + pickNoun(len(spent), "output", "outputs"), debitAmount) } switch t.BlockHeight { @@ -762,6 +772,10 @@ func (t *TxRecord) AddCredit(index uint32, change bool) (Credit, error) { return Credit{}, err } + txOutAmt := btcutil.Amount(t.tx.MsgTx().TxOut[index].Value) + log.Debugf("Marking transaction %v output %d (%v) spendable", + t.tx.Sha(), index, txOutAmt) + switch t.BlockHeight { case -1: // unconfirmed default: @@ -773,11 +787,11 @@ func (t *TxRecord) AddCredit(index uint32, change bool) (Credit, error) { // New outputs are added unspent. op := btcwire.OutPoint{Hash: *t.tx.Sha(), Index: index} t.s.unspent[op] = t.BlockTxKey - switch a := t.tx.MsgTx().TxOut[index].Value; t.tx.Index() { + switch t.tx.Index() { case 0: // Coinbase - b.amountDeltas.Reward += btcutil.Amount(a) + b.amountDeltas.Reward += txOutAmt default: - b.amountDeltas.Spendable += btcutil.Amount(a) + b.amountDeltas.Spendable += txOutAmt } } @@ -939,6 +953,7 @@ func (s *Store) UnminedDebitTxs() []*btcutil.Tx { // removed transactions are set to unspent. func (s *Store) removeDoubleSpends(tx *btcutil.Tx) error { if ds := s.unconfirmed.findDoubleSpend(tx); ds != nil { + log.Debugf("Removing double spending transaction %v", ds.tx.Sha()) return s.removeConflict(ds) } return nil @@ -971,6 +986,8 @@ func (s *Store) removeConflict(r *txRecord) error { if !ok { return ErrInconsistentStore } + log.Debugf("Transaction %v is part of a removed double spend "+ + "chain -- removing as well", nextSpender.tx.Sha()) if err := s.removeConflict(nextSpender); err != nil { return err } @@ -1010,6 +1027,7 @@ func (s *Store) removeConflict(r *txRecord) error { for _, input := range r.Tx().MsgTx().TxIn { delete(u.previousOutpoints, input.PreviousOutpoint) } + return nil }