universe/supplyverifier: adding basic logging

Author: Roasbeef

universe/supplyverifier/env.go

@@ -6,6 +6,7 @@ import (
 	"time"
 
 	"github.com/btcsuite/btcd/wire"
+	"github.com/btcsuite/btclog/v2"
 	"github.com/lightninglabs/lndclient"
 	"github.com/lightninglabs/taproot-assets/asset"
 	"github.com/lightninglabs/taproot-assets/fn"
@@ -96,6 +97,9 @@ type Environment struct {
 	// that we're maintaining a supply commit for.
 	AssetSpec asset.Specifier
 
+	// AssetLog is the asset-specific logger for this state machine.
+	AssetLog btclog.Logger
+
 	// Chain is our access to the current main chain.
 	Chain tapgarden.ChainBridge
 
@@ -138,3 +142,14 @@ type Environment struct {
 func (e *Environment) Name() string {
 	return fmt.Sprintf("supply_verifier(%s)", e.AssetSpec.String())
 }
+
+// Logger returns the logger for the environment. If a logger is configured 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.AssetLog != nil {
+		return e.AssetLog
+	}
+
+	return NewAssetLogger(e.AssetSpec.String())
+}

universe/supplyverifier/log.go

@@ -1,6 +1,8 @@
 package supplyverifier
 
 import (
+	"fmt"
+
 	"github.com/btcsuite/btclog/v2"
 )
 
@@ -24,3 +26,10 @@ func DisableLog() {
 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 "SupplyVerifier(asset): message".
+func NewAssetLogger(assetSpec string) btclog.Logger {
+	return log.WithPrefix(fmt.Sprintf("SupplyVerifier(%v): ", assetSpec))
+}

universe/supplyverifier/manager.go

@@ -174,6 +174,8 @@ func (m *Manager) InitStateMachines() error {
 	ctx, cancel := m.WithCtxQuitNoTimeout()
 	defer cancel()
 
+	log.Infof("Initializing supply verifier state machines")
+
 	// First, get all assets with group keys that could potentially be
 	// involved in supply commitments. The Manager will filter these
 	// based on delegation key ownership and other criteria.
@@ -185,6 +187,9 @@ func (m *Manager) InitStateMachines() error {
 			err)
 	}
 
+	log.Debugf("Found %d potential asset groups for supply verification",
+		len(assetGroupKeys))
+
 	for idx := range assetGroupKeys {
 		groupKey := assetGroupKeys[idx]
 
@@ -195,6 +200,9 @@ func (m *Manager) InitStateMachines() error {
 		// already exist.
 		_, ok := m.smCache.Get(groupKey)
 		if ok {
+			log.Tracef("State machine already exists for "+
+				"asset group: %x",
+				groupKey.SerializeCompressed())
 			continue
 		}
 
@@ -217,6 +225,8 @@ func (m *Manager) Start() error {
 	var startErr error
 
 	m.startOnce.Do(func() {
+		log.Infof("Starting supply verifier manager")
+
 		// Initialize the state machine cache.
 		m.smCache = newStateMachineCache()
 
@@ -229,13 +239,17 @@ func (m *Manager) Start() error {
 			return
 		}
 
+		log.Debugf("Starting universe syncer event monitor")
+
 		// Start a goroutine to handle universe syncer issuance events.
 		m.ContextGuard.Goroutine(
 			m.MonitorUniSyncEvents, func(err error) {
 				log.Errorf("MonitorUniIssuanceSyncEvents: %v",
 					err)
 			},
 		)
+
+		log.Infof("Supply verifier manager started successfully")
 	})
 	if startErr != nil {
 		return fmt.Errorf("unable to start manager: %w", startErr)
@@ -273,6 +287,10 @@ func (m *Manager) handleUniSyncEvent(event fn.Event) error {
 		return nil
 	}
 
+	log.Tracef("Processing universe sync event for group key: %x, "+
+		"new_leaf_proofs=%d", universeID.GroupKey.SerializeCompressed(),
+		len(syncDiffEvent.SyncDiff.NewLeafProofs))
+
 	// Get genesis asset ID from the first synced leaf and formulate an
 	// asset specifier.
 	//
@@ -298,14 +316,17 @@ func (m *Manager) handleUniSyncEvent(event fn.Event) error {
 	cancelCtx()
 
 	if !isSupported {
+		log.Tracef("Asset does not support supply commitments: %s",
+			assetSpec.String())
 		return nil
 	}
 
-	// Fetch the state machine for the asset group, creating and starting it
-	// if it doesn't exist.
 	log.Debugf("Ensure supply verifier state machine for asset "+
 		"group due to universe syncer issuance event (asset=%s)",
 		assetSpec.String())
+
+	// Fetch the state machine for the asset group, creating and starting it
+	// if it doesn't exist.
 	_, err = m.fetchStateMachine(assetSpec)
 	if err != nil {
 		return fmt.Errorf("unable to get or create state machine: %w",
@@ -363,12 +384,16 @@ func (m *Manager) MonitorUniSyncEvents() error {
 // group key specific supply verifier state machines.
 func (m *Manager) Stop() error {
 	m.stopOnce.Do(func() {
+		log.Infof("Stopping supply verifier manager")
+
 		// Cancel the state machine context to signal all state machines
 		// to stop.
 		close(m.Quit)
 
 		// Stop all state machines.
 		m.smCache.StopAll()
+
+		log.Infof("Supply verifier manager stopped")
 	})
 
 	return nil
@@ -385,6 +410,7 @@ func (m *Manager) startAssetSM(ctx context.Context,
 	// If the state machine is not found, create a new one.
 	env := &Environment{
 		AssetSpec:        assetSpec,
+		AssetLog:         NewAssetLogger(assetSpec.String()),
 		Chain:            m.cfg.Chain,
 		SupplyCommitView: m.cfg.SupplyCommitView,
 		SupplyTreeView:   m.cfg.SupplyTreeView,
@@ -487,10 +513,15 @@ func (m *Manager) InsertSupplyCommit(ctx context.Context,
 	assetSpec asset.Specifier, commitment supplycommit.RootCommitment,
 	leaves supplycommit.SupplyLeaves) error {
 
+	log.Infof("Inserting supply commitment for asset: %s, "+
+		"commitment_outpoint=%s", assetSpec.String(),
+		commitment.CommitPoint().String())
+
 	// First, we verify the supply commitment to ensure it is valid and
 	// consistent with the given supply leaves.
 	verifier, err := NewVerifier(
 		VerifierCfg{
+			AssetSpec:        assetSpec,
 			ChainBridge:      m.cfg.Chain,
 			AssetLookup:      m.cfg.AssetLookup,
 			Lnd:              m.cfg.Lnd,

universe/supplyverifier/syncer.go

@@ -99,6 +99,9 @@ func (s *SupplySyncer) pushUniServer(ctx context.Context,
 	chainProof supplycommit.ChainProof,
 	serverAddr universe.ServerAddr) error {
 
+	log.Debugf("Pushing supply commitment to server: %s, asset: %s",
+		serverAddr.HostStr(), assetSpec.String())
+
 	// Create a client for the specific universe server address.
 	client, err := s.cfg.ClientFactory(serverAddr)
 	if err != nil {
@@ -128,6 +131,11 @@ func (s *SupplySyncer) pushUniServer(ctx context.Context,
 		return fmt.Errorf("unable to log supply commit push: %w", err)
 	}
 
+	log.Infof("Successfully pushed supply commitment to server: %s, "+
+		"asset: %s, commitment_outpoint=%s",
+		serverAddr.HostStr(), assetSpec.String(),
+		commitment.CommitPoint().String())
+
 	return nil
 }
 
@@ -183,6 +191,9 @@ func (s *SupplySyncer) PushSupplyCommitment(ctx context.Context,
 	chainProof supplycommit.ChainProof,
 	canonicalUniverses []url.URL) (map[string]error, error) {
 
+	log.Infof("Starting push of supply commitment for asset: %s to "+
+		"%d servers", assetSpec.String(), len(canonicalUniverses))
+
 	targetAddrs, err := s.fetchServerAddrs(ctx, canonicalUniverses)
 	if err != nil {
 		// This is an internal error that prevents the operation from
@@ -245,6 +256,10 @@ func (s *SupplySyncer) pullUniServer(ctx context.Context,
 
 	var zero supplycommit.FetchSupplyCommitResult
 
+	log.Debugf("Pulling supply commitment from server: %s, asset: %s, "+
+		"spent_outpoint=%v", serverAddr.HostStr(), assetSpec.String(),
+		spentCommitOutpoint.IsSome())
+
 	// Create a client for the specific universe server address.
 	client, err := s.cfg.ClientFactory(serverAddr)
 	if err != nil {
@@ -268,6 +283,9 @@ func (s *SupplySyncer) pullUniServer(ctx context.Context,
 			err)
 	}
 
+	log.Infof("Successfully pulled supply commitment from server: %s, "+
+		"asset: %s", serverAddr.HostStr(), assetSpec.String())
+
 	return result, nil
 }
 
@@ -297,6 +315,11 @@ func (s *SupplySyncer) PullSupplyCommitment(ctx context.Context,
 
 	var zero SupplyCommitPullResult
 
+	log.Infof("Starting pull of supply commitment for asset: %s, "+
+		"spent_outpoint=%v, canonical_universes=%d",
+		assetSpec.String(), spentCommitOutpoint.IsSome(),
+		len(canonicalUniverses))
+
 	targetAddrs, err := s.fetchServerAddrs(ctx, canonicalUniverses)
 	if err != nil {
 		// This is an internal error that prevents the operation from

universe/supplyverifier/transitions.go

@@ -21,6 +21,9 @@ func (s *InitState) ProcessEvent(event Event,
 
 	switch event.(type) {
 	case *InitEvent:
+		log.Debugf("Processing InitEvent for asset: %s",
+			env.AssetSpec.String())
+
 		ctx := context.Background()
 
 		// Retrieve the set of unspent pre-commitments for the asset
@@ -54,6 +57,12 @@ func (s *InitState) ProcessEvent(event Event,
 				"verified supply commitment found")
 		}
 
+		log.Infof("Transitioning from InitState to "+
+			"WatchOutputsState for asset: %s, "+
+			"pre_commits=%d, has_latest_commit=%v",
+			env.AssetSpec.String(), len(preCommits),
+			latestCommit != nil)
+
 		return &StateTransition{
 			NextState: &WatchOutputsState{},
 			NewEvents: lfn.Some(FsmEvent{
@@ -102,6 +111,9 @@ func (s *SyncVerifyState) ProcessEvent(event Event,
 
 	switch e := event.(type) {
 	case *SyncVerifyEvent:
+		log.Debugf("Processing SyncVerifyEvent for asset: %s",
+			env.AssetSpec.String())
+
 		ctx := context.Background()
 
 		// Check to ensure that we haven't already processed a supply
@@ -133,6 +145,10 @@ func (s *SyncVerifyState) ProcessEvent(event Event,
 					return nil, err
 				}
 
+				log.Debugf("Supply commitment already " +
+					"processed, transitioning to " +
+					"WatchOutputsState")
+
 				watchEvent := WatchOutputsEvent{
 					SupplyCommit: &commit,
 				}
@@ -185,6 +201,7 @@ func (s *SyncVerifyState) ProcessEvent(event Event,
 
 		verifier, err := NewVerifier(
 			VerifierCfg{
+				AssetSpec:        env.AssetSpec,
 				ChainBridge:      env.Chain,
 				AssetLookup:      env.AssetLookup,
 				Lnd:              env.Lnd,
@@ -207,6 +224,8 @@ func (s *SyncVerifyState) ProcessEvent(event Event,
 				"commitment: %w", err)
 		}
 
+		log.Debugf("Storing verified supply commitment")
+
 		// Store the verified commitment.
 		err = env.SupplyCommitView.InsertSupplyCommit(
 			ctx, env.AssetSpec, supplyCommit.RootCommitment,
@@ -217,6 +236,11 @@ func (s *SyncVerifyState) ProcessEvent(event Event,
 				"commitment: %w", err)
 		}
 
+		log.Infof("Successfully synced and verified supply "+
+			"commitment for asset: %s, "+
+			"transitioning to WatchOutputsState",
+			env.AssetSpec.String())
+
 		// After syncing, verifying, and storing the latest supply
 		// commitment, transition to the watch state to await its spend.
 		watchEvent := WatchOutputsEvent{
@@ -232,12 +256,18 @@ func (s *SyncVerifyState) ProcessEvent(event Event,
 		}, nil
 
 	case *SpendEvent:
+		log.Infof("Received SpendEvent for asset: %s, spend_tx=%s",
+			env.AssetSpec.String(),
+			e.SpendDetail.SpendingTx.TxHash())
+
 		// A watched output has been spent, so transition to the sync
 		// state to fetch the new supply commitment. Before syncing,
 		// apply a delay to give the issuer time to publish it.
 		switch {
 		case e.WatchStartTimestamp.IsZero():
 			// No watch start timestamp: wait the full sync delay.
+			log.Debugf("Waiting full sync delay of %v before "+
+				"syncing", env.SpendSyncDelay)
 			time.Sleep(env.SpendSyncDelay)
 
 		default:
@@ -246,6 +276,10 @@ func (s *SyncVerifyState) ProcessEvent(event Event,
 			timeSinceWatch := time.Since(e.WatchStartTimestamp)
 			if timeSinceWatch < env.SpendSyncDelay {
 				delay := env.SpendSyncDelay - timeSinceWatch
+
+				env.Logger().Debugf("Waiting remaining sync "+
+					"delay of %v before syncing", delay)
+
 				time.Sleep(delay)
 			}
 		}
@@ -283,6 +317,8 @@ func (s *WatchOutputsState) ProcessEvent(event Event,
 
 	switch e := event.(type) {
 	case *WatchOutputsEvent:
+		env.Logger().Debugf("Processing WatchOutputsEvent")
+
 		preCommits := e.PreCommits
 
 		// If no pre-commitments were provided, then we'll query our
@@ -342,6 +378,11 @@ func (s *WatchOutputsState) ProcessEvent(event Event,
 				Hash:  e.SupplyCommit.Txn.TxHash(),
 				Index: e.SupplyCommit.TxOutIdx,
 			}
+
+			env.Logger().Debugf("Registering spend watch for "+
+				"supply commitment outpoint: %s",
+				outpoint.String())
+
 			txOutIdx := e.SupplyCommit.TxOutIdx
 			txOut := e.SupplyCommit.Txn.TxOut[txOutIdx]
 
@@ -365,6 +406,9 @@ func (s *WatchOutputsState) ProcessEvent(event Event,
 			})
 		}
 
+		env.Logger().Infof("Transitioning to SyncVerifyState, "+
+			"watching %d outputs", len(events))
+
 		// Otherwise, we'll transition to the verify state to await
 		// a spend of one of the outputs we're watching.
 		return &StateTransition{