universe/supplycommit: add additional logging

Author: Roasbeef

universe/supplycommit/env.go

@@ -12,6 +12,7 @@ import (
 	"github.com/btcsuite/btcd/chaincfg/chainhash"
 	"github.com/btcsuite/btcd/txscript"
 	"github.com/btcsuite/btcd/wire"
+	"github.com/btcsuite/btclog/v2"
 	"github.com/lightninglabs/taproot-assets/asset"
 	"github.com/lightninglabs/taproot-assets/fn"
 	"github.com/lightninglabs/taproot-assets/mssmt"
@@ -509,6 +510,9 @@ type Environment struct {
 	// ChainParams is the chain parameters for the chain that we're
 	// operating on.
 	ChainParams chaincfg.Params
+
+	// Log is the prefixed logger for this supply commitment state machine.
+	Log btclog.Logger
 }
 
 // SupplyCommitTxn encapsulates the details of the transaction that creates a
@@ -534,3 +538,14 @@ type SupplyCommitTxn struct {
 func (e *Environment) Name() string {
 	return fmt.Sprintf("universe_supply_commit(%v)", e.AssetSpec)
 }
+
+// Logger returns the logger for this environment. If a logger was provided in
+// the environment configuration, it returns that logger. Otherwise, it returns
+// the package-level logger with an asset-specific prefix.
+func (e *Environment) Logger() btclog.Logger {
+	if e.Log != nil {
+		return e.Log
+	}
+
+	return NewAssetLogger(e.AssetSpec.String())
+}

universe/supplycommit/log.go

@@ -1,7 +1,10 @@
 package supplycommit
 
 import (
+	"fmt"
+
 	"github.com/btcsuite/btclog/v2"
+	"github.com/davecgh/go-spew/spew"
 )
 
 // Subsystem defines the logging code for this subsystem.
@@ -18,9 +21,23 @@ func DisableLog() {
 	UseLogger(btclog.Disabled)
 }
 
+// limitSpewer is a spew.ConfigState that limits the depth of the output to 4
+// levels, so it can safely be used for things that contain an MS-SMT tree.
+var limitSpewer = &spew.ConfigState{
+	Indent:   "  ",
+	MaxDepth: 4,
+}
+
 // 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
 }
+
+// NewAssetLogger creates a new prefixed logger for a specific asset. This
+// logger will automatically include the asset specifier in all log messages,
+// using the format "SupplyCommit(asset): message".
+func NewAssetLogger(assetSpec string) btclog.Logger {
+	return log.WithPrefix(fmt.Sprintf("SupplyCommit(%v): ", assetSpec))
+}

universe/supplycommit/transitions.go

@@ -8,6 +8,7 @@ import (
 	"github.com/btcsuite/btcd/btcutil/psbt"
 	"github.com/btcsuite/btcd/chaincfg"
 	"github.com/btcsuite/btcd/wire"
+	"github.com/btcsuite/btclog/v2"
 	"github.com/lightninglabs/taproot-assets/asset"
 	"github.com/lightninglabs/taproot-assets/mssmt"
 	"github.com/lightninglabs/taproot-assets/proof"
@@ -66,11 +67,16 @@ func createCommitmentTxLabel(assetSpec asset.Specifier,
 func (d *DefaultState) ProcessEvent(event Event,
 	env *Environment) (*StateTransition, error) {
 
+	prefixedLog := env.Logger()
+
 	// In this state, we'll receive one of three events: a new burn, a new
 	// mint, or a new ignore. For all three types, we'll emit this as an
 	// internal event as we transition to the UpdatePendingState.
 	switch supplyEvent := event.(type) {
 	case SyncSupplyUpdateEvent:
+		prefixedLog.Infof("Received new supply update event: %T",
+			supplyEvent)
+
 		// Before we transition to the next state, we'll add this event
 		// to our update log. This ensures that we'll remember to
 		// process from this state after a restart.
@@ -120,10 +126,15 @@ func (d *DefaultState) ProcessEvent(event Event,
 func (u *UpdatesPendingState) ProcessEvent(event Event, env *Environment) (
 	*StateTransition, error) {
 
+	prefixedLog := env.Logger()
+
 	switch newEvent := event.(type) {
 	// We've received a new update event, we'll stage this in our local
 	// state, and do a self transition.
 	case SyncSupplyUpdateEvent:
+		prefixedLog.Infof("Received new supply update event: %T",
+			newEvent)
+
 		// We just got a new pending update in addition to the one that
 		// made us transition to this state. This ensures that we'll
 		// remember to process from this state after a restart.
@@ -163,6 +174,9 @@ func (u *UpdatesPendingState) ProcessEvent(event Event, env *Environment) (
 				"pending transition: %w", err)
 		}
 
+		prefixedLog.Infof("Received tick event, committing %d "+
+			"supply updates", len(u.pendingUpdates))
+
 		return &StateTransition{
 			NextState: &CommitTreeCreateState{},
 			NewEvents: lfn.Some(FsmEvent{
@@ -254,13 +268,18 @@ func applyTreeUpdates(supplyTrees SupplyTrees,
 func (c *CommitTreeCreateState) ProcessEvent(event Event,
 	env *Environment) (*StateTransition, error) {
 
+	prefixedLog := env.Logger()
+
 	// TODO(roasbeef): cache attemps to add new elements? or main state
 	// driver still single threaded?
 
 	switch newEvent := event.(type) {
 	// If we get a supply update event while we're creating the tree,
 	// we'll just insert it as a dangling update and do a self-transition.
 	case SyncSupplyUpdateEvent:
+		prefixedLog.Infof("Received new supply update event: %T",
+			newEvent)
+
 		ctx := context.Background()
 		err := env.StateLog.InsertPendingUpdate(
 			ctx, env.AssetSpec, newEvent,
@@ -291,6 +310,10 @@ func (c *CommitTreeCreateState) ProcessEvent(event Event,
 	case *CreateTreeEvent:
 		pendingUpdates := newEvent.updatesToCommit
 
+		prefixedLog.Infof("Creating new supply trees "+
+			"with %d pending updates",
+			len(pendingUpdates))
+
 		// TODO(ffranr): Pass in context?
 		ctx := context.Background()
 
@@ -396,7 +419,13 @@ func newRootCommitment(ctx context.Context,
 	oldCommitment lfn.Option[RootCommitment],
 	unspentPreCommits []PreCommitment, newSupplyRoot *mssmt.BranchNode,
 	wallet Wallet, keyRing KeyRing,
-	chainParams chaincfg.Params) (*RootCommitment, *psbt.Packet, error) {
+	chainParams chaincfg.Params,
+	logger lfn.Option[btclog.Logger]) (*RootCommitment, *psbt.Packet, error) {
+
+	logger.WhenSome(func(l btclog.Logger) {
+		l.Infof("Creating new root commitment, spending %v "+
+			"pre-commits", len(unspentPreCommits))
+	})
 
 	newCommitTx := wire.NewMsgTx(2)
 
@@ -435,6 +464,11 @@ func newRootCommitment(ctx context.Context,
 	// on mint transactions where as the old commitment is the last
 	// commitment that was broadcast.
 	oldCommitment.WhenSome(func(r RootCommitment) {
+		logger.WhenSome(func(l btclog.Logger) {
+			l.Infof("Re-using prior commitment as outpoint=%v: %v",
+				r.CommitPoint(), limitSpewer.Sdump(r))
+		})
+
 		newCommitTx.AddTxIn(r.TxIn())
 
 		bip32Derivation, trBip32Derivation :=
@@ -459,11 +493,12 @@ func newRootCommitment(ctx context.Context,
 		})
 	})
 
+	// TODO(roasbef): do CreateTaprootSignature instead?
 	// With the inputs available, derive the supply commitment output.
 	//
-	// Determine the internal key to use for this output.
-	// If a prior root commitment exists, reuse its internal key;
-	// otherwise, generate a new one.
+	// Determine the internal key to use for this output. If a prior root
+	// commitment exists, reuse its internal key; otherwise, generate a new
+	// one.
 	iKeyOpt := lfn.MapOption(func(r RootCommitment) keychain.KeyDescriptor {
 		return r.InternalKey
 	})(oldCommitment)
@@ -534,6 +569,11 @@ func newRootCommitment(ctx context.Context,
 		SupplyRoot:  newSupplyRoot,
 	}
 
+	logger.WhenSome(func(l btclog.Logger) {
+		l.Infof("Created new root commitment: %v",
+			limitSpewer.Sdump(newSupplyCommit))
+	})
+
 	commitPkt, err := psbt.NewFromUnsignedTx(newCommitTx)
 	if err != nil {
 		return nil, nil, fmt.Errorf("unable to create PSBT: %w", err)
@@ -608,10 +648,15 @@ func fundSupplyCommitTx(ctx context.Context, supplyCommit *RootCommitment,
 func (c *CommitTxCreateState) ProcessEvent(event Event,
 	env *Environment) (*StateTransition, error) {
 
+	prefixedLog := env.Logger()
+
 	switch newEvent := event.(type) {
 	// If we get a supply update event while we're creating the commit tx,
 	// we'll just insert it as a dangling update and do a self-transition.
 	case SyncSupplyUpdateEvent:
+		prefixedLog.Infof("Received new supply update event: %T",
+			newEvent)
+
 		ctx := context.Background()
 		err := env.StateLog.InsertPendingUpdate(
 			ctx, env.AssetSpec, newEvent,
@@ -635,6 +680,8 @@ func (c *CommitTxCreateState) ProcessEvent(event Event,
 	case *CreateTxEvent:
 		ctx := context.Background()
 
+		prefixedLog.Infof("Creating new supply commitment tx")
+
 		// To create the new commitment, we'll fetch the unspent pre
 		// commitments, the current supply root (which may not exist),
 		// and the new supply root.
@@ -659,6 +706,7 @@ func (c *CommitTxCreateState) ProcessEvent(event Event,
 		newSupplyCommit, commitPkt, err := newRootCommitment(
 			ctx, oldCommitment, preCommits, newSupplyRoot,
 			env.Wallet, env.KeyRing, env.ChainParams,
+			lfn.Some(prefixedLog),
 		)
 		if err != nil {
 			return nil, fmt.Errorf("unable to create "+
@@ -711,6 +759,8 @@ func (c *CommitTxCreateState) ProcessEvent(event Event,
 func (s *CommitTxSignState) ProcessEvent(event Event,
 	env *Environment) (*StateTransition, error) {
 
+	prefixedLog := env.Logger()
+
 	switch newEvent := event.(type) {
 	// If we get a supply update event while we're signing the commit tx,
 	// we'll just insert it as a dangling update and do a self-transition.
@@ -728,6 +778,9 @@ func (s *CommitTxSignState) ProcessEvent(event Event,
 
 		newEvent.SignalDone(nil)
 
+		prefixedLog.Infof("Received new supply update "+
+			"event: %T", newEvent)
+
 		return &StateTransition{
 			NextState: s,
 		}, nil
@@ -741,7 +794,7 @@ func (s *CommitTxSignState) ProcessEvent(event Event,
 		stateTransition := s.SupplyTransition
 
 		// After some initial validation, we'll now sign the PSBT.
-		log.Debug("Signing supply commitment PSBT")
+		prefixedLog.Debug("Signing supply commitment PSBT")
 		signedPsbt, err := env.Wallet.SignPsbt(
 			ctx, newEvent.CommitPkt.Pkt,
 		)
@@ -750,10 +803,13 @@ func (s *CommitTxSignState) ProcessEvent(event Event,
 				"commitment tx: %w", err)
 		}
 
+		prefixedLog.Infof("Signed supply "+
+			"commitment txn: %v", limitSpewer.Sdump(signedPsbt))
+
 		err = psbt.MaybeFinalizeAll(signedPsbt)
 		if err != nil {
-			return nil, fmt.Errorf("unable to finalize psbt: %w",
-				err)
+			return nil, fmt.Errorf("unable to finalize "+
+				"psbt: %w", err)
 		}
 
 		commitTx, err := psbt.Extract(signedPsbt)
@@ -805,11 +861,17 @@ func (s *CommitTxSignState) ProcessEvent(event Event,
 func (c *CommitBroadcastState) ProcessEvent(event Event,
 	env *Environment) (*StateTransition, error) {
 
+	prefixedLog := env.Logger()
+
 	switch newEvent := event.(type) {
 	// If we get a supply update event while we're broadcasting the commit
 	// tx, we'll just insert it as a dangling update and do a
 	// self-transition.
 	case SyncSupplyUpdateEvent:
+		prefixedLog.Infof("Received new supply update %T while "+
+			"finalizing prior commitment, inserting as dangling update",
+			newEvent)
+
 		ctx := context.Background()
 		err := env.StateLog.InsertPendingUpdate(
 			ctx, env.AssetSpec, newEvent,
@@ -835,6 +897,11 @@ func (c *CommitBroadcastState) ProcessEvent(event Event,
 			return nil, fmt.Errorf("commitment transaction is nil")
 		}
 
+		commitTxid := c.SupplyTransition.NewCommitment.Txn.TxHash()
+		prefixedLog.Infof("Broadcasting supply commitment "+
+			"txn (txid=%v): %v", commitTxid,
+			limitSpewer.Sdump(c.SupplyTransition.NewCommitment.Txn))
+
 		commitTx := c.SupplyTransition.NewCommitment.Txn
 
 		// Construct a detailed label for the broadcast request using
@@ -912,18 +979,20 @@ func (c *CommitBroadcastState) ProcessEvent(event Event,
 				"proof: %w", err)
 		}
 
+		// Now that the transaction has been confirmed, we'll construct
+		// a merkle proof for the commitment transaction. This'll be
+		// used to prove that the supply commit is canonical.
 		stateTransition.ChainProof = lfn.Some(ChainProof{
 			Header:      newEvent.Block.Header,
 			BlockHeight: newEvent.BlockHeight,
 			MerkleProof: *merkleProof,
 			TxIndex:     newEvent.TxIndex,
 		})
 
-		// Now that the transaction has been confirmed, we'll construct
-		// a merkle proof for the commitment transaction. This'll be
-		// used to prove that the supply commit is canonical.
-		//
-		// TODO(roasbeef): need header and txindex, etc to construct
+		prefixedLog.Infof("Supply commitment txn confirmed "+
+			"in block %d (hash=%v): %v",
+			newEvent.BlockHeight, newEvent.Block.Header.BlockHash(),
+			limitSpewer.Sdump(c.SupplyTransition.NewCommitment.Txn))
 
 		// The commitment has been confirmed, so we'll transition to the
 		// finalize state, but also log on disk that we no longer need
@@ -960,10 +1029,16 @@ func (c *CommitBroadcastState) ProcessEvent(event Event,
 func (c *CommitFinalizeState) ProcessEvent(event Event,
 	env *Environment) (*StateTransition, error) {
 
+	prefixedLog := env.Logger()
+
 	switch newEvent := event.(type) {
 	// If we get a supply update event while we're finalizing the commit,
 	// we'll just insert it as a dangling update and do a self-transition.
 	case SyncSupplyUpdateEvent:
+		prefixedLog.Infof("Received new supply update %T while "+
+			"finalizing prior commitment, inserting as dangling "+
+			"update", newEvent)
+
 		ctx := context.Background()
 		err := env.StateLog.InsertPendingUpdate(
 			ctx, env.AssetSpec, newEvent,
@@ -987,6 +1062,8 @@ func (c *CommitFinalizeState) ProcessEvent(event Event,
 	case *FinalizeEvent:
 		ctx := context.Background()
 
+		prefixedLog.Infof("Finalizing supply commitment transition")
+
 		// At this point, the commitment has been confirmed on disk, so
 		// we can update: the state machine state on disk, and swap in
 		// all the new supply tree information.
@@ -1021,6 +1098,9 @@ func (c *CommitFinalizeState) ProcessEvent(event Event,
 			}, nil
 		}
 
+		prefixedLog.Infof("Dangling updates found: %d",
+			len(danglingUpdates))
+
 		// Otherwise, we have more work to do! We'll kick off a new
 		// commitment cycle right away by transitioning to the tree
 		// creation state.