Add basic transaction store logging.

The info log level (default) will produce output about confirmed and
unconfirmed transactions being inserted into the store, as well as
unconfirmed transactions which have been mined into blocks.  By
enabling the debug log level (-d TXST=debug), additional information
about transaction inputs and outputs is logged.  This includes the
total amount of previously-unspent outputs which have been marked
spent by the inserted transaction, and the output indexes and amounts
for each spendable output.  Additionally, the debug log level will log
whenever transactions are removed due to being a double spend of
another inserted transaction.

cmd.go

@@ -128,25 +128,14 @@ func clientConnect(certs []byte, newClient chan<- *rpcClient) {
 }
 
 func main() {
-	// Initialize logging and setup deferred flushing to ensure all
+	// Load configuration and parse command line.  This function also
-	// outstanding messages are written on shutdown
+	// initializes logging and configures it accordingly.
-	loggers := setLogLevel(defaultLogLevel)
-	defer func() {
-		for _, logger := range loggers {
-			logger.Flush()
-		}
-	}()
-
 	tcfg, _, err := loadConfig()
 	if err != nil {
 		os.Exit(1)
 	}
 	cfg = tcfg
-
+	defer backendLog.Flush()
-	// Change the logging level if needed.
-	if cfg.DebugLevel != defaultLogLevel {
-		loggers = setLogLevel(cfg.DebugLevel)
-	}
 
 	if cfg.Profile != "" {
 		go func() {

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
+	// Special show command to list supported subsystems and exit.
-	if !validLogLevel(cfg.DebugLevel) {
+	if cfg.DebugLevel == "show" {
-		str := "%s: The specified debug level [%v] is invalid"
+		fmt.Println("Supported subsystems", supportedSubsystems())
-		err := fmt.Errorf(str, "loadConfig", cfg.DebugLevel)
+		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
-}

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 (
+const (
-	log = seelog.Disabled
+	// 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
+// useLogger updates the logger references for subsystemID to logger.  Invalid
-// log message prefix.
+// subsystems are ignored.
-func newLogger(level string, prefix string) seelog.LoggerInterface {
+func useLogger(subsystemID string, logger btclog.Logger) {
-	//<seelog type="adaptive" mininterval="2000000" maxinterval="100000000"
+	if _, ok := subsystemLoggers[subsystemID]; !ok {
-	//      critmsgcount="500" minlevel="%s">
+		return
+	}
+	subsystemLoggers[subsystemID] = logger
 
-	fmtstring := `
+	switch subsystemID {
-        <seelog type="sync" minlevel="%s">
+	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 := `
+        <seelog type="adaptive" mininterval="2000000" maxinterval="100000000"
+                critmsgcount="500" minlevel="trace">
                 <outputs formatid="all">
-                        <console/>
+                        <console />
+                        <rollingfile type="size" filename="%s" maxsize="10485760" maxrolls="3" />
                 </outputs>
                 <formats>
-                        <format id="all" format="%%Time %%Date [%%LEV] %s: %%Msg%%n" />
+                        <format id="all" format="%%Time %%Date [%%LEV] %%Msg%%n" />
                 </formats>
         </seelog>`
-	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.
+// setLogLevel sets the logging level for provided subsystem.  Invalid
-func useLogger(logger seelog.LoggerInterface) {
+// subsystems are ignored.  Uninitialized subsystems are dynamically created as
-	log = logger
+// 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
+// setLogLevels sets the log level for all subsystem loggers to the passed
-// logger for each subsystem at the provided level.
+// level.  It also dynamically creates the subsystem loggers as needed, so it
-func setLogLevel(logLevel string) []seelog.LoggerInterface {
+// can be used to initialize the logging system.
-	var loggers []seelog.LoggerInterface
+func setLogLevels(logLevel string) {
-
+	// Configure all sub-systems with the new logging level.  Dynamically
-	// Define sub-systems.
+	// create loggers as needed.
-	subSystems := []struct {
+	for subsystemID := range subsystemLoggers {
-		level     string
+		setLogLevel(subsystemID, logLevel)
-		prefix    string
-		useLogger func(seelog.LoggerInterface)
-	}{
-		{logLevel, "BTCW", useLogger},
 	}
-
-	// 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

txstore/log.go

@@ -0,0 +1,68 @@
+/*
+ * Copyright (c) 2013, 2014 Conformal Systems LLC <info@conformal.com>
+ *
+ * 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
+}

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
 }