proof: enhance backoff procedure locator logging

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

@@ -5,7 +5,6 @@ import (
 	"context"
 	"crypto/sha512"
 	"crypto/tls"
-	"encoding/hex"
 	"fmt"
 	"net/url"
 	"sync"
@@ -615,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(
@@ -632,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
 	}
 
@@ -650,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 {
@@ -674,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.InfoS(ctx, "Starting proof transfer backoff procedure",
-		"transfer_type", transferType, "locator_hash",
-		hex.EncodeToString(locatorHash[:]))
+		"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
@@ -735,9 +734,9 @@ func (b *BackoffHandler) Exec(ctx context.Context, proofLocator Locator,
 		subscriberEvent(waitEvent)
 
 		log.DebugS(ctx, "Backing off: proof transfer failed",
-			"transfer_type", transferType, "locator_hash",
-			hex.EncodeToString(locatorHash[:]), "backoff", backoff,
-			"attempt", i, "err", errExec)
+			"transfer_type", transferType, "locator",
+			locatorStr, "backoff", backoff, "attempt", i, "err",
+			errExec)
 
 		// Wait before reattempting execution.
 		err := b.wait(ctx, backoff)