Merge pull request #1359 from ellemouton/kvdb-sql-mig-lnd-ready-timeout

multi: wait for lnd with a configurable timeout during the SQL migration

config.go

@@ -115,6 +115,18 @@ const (
 
 	defaultFirstLNCConnTimeout = 10 * time.Minute
 
+	// defaultLndReadyTimeout is the default maximum time that litd
+	// waits for lnd's RPC server to become ready. It currently applies
+	// to the one-time kvdb-to-SQL data migration, which must call into
+	// lnd's main RPC server (ListMacaroonIDs); that only becomes
+	// available once lnd reaches its "RPC active" state. On nodes with a
+	// large channel/graph state this can take well over a minute after
+	// the wallet is unlocked, and timing out aborts litd startup
+	// entirely (requiring a manual restart), so we default to a
+	// deliberately generous value that comfortably covers even large
+	// nodes.
+	defaultLndReadyTimeout = 10 * time.Minute
+
 	// DatabaseBackendSqlite is the name of the SQLite database backend.
 	DatabaseBackendSqlite = "sqlite"
 
@@ -246,6 +258,11 @@ type Config struct {
 	// resolved.
 	autoMigrateKVDBApproved bool
 
+	// LndReadyTimeout is the maximum time that litd will wait for lnd's RPC
+	// server to become ready. This currently applies to the one-time
+	// kvdb-to-SQL data migration, which must call into lnd's RPC.
+	LndReadyTimeout time.Duration `long:"lndreadytimeout" description:"The maximum time that litd will wait for lnd's RPC server to become ready. This currently applies to the one-time migration of litd's legacy kvdb data to the configured SQL backend, which must call into lnd's RPC. On nodes with a large channel and graph state, lnd can take a while to start serving RPC calls after the wallet is unlocked; increase this value if startup fails with an error mentioning that lnd's 'RPC server is in the process of starting up'."`
+
 	// Sqlite holds the configuration options for a SQLite database
 	// backend.
 	Sqlite *db.SqliteConfig `group:"sqlite" namespace:"sqlite"`
@@ -367,6 +384,7 @@ func (c *Config) NewStores(ctx context.Context,
 				migsets.MakeMigrationSets(
 					ctx, basicClient, c.MacaroonPath,
 					c.LitDir, c.Network, clock,
+					c.LndReadyTimeout,
 				),
 			)
 			if err != nil {
@@ -419,6 +437,7 @@ func (c *Config) NewStores(ctx context.Context,
 				migsets.MakeMigrationSets(
 					ctx, basicClient, c.MacaroonPath,
 					c.LitDir, c.Network, clock,
+					c.LndReadyTimeout,
 				),
 			)
 			if err != nil {
@@ -565,6 +584,7 @@ func defaultConfig() *Config {
 		Lnd:                &lndDefaultConfig,
 		LndRPCTimeout:      defaultRPCTimeout,
 		LndConnectInterval: defaultStartupTimeout,
+		LndReadyTimeout:    defaultLndReadyTimeout,
 		LitDir:             DefaultLitDir,
 		LetsEncryptListen:  defaultLetsEncryptListen,
 		LetsEncryptDir:     defaultLetsEncryptDir,
@@ -701,6 +721,15 @@ func loadAndValidateConfig(ctx context.Context,
 			"to avoid problems", minimumRPCTimeout)
 	}
 
+	// The work that waits on lnd's readiness (currently the kvdb-to-SQL
+	// migration) cannot proceed without lnd, so a non-positive timeout
+	// would make it fail immediately on any node where lnd isn't
+	// instantly ready. Require a positive value.
+	if cfg.LndReadyTimeout <= 0 {
+		return nil, fmt.Errorf("lndreadytimeout must be positive, got "+
+			"%v", cfg.LndReadyTimeout)
+	}
+
 	// Validate the lightning-terminal config options.
 	litDir := lnd.CleanAndExpandPath(preCfg.LitDir)
 	cfg.LetsEncryptDir = lncfg.CleanAndExpandPath(cfg.LetsEncryptDir)

db/migsets/programmatic_migrations.go

@@ -21,12 +21,19 @@ import (
 	"github.com/lightningnetwork/lnd/sqldb/v2"
 )
 
+// listMacaroonIDRetryDelay is the delay between successive attempts to reach
+// lnd's ListMacaroonIDs RPC while waiting for lnd to become ready. 500ms keeps
+// the poll responsive (lnd is typically ready within a minute or two) without
+// busy-looping against a not-yet-ready RPC server.
+const listMacaroonIDRetryDelay = 500 * time.Millisecond
+
 // Mig6ProgrammaticMigration generates and returns the programmatic migration
 // entry containing the kvdb to SQL migration for all of litd's database stores.
 func Mig6ProgrammaticMigration(ctx context.Context,
 	basicClient lnrpc.LightningClient, db *sqldb.BaseDB,
 	accountsDir, networkDir string, clock clock.Clock,
-	migVersion uint) migrate.ProgrammaticMigrEntry {
+	migVersion uint,
+	lndReadyTimeout time.Duration) migrate.ProgrammaticMigrEntry {
 
 	mig6queries := sqlcmig6.NewForType(db, db.BackendType)
 	mig6executor := sqldb.NewTransactionExecutor(
@@ -49,6 +56,7 @@ func Mig6ProgrammaticMigration(ctx context.Context,
 				return kvdbToSqlProgrammaticMigration(
 					ctx, basicClient, accountsDir,
 					networkDir, db, clock, q6,
+					lndReadyTimeout,
 				)
 			}, sqldb.NoOpReset,
 		)
@@ -87,7 +95,8 @@ func Mig6ProgrammaticMigration(ctx context.Context,
 
 func kvdbToSqlProgrammaticMigration(ctx context.Context,
 	basicClient lnrpc.LightningClient, accountsDir, networkDir string,
-	_ *sqldb.BaseDB, clock clock.Clock, q *sqlcmig6.Queries) error {
+	_ *sqldb.BaseDB, clock clock.Clock, q *sqlcmig6.Queries,
+	lndReadyTimeout time.Duration) error {
 
 	start := time.Now()
 
@@ -185,43 +194,18 @@ func kvdbToSqlProgrammaticMigration(ctx context.Context,
 		}
 	}()
 
-	// We'll fetch the macaroonIDList from `lnd` next. Note that since lnd's
-	// RPC servers may not have been fully started yet if the execution of
-	// accounts and session migration were really quick, we poll the request
-	// up to 120 times with a 0.5 second delay between the attempts. This
-	// should be a sufficient amount of time for the wallet to have been
-	// loaded and for the RPC servers to started.
-	const (
-		maxListMacaroonIDAttempts = 120
-		listMacaroonIDRetryDelay  = 500 * time.Millisecond
+	// The firewalldb migration below needs lnd's macaroon root key IDs, but
+	// lnd only starts serving that RPC once it has reached its "RPC active"
+	// state, which can take well over a minute on nodes with a large
+	// channel and graph state. So we cannot assume lnd is ready by the time
+	// the (fast) accounts and session migrations above have completed, and
+	// instead poll until it is.
+	macaroonIDList, err := listMacaroonIDsWhenLndReady(
+		ctx, basicClient, lndReadyTimeout,
 	)
-
-	var macaroonIDList *lnrpc.ListMacaroonIDsResponse
-	for i := 1; i <= maxListMacaroonIDAttempts; i++ {
-		macaroonIDList, err = basicClient.ListMacaroonIDs(
-			ctx, &lnrpc.ListMacaroonIDsRequest{},
-		)
-		if err == nil {
-			break
-		}
-
-		if i == maxListMacaroonIDAttempts {
-			return fmt.Errorf("error listing macaroon IDs when "+
-				"migrating stores to SQL after %d attempts: %w",
-				maxListMacaroonIDAttempts, err)
-		}
-
-		log.Warnf("Failed to list macaroon IDs when migrating "+
-			"stores to SQL (attempt %d/%d), retrying in %v: %v",
-			i, maxListMacaroonIDAttempts, listMacaroonIDRetryDelay,
-			err)
-
-		select {
-		case <-ctx.Done():
-			return fmt.Errorf("context canceled while retrying "+
-				"to list macaroon IDs: %w", ctx.Err())
-		case <-time.After(listMacaroonIDRetryDelay):
-		}
+	if err != nil {
+		return fmt.Errorf("error listing macaroon IDs when migrating "+
+			"stores to SQL: %w", err)
 	}
 
 	log.Infof("Successfully listed macaroon IDs during store migration.")
@@ -250,6 +234,64 @@ func kvdbToSqlProgrammaticMigration(ctx context.Context,
 	return nil
 }
 
+// listMacaroonIDsWhenLndReady calls lnd's ListMacaroonIDs RPC, retrying every
+// listMacaroonIDRetryDelay until it succeeds, until the lndReadyTimeout budget
+// is exhausted, or until the passed context is canceled (litd shutting down).
+//
+// NOTE: lndReadyTimeout is meant to be a generous backstop rather than a tight
+// bound (see its default in the main config). litd cannot complete the kvdb to
+// SQL migration without lnd, so timing out here aborts litd startup entirely
+// and forces a manual restart; waiting longer for a slow-but-healthy lnd is
+// strictly preferable to that.
+func listMacaroonIDsWhenLndReady(ctx context.Context,
+	basicClient lnrpc.LightningClient,
+	lndReadyTimeout time.Duration) (*lnrpc.ListMacaroonIDsResponse, error) {
+
+	start := time.Now()
+
+	waitCtx, cancel := context.WithTimeout(ctx, lndReadyTimeout)
+	defer cancel()
+
+	for attempt := 1; ; attempt++ {
+		// We pass waitCtx rather than ctx so that a single hanging call
+		// cannot outlive the lnd-ready budget.
+		macaroonIDList, err := basicClient.ListMacaroonIDs(
+			waitCtx, &lnrpc.ListMacaroonIDsRequest{},
+		)
+		if err == nil {
+			return macaroonIDList, nil
+		}
+
+		log.Warnf("Failed to list macaroon IDs when migrating stores "+
+			"to SQL (attempt %d after %v): %v", attempt,
+			time.Since(start), err)
+
+		select {
+		case <-waitCtx.Done():
+			// waitCtx is derived from ctx, so it also fires when
+			// the daemon shuts down. Check the parent explicitly
+			// first so that a shutdown mid-retry is reported as
+			// such instead of as a readiness timeout.
+			if ctx.Err() != nil {
+				return nil, fmt.Errorf("aborted after %d "+
+					"attempts over %v while waiting for "+
+					"lnd's RPC server to become ready: "+
+					"%w", attempt, time.Since(start),
+					ctx.Err())
+			}
+
+			return nil, fmt.Errorf("lnd's RPC server did not "+
+				"become ready within %v (%d attempts over "+
+				"%v); increase --lndreadytimeout if lnd "+
+				"legitimately needs longer to start up: %w",
+				lndReadyTimeout, attempt, time.Since(start),
+				err)
+
+		case <-time.After(listMacaroonIDRetryDelay):
+		}
+	}
+}
+
 // deprecateKVDBStores marks the old kvdb stores as deprecated after the SQL
 // migration committed successfully. We do this after the SQL transaction is
 // committed so a failed SQL migration cannot strand the user with an unusable

db/migsets/programmatic_migrations_test.go

@@ -2,6 +2,7 @@ package migsets
 
 import (
 	"context"
+	"errors"
 	"net"
 	"os"
 	"path/filepath"
@@ -22,6 +23,12 @@ import (
 	"google.golang.org/grpc/test/bufconn"
 )
 
+// testLndReadyTimeout is the lnd RPC-ready timeout used for the migration in
+// these tests. The test lnd server is ready immediately, so any positive value
+// works; we use a short one so a broken poll loop fails fast rather than
+// hanging the test.
+const testLndReadyTimeout = 5 * time.Second
+
 // TestKVDBToSQLProgrammaticMigrationSkipsMissingStores verifies that the kvdb
 // to SQL migration does not create missing legacy kvdb files while scanning for
 // stores to migrate.
@@ -39,6 +46,7 @@ func TestKVDBToSQLProgrammaticMigrationSkipsMissingStores(t *testing.T) {
 	err := kvdbToSqlProgrammaticMigration(
 		context.Background(), nil, accountsDir, networkDir,
 		sqlStore.BaseDB, clock.NewDefaultClock(), queries,
+		testLndReadyTimeout,
 	)
 	require.NoError(t, err)
 
@@ -72,11 +80,12 @@ func TestKVDBToSQLProgrammaticMigrationRunsWithOneBBoltDBFiles(t *testing.T) {
 		sqlStore.BaseDB, sqlStore.BackendType,
 	)
 
-	lndClient := newTestLightningClient(t)
+	lndClient := newTestLightningClient(t, nil)
 
 	err = kvdbToSqlProgrammaticMigration(
 		ctx, lndClient, accountsDir, networkDir,
 		sqlStore.BaseDB, testClock, queries,
+		testLndReadyTimeout,
 	)
 	require.NoError(t, err)
 
@@ -93,6 +102,43 @@ func TestKVDBToSQLProgrammaticMigrationRunsWithOneBBoltDBFiles(t *testing.T) {
 	require.Empty(t, dbSessions)
 }
 
+// TestListMacaroonIDsWhenLndReadyTimeout asserts that we give up with a helpful
+// error, pointing at the lndreadytimeout option, once the lnd-ready budget is
+// exhausted without lnd ever becoming ready.
+func TestListMacaroonIDsWhenLndReadyTimeout(t *testing.T) {
+	t.Parallel()
+
+	// The server never becomes ready, so the only way out is the timeout.
+	// We use a timeout well below listMacaroonIDRetryDelay so that the
+	// budget is exhausted during the first retry wait.
+	lndClient := newTestLightningClient(t, errNotReady)
+
+	_, err := listMacaroonIDsWhenLndReady(
+		context.Background(), lndClient, 50*time.Millisecond,
+	)
+	require.ErrorContains(t, err, "did not become ready")
+	require.ErrorContains(t, err, "--lndreadytimeout")
+	require.ErrorContains(t, err, errNotReady.Error())
+}
+
+// TestListMacaroonIDsWhenLndReadyCancel asserts that a canceled parent context
+// (litd shutting down) is surfaced as a cancellation rather than as a readiness
+// timeout.
+func TestListMacaroonIDsWhenLndReadyCancel(t *testing.T) {
+	t.Parallel()
+
+	lndClient := newTestLightningClient(t, errNotReady)
+
+	// Cancel the parent context up front, so that the generous timeout
+	// below is never the reason we stop retrying.
+	ctx, cancel := context.WithCancel(context.Background())
+	cancel()
+
+	_, err := listMacaroonIDsWhenLndReady(ctx, lndClient, time.Hour)
+	require.ErrorIs(t, err, context.Canceled)
+	require.NotContains(t, err.Error(), "did not become ready")
+}
+
 func requireNoFile(t *testing.T, path string) {
 	t.Helper()
 
@@ -107,12 +153,23 @@ func requireFileExists(t *testing.T, path string) {
 	require.NoError(t, err)
 }
 
-func newTestLightningClient(t *testing.T) lnrpc.LightningClient {
+// errNotReady mimics the error lnd's RPC server returns before it has reached
+// its "RPC active" state.
+var errNotReady = errors.New("the RPC server is in the process of starting up")
+
+// newTestLightningClient returns a client backed by an in-memory lnd stub. If
+// listMacaroonIDsErr is non-nil, all ListMacaroonIDs calls fail with it,
+// simulating an lnd that never becomes ready.
+func newTestLightningClient(t *testing.T,
+	listMacaroonIDsErr error) lnrpc.LightningClient {
+
 	t.Helper()
 
 	lis := bufconn.Listen(1024 * 1024)
 	server := grpc.NewServer()
-	lnrpc.RegisterLightningServer(server, &testLightningServer{})
+	lnrpc.RegisterLightningServer(server, &testLightningServer{
+		listMacaroonIDsErr: listMacaroonIDsErr,
+	})
 
 	go func() {
 		_ = server.Serve(lis)
@@ -143,10 +200,16 @@ func newTestLightningClient(t *testing.T) lnrpc.LightningClient {
 
 type testLightningServer struct {
 	lnrpc.UnimplementedLightningServer
+
+	listMacaroonIDsErr error
 }
 
 func (t *testLightningServer) ListMacaroonIDs(context.Context,
 	*lnrpc.ListMacaroonIDsRequest) (*lnrpc.ListMacaroonIDsResponse, error) {
 
+	if t.listMacaroonIDsErr != nil {
+		return nil, t.listMacaroonIDsErr
+	}
+
 	return &lnrpc.ListMacaroonIDsResponse{}, nil
 }

db/migsets/sql_migrations.go

@@ -5,6 +5,7 @@ package migsets
 import (
 	"context"
 	"path/filepath"
+	"time"
 
 	"github.com/golang-migrate/migrate/v4"
 	"github.com/golang-migrate/migrate/v4/database/pgx/v5"
@@ -16,8 +17,8 @@ import (
 
 // MakeMigrationSets creates the migration sets for production environments.
 func MakeMigrationSets(ctx context.Context, basicClient lnrpc.LightningClient,
-	macPath, litDir, network string,
-	clock clock.Clock) []sqldb.MigrationSet {
+	macPath, litDir, network string, clock clock.Clock,
+	lndReadyTimeout time.Duration) []sqldb.MigrationSet {
 
 	accountsDir := filepath.Dir(macPath)
 	networkDir := filepath.Join(litDir, network)
@@ -50,6 +51,7 @@ func MakeMigrationSets(ctx context.Context, basicClient lnrpc.LightningClient,
 			res[db.KVDBtoSQLMigVersion] = Mig6ProgrammaticMigration(
 				ctx, basicClient, baseDB, accountsDir,
 				networkDir, clock, db.KVDBtoSQLMigVersion,
+				lndReadyTimeout,
 			)
 
 			return res, nil

db/migsets/sql_migrations_dev.go

@@ -5,6 +5,7 @@ package migsets
 import (
 	"context"
 	"path/filepath"
+	"time"
 
 	"github.com/golang-migrate/migrate/v4"
 	"github.com/golang-migrate/migrate/v4/database/pgx/v5"
@@ -17,7 +18,8 @@ import (
 // MakeMigrationSets creates the migration sets for the dev environments.
 func MakeMigrationSets(ctx context.Context,
 	basicClient lnrpc.LightningClient, macPath, litDir, network string,
-	clock clock.Clock) []sqldb.MigrationSet {
+	clock clock.Clock,
+	lndReadyTimeout time.Duration) []sqldb.MigrationSet {
 
 	accountsDir := filepath.Dir(macPath)
 	networkDir := filepath.Join(litDir, network)
@@ -49,6 +51,7 @@ func MakeMigrationSets(ctx context.Context,
 			res[db.KVDBtoSQLMigVersion] = Mig6ProgrammaticMigration(
 				ctx, basicClient, baseDB, accountsDir,
 				networkDir, clock, db.KVDBtoSQLMigVersion,
+				lndReadyTimeout,
 			)
 
 			return res, nil

docs/release-notes/release-notes-0.17.1.md

@@ -31,6 +31,17 @@
   of being masked by a confusing `no request values found for request: <id>`
   error.
 
+* [Wait longer for lnd during the kvdb-to-SQL
+  migration](https://github.com/lightninglabs/lightning-terminal/pull/1359):
+  The kvdb-to-SQL data migration polls lnd's `ListMacaroonIDs` RPC, which only
+  becomes available once lnd reaches its "RPC active" state. On nodes with a
+  large channel/graph state, lnd can take well over a minute to get there after
+  the wallet is unlocked, which exceeded the previous fixed 60-second poll
+  budget and caused the migration (and therefore litd startup) to fail
+  permanently, requiring a manual restart. The wait is now bounded by a
+  configurable, generous timeout (`--lndreadytimeout`, defaulting to 10
+  minutes) instead of a fixed attempt count.
+
 ### Functional Changes/Additions
 
 * [Add accounts payments history subcommand](https://github.com/lightninglabs/lightning-terminal/pull/1316):