Merge pull request #1871 from lightninglabs/wip/proof-transfer-logging

Improve proof transfer logging and adjust log levels for clearer diagnostics

Author: ffranr

proof/archive.go

@@ -119,10 +119,34 @@ func (l *Locator) Hash() ([32]byte, error) {
 		}
 	}
 
-	// Hash the buffer.
 	return sha256.Sum256(buf.Bytes()), nil
 }
 
+// LogString returns a human-readable representation of the locator. This is
+// primarily used for logging purposes.
+func (l *Locator) LogString() (string, error) {
+	var zero string
+
+	assetSpec, err := asset.NewSpecifier(l.AssetID, l.GroupKey, nil, true)
+	if err != nil {
+		return zero, fmt.Errorf("unable to create asset specifier: %w",
+			err)
+	}
+
+	var outpointStr string
+	if l.OutPoint != nil {
+		outpointStr = l.OutPoint.String()
+	}
+
+	locatorHash, err := l.Hash()
+	if err != nil {
+		return zero, fmt.Errorf("hashing locator: %w", err)
+	}
+
+	return fmt.Sprintf("Locator(asset_spec=%s, outpoint=%s, hash=%x)",
+		assetSpec.String(), outpointStr, locatorHash), nil
+}
+
 // AnnotatedProof an annotated proof contains the raw proof blob along with a
 // locator that may convey additional information related to the proof.
 type AnnotatedProof struct {

proof/courier.go

@@ -11,6 +11,7 @@ import (
 	"time"
 
 	"github.com/btcsuite/btcd/btcec/v2"
+	"github.com/btcsuite/btclog/v2"
 	"github.com/lightninglabs/lightning-node-connect/hashmailrpc"
 	"github.com/lightninglabs/taproot-assets/asset"
 	"github.com/lightninglabs/taproot-assets/fn"
@@ -613,12 +614,12 @@ func (b *BackoffHandler) initialDelay(ctx context.Context,
 		return nil
 	}
 
-	locatorHash, err := proofLocator.Hash()
+	locatorStr, err := proofLocator.LogString()
 	if err != nil {
 		return err
 	}
-	log.Debugf("Handling initial proof transfer delay (locator_hash=%x)",
-		locatorHash[:])
+	log.DebugS(ctx, "Handling initial proof transfer delay", "locator",
+		locatorStr)
 
 	// Query delivery log to ensure a sensible rate of delivery attempts.
 	timestamps, err := b.transferLog.QueryProofTransferLog(
@@ -630,8 +631,8 @@ func (b *BackoffHandler) initialDelay(ctx context.Context,
 	}
 
 	if len(timestamps) == 0 {
-		log.Debugf("No previous transfer attempts found for proof "+
-			"(locator_hash=%x)", locatorHash[:])
+		log.DebugS(ctx, "No previous transfer attempts found for proof",
+			"locator", locatorStr)
 		return nil
 	}
 
@@ -648,9 +649,9 @@ func (b *BackoffHandler) initialDelay(ctx context.Context,
 	backoffResetWait := b.cfg.BackoffResetWait
 	if timeSinceLastAttempt < backoffResetWait {
 		waitDuration := backoffResetWait - timeSinceLastAttempt
-		log.Debugf("Waiting %v before attempting to transfer proof "+
-			"(locator_hash=%x) using backoff procedure",
-			waitDuration, locatorHash[:])
+		log.DebugS(ctx, "Backoff: waiting before attempting to "+
+			"transfer proof", "wait_duration", waitDuration,
+			"locator", locatorStr)
 
 		err := b.wait(ctx, waitDuration)
 		if err != nil {
@@ -672,13 +673,13 @@ func (b *BackoffHandler) Exec(ctx context.Context, proofLocator Locator,
 		return fmt.Errorf("backoff config not specified")
 	}
 
-	locatorHash, err := proofLocator.Hash()
+	locatorStr, err := proofLocator.LogString()
 	if err != nil {
-		return err
+		return fmt.Errorf("generate locator log string: %w", err)
 	}
-	log.Infof("Starting proof transfer backoff procedure "+
-		"(transfer_type=%s, locator_hash=%x)", transferType,
-		locatorHash[:])
+
+	log.InfoS(ctx, "Starting proof transfer backoff procedure",
+		"transfer_type", transferType, "locator", locatorStr)
 
 	// Conditionally perform an initial delay based on the transfer log to
 	// ensure that we don't spam the courier service with proof transfer
@@ -708,7 +709,7 @@ func (b *BackoffHandler) Exec(ctx context.Context, proofLocator Locator,
 				"attempt: %w", err)
 		}
 
-		// Execute target proof transfer function.
+		// Execute the target proof transfer function.
 		errExec = transferFunc()
 		if errExec == nil {
 			// The target function executed successfully, we can
@@ -732,10 +733,10 @@ func (b *BackoffHandler) Exec(ctx context.Context, proofLocator Locator,
 		)
 		subscriberEvent(waitEvent)
 
-		log.Debugf("Proof transfer failed with error. Backing off. "+
-			"(transfer_type=%s, locator_hash=%x, backoff=%s, "+
-			"attempt=%d): %v",
-			transferType, locatorHash[:], backoff, i, errExec)
+		log.DebugS(ctx, "Backing off: proof transfer failed",
+			"transfer_type", transferType, "locator",
+			locatorStr, "backoff", backoff, "attempt", i, "err",
+			errExec)
 
 		// Wait before reattempting execution.
 		err := b.wait(ctx, backoff)
@@ -976,8 +977,10 @@ func (h *HashMailCourier) DeliverProof(ctx context.Context, recipient Recipient,
 
 		return nil
 	}
+
+	backoffCtx := btclog.WithCtx(ctx, "addr", h.addr.String())
 	err := h.backoffHandle.Exec(
-		ctx, proof.Locator, SendTransferType, deliveryExec,
+		backoffCtx, proof.Locator, SendTransferType, deliveryExec,
 		h.publishSubscriberEvent,
 	)
 	if err != nil {
@@ -1550,8 +1553,10 @@ func (c *UniverseRpcCourier) DeliverProof(ctx context.Context,
 
 			return nil
 		}
+
+		backoffCtx := btclog.WithCtx(ctx, "addr", c.addr.String())
 		err = c.backoffHandle.Exec(
-			ctx, loc, SendTransferType, deliverFunc,
+			backoffCtx, loc, SendTransferType, deliverFunc,
 			c.publishSubscriberEvent,
 		)
 		if err != nil {
@@ -1626,8 +1631,10 @@ func (c *UniverseRpcCourier) ReceiveProof(ctx context.Context,
 
 			return nil
 		}
+
+		backoffCtx := btclog.WithCtx(ctx, "addr", c.addr.String())
 		err := c.backoffHandle.Exec(
-			ctx, loc, ReceiveTransferType, receiveFunc,
+			backoffCtx, loc, ReceiveTransferType, receiveFunc,
 			c.publishSubscriberEvent,
 		)
 		if err != nil {

proof/taproot.go

@@ -423,7 +423,7 @@ func (p TaprootProof) DeriveByAssetExclusion(assetCommitmentKey,
 	// asset ID, but we want to verify that the particular asset we care
 	// about isn't included.
 	default:
-		log.Debugf("Deriving commitment by asset exclusion")
+		log.Tracef("Deriving commitment by asset exclusion")
 		tapCommitment, err = p.CommitmentProof.
 			DeriveByAssetExclusion(assetCommitmentKey)
 	}
@@ -485,7 +485,7 @@ func deriveCommitmentKeys(commitment *commitment.TapCommitment,
 		commitmentKeys[downgradePubKey] = downgradedCommitment
 	}
 
-	log.Debugf("Derived Taproot Asset commitment by %s "+
+	log.Tracef("Derived Taproot Asset commitment by %s "+
 		"taproot_asset_root=%x, internal_key=%x, Commitment V2 "+
 		"taproot_key=%x, NonV2 taproot_key=%x",
 		proofType, fn.ByteSlice(commitment.TapscriptRoot(nil)),

universe/archive.go

@@ -129,7 +129,8 @@ func withUni[T any](fetcher uniFetcher, id Identifier,
 func (a *Archive) RootNode(ctx context.Context,
 	id Identifier) (Root, error) {
 
-	log.Debugf("Looking up root node for base Universe %v", spew.Sdump(id))
+	log.TraceS(ctx, "Looking up universe root node", "universe",
+		id.StringForLog())
 
 	return a.cfg.Multiverse.UniverseRootNode(ctx, id)
 }

universe/federation.go

@@ -751,8 +751,8 @@ func (f *FederationEnvoy) SyncServers(serverAddrs []ServerAddr) error {
 	syncServer := func(ctx context.Context, serverAddr ServerAddr) error {
 		err := f.syncServerState(ctx, serverAddr, *syncConfigs)
 		if err != nil {
-			log.Warnf("encountered an error whilst syncing with "+
-				"server=%v: %v", spew.Sdump(serverAddr), err)
+			log.WarnS(ctx, "Error syncing with universe", err,
+				"server", serverAddr.HostStr())
 		}
 		return nil
 	}

universe/syncer.go

@@ -301,8 +301,8 @@ func (s *SimpleSyncer) syncRoot(ctx context.Context, remoteRoot Root,
 
 	// If the local root matches the remote root, then we're done here.
 	case err == nil && mssmt.IsEqualNode(localRoot, remoteRoot):
-		log.Debugf("Root for %v matches, no sync needed",
-			uniID.String())
+		log.DebugS(ctx, "Universe roots match, no sync needed",
+			"universe", uniID.StringForLog())
 
 		return nil