diff --git a/config.go b/config.go index 038f39ef..a8393d96 100644 --- a/config.go +++ b/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) diff --git a/db/migsets/programmatic_migrations.go b/db/migsets/programmatic_migrations.go index 585bf016..5af23df5 100644 --- a/db/migsets/programmatic_migrations.go +++ b/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 diff --git a/db/migsets/programmatic_migrations_test.go b/db/migsets/programmatic_migrations_test.go index 49d3b110..a48f2eb4 100644 --- a/db/migsets/programmatic_migrations_test.go +++ b/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 } diff --git a/db/migsets/sql_migrations.go b/db/migsets/sql_migrations.go index 6fde04ac..f3164be5 100644 --- a/db/migsets/sql_migrations.go +++ b/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 diff --git a/db/migsets/sql_migrations_dev.go b/db/migsets/sql_migrations_dev.go index 569eae33..8d703da8 100644 --- a/db/migsets/sql_migrations_dev.go +++ b/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