Merge pull request #1853 from lightninglabs/wip/improve-troubleshoot-logging

Improve troubleshooting logs for bug reports 1845 and 1850

Author: ffranr

address/book.go

@@ -535,7 +535,7 @@ func (b *Book) NewAddress(ctx context.Context, addrVersion Version,
 	error) {
 
 	// Before we proceed and make new keys, make sure that we actually know
-	// of this asset ID, or can import it.
+	// of this asset, or can import it.
 	if _, err := b.QueryAssetInfo(ctx, specifier); err != nil {
 		return nil, fmt.Errorf("unable to make address for unknown "+
 			"asset %s: %w", &specifier, err)

authmailbox/receive_subscription.go

@@ -249,8 +249,9 @@ func (s *receiveSubscription) connectServerStream(ctx context.Context,
 		if backoff > s.cfg.MaxBackoff {
 			backoff = s.cfg.MaxBackoff
 		}
-		log.DebugS(ctx, "Connect failed with error, canceling and "+
-			"backing off", "backoff", backoff, "err", err)
+		log.WarnS(ctx, "Connect failed with error, canceling and "+
+			"backing off", err, "backoff", backoff, "client_config",
+			s.cfg)
 
 		if i < numRetries-1 {
 			log.InfoS(ctx, "Connection to server failed, will try "+
@@ -278,7 +279,8 @@ func (s *receiveSubscription) connectServerStream(ctx context.Context,
 
 	// Read incoming messages and send them to the channel where the caller
 	// is listening to.
-	log.InfoS(ctx, "Successfully connected to mailbox server")
+	log.InfoS(ctx, "Successfully connected to mailbox server",
+		"server_addr", s.cfg.ServerAddress)
 	s.wg.Add(1)
 	go func() {
 		defer s.wg.Done()

rfq/manager.go

@@ -416,9 +416,6 @@ func (m *Manager) handleIncomingMessage(incomingMsg rfqmsg.IncomingMsg) error {
 		}
 
 	case *rfqmsg.BuyAccept:
-		// TODO(ffranr): The stream handler should ensure that the
-		//  accept message corresponds to a request.
-
 		finaliseCallback := func(msg rfqmsg.BuyAccept,
 			invalidQuoteEvent fn.Option[InvalidQuoteRespEvent]) {
 
@@ -472,9 +469,6 @@ func (m *Manager) handleIncomingMessage(incomingMsg rfqmsg.IncomingMsg) error {
 		}
 
 	case *rfqmsg.SellAccept:
-		// TODO(ffranr): The stream handler should ensure that the
-		//  accept message corresponds to a request.
-
 		finaliseCallback := func(msg rfqmsg.SellAccept,
 			invalidQuoteEvent fn.Option[InvalidQuoteRespEvent]) {
 

rpcserver.go

@@ -1626,6 +1626,8 @@ func (r *rpcServer) QueryAddrs(ctx context.Context,
 func (r *rpcServer) NewAddr(ctx context.Context,
 	req *taprpc.NewAddrRequest) (*taprpc.Addr, error) {
 
+	rpcsLog.TraceS(ctx, "[NewAddr]: Called", "req", spew.Sdump(req))
+
 	// Parse the proof courier address if one was provided, otherwise use
 	// the default specified in the config.
 	courierAddr := r.cfg.DefaultProofCourierAddr
@@ -1660,9 +1662,6 @@ func (r *rpcServer) NewAddr(ctx context.Context,
 			err)
 	}
 
-	rpcsLog.Infof("[NewAddr]: making new addr: specifier=%s, amt=%v",
-		&specifier, req.Amt)
-
 	err = r.checkBalanceOverflow(ctx, assetID, groupKey, req.Amt)
 	if err != nil {
 		return nil, err
@@ -1695,6 +1694,10 @@ func (r *rpcServer) NewAddr(ctx context.Context,
 		addrVersion = address.V2
 	}
 
+	rpcsLog.Infof("[NewAddr]: Making new addr: specifier=%s, amt=%v, "+
+		"courier=%v, addr_version=%v, asset_version=%v", &specifier,
+		req.Amt, courierAddr, addrVersion, assetVersion)
+
 	// Addresses with version 2 must use the new authmailbox proof courier
 	// type.
 	protocol := courierAddr.Scheme
@@ -1790,8 +1793,8 @@ func (r *rpcServer) NewAddr(ctx context.Context,
 			address.WithAssetVersion(assetVersion),
 		)
 		if err != nil {
-			return nil, fmt.Errorf("unable to make new addr: %w",
-				err)
+			return nil, fmt.Errorf("unable to make new addr with "+
+				"keys: %w", err)
 		}
 	}
 

tapgarden/planter_test.go

@@ -331,11 +331,15 @@ func (t *mintingTestHarness) queueSeedlingsInBatch(isFunded bool,
 
 // assertPendingBatchExists asserts that a pending batch is found and it has
 // numSeedlings assets registered.
-func (t *mintingTestHarness) assertPendingBatchExists(numSeedlings int) {
-	t.Helper()
+func (t *mintingTestHarness) assertPendingBatchExists(
+	expectedSeedlings []*tapgarden.Seedling) {
 
 	// The planter is a state machine, so we need to wait until it has
 	// reached the expected state.
+	var (
+		numExpectedSeedlings = len(expectedSeedlings)
+		lastActualSeedlings  map[string]*tapgarden.Seedling
+	)
 	err := wait.NoError(func() error {
 		batch, err := t.planter.PendingBatch()
 		if err != nil {
@@ -348,14 +352,43 @@ func (t *mintingTestHarness) assertPendingBatchExists(numSeedlings int) {
 				"non-nil")
 		}
 
-		if len(batch.Seedlings) < numSeedlings {
+		lastActualSeedlings = batch.Seedlings
+
+		if len(batch.Seedlings) < numExpectedSeedlings {
 			return fmt.Errorf("expected %d seedlings, got %d",
-				numSeedlings, len(batch.Seedlings))
+				numExpectedSeedlings, len(batch.Seedlings))
 		}
 
 		return nil
 	}, defaultTimeout)
-	require.NoError(t, err)
+	if err != nil {
+		// Report any missing seedlings.
+		spewCfg := spew.ConfigState{
+			// Disable .String() and other methods.
+			DisableMethods: true,
+			Indent:         "  ",
+		}
+
+		for idx := range expectedSeedlings {
+			expectedSeedling := expectedSeedlings[idx]
+			if lastActualSeedlings == nil {
+				t.Logf("Missing expected seedling: %s",
+					spewCfg.Sdump(expectedSeedling))
+				continue
+			}
+
+			_, ok := lastActualSeedlings[expectedSeedling.AssetName]
+			if !ok {
+				t.Logf("Missing expected seedling: %s",
+					spewCfg.Sdump(expectedSeedling))
+			}
+		}
+
+		t.Fatalf("Batch seedling mismatch: \nactual seedlings: %s\n"+
+			"expected seedlings: %s\nerror: %v",
+			spew.Sdump(lastActualSeedlings),
+			spew.Sdump(expectedSeedlings), err)
+	}
 }
 
 // assertNoActiveBatch asserts that no pending batch exists.
@@ -1089,7 +1122,7 @@ func (t *mintingTestHarness) queueInitialBatch(
 
 	// At this point, there should be a single pending batch with 5
 	// seedlings. The batch stored in the log should also match up exactly.
-	t.assertPendingBatchExists(numSeedlings)
+	t.assertPendingBatchExists(seedlings)
 
 	// Before we tick the batch, we record all existing batches, so we can
 	// make sure a new one was created.
@@ -1303,10 +1336,9 @@ func testMintingCancelFinalize(t *mintingTestHarness) {
 	// harness.
 	t.refreshChainPlanter()
 
-	// Create an initial batch of 5 seedlings.
-	const numSeedlings = 5
+	// Create an initial set of seedlings.
+	const numSeedlings = 4
 	seedlings := t.queueInitialBatch(numSeedlings)
-	firstSeedling := seedlings[0]
 
 	// If we cancel the current batch, the pending batch should be cleared,
 	// but the seedlings should still exist on disk.
@@ -1320,21 +1352,20 @@ func testMintingCancelFinalize(t *mintingTestHarness) {
 	t.finalizeBatchAssertFrozen(true)
 	t.cancelMintingBatch(true)
 
-	// Next, make another 5 random seedlings and continue with minting.
+	// Next, make another set of random seedlings and continue with minting.
 	seedlings = t.newRandSeedlings(numSeedlings)
-	seedlings[0] = firstSeedling
 	seedlings[0].ScriptKey = asset.ScriptKey{}
 	if seedlings[0].EnableEmission {
 		seedlings[0].GroupInternalKey = nil
 	}
 	t.queueSeedlingsInBatch(false, seedlings...)
 
-	t.assertPendingBatchExists(numSeedlings)
+	t.assertPendingBatchExists(seedlings)
 	t.assertSeedlingsExist(seedlings, nil)
 
 	// If we attempt to queue a seedling with the same name as a pending
 	// seedling, the planter should reject it.
-	updates, err := t.planter.QueueNewSeedling(firstSeedling)
+	updates, err := t.planter.QueueNewSeedling(seedlings[0])
 	require.NoError(t, err)
 	planterErr := <-updates
 	require.NotNil(t, planterErr.Error)
@@ -1781,7 +1812,7 @@ func testFundSealBeforeFinalize(t *mintingTestHarness) {
 	// Add the seedlings modified earlier to the batch, and check that they
 	// were added correctly.
 	t.queueSeedlingsInBatch(true, seedlings...)
-	t.assertPendingBatchExists(numSeedlings)
+	t.assertPendingBatchExists(seedlings)
 	t.assertSeedlingsExist(seedlings, nil)
 
 	verboseBatches, err := t.planter.ListBatches(