Error when restoring a wallet on a fresh LND install configured with postgresql db backend

[nzjess]

Background

Getting an RPC error when trying to restore a wallet (via a seed-phrase) on a fresh LND install configured with postgresql db backend.

Your environment

• lnd v0.14.1-beta
• Linux bitcoin-lnd 5.13.0-1006-gcp #7-Ubuntu SMP Wed Oct 27 07:10:25 UTC 2021 x86_64 x86_64 x86_64 GNU/Linux
• bitcoind 0.21.1
• docker compose v2

Steps to reproduce

I started up LND with postgres db backend configured. The db connects and initialises fine, and then it asks me to create a new wallet. I run lncli create and choose to restore from a seed phrase. It takes me through the whole process, which only takes a few seconds, but then it gives me an error. This is what my lncli create session looks like:

$> docker exec -it lnd lncli create

Input wallet password:
Confirm password:

Do you have an existing cipher seed mnemonic or extended master root key you want to use?
Enter 'y' to use an existing cipher seed mnemonic, 'x' to use an extended master root key
or 'n' to create a new seed (Enter y/x/n): y

Input your 24-word mnemonic separated by spaces: <DELETED>

Input your cipher seed passphrase (press enter if your seed doesn't have a passphrase):

Input an optional address look-ahead used to scan for used keys (default 2500):

!!!YOU MUST WRITE DOWN THIS SEED TO BE ABLE TO RESTORE THE WALLET!!!

---------------BEGIN LND CIPHER SEED---------------
  <DELETED>
---------------END LND CIPHER SEED-----------------

!!!YOU MUST WRITE DOWN THIS SEED TO BE ABLE TO RESTORE THE WALLET!!!
[lncli] rpc error: code = Unavailable desc = error reading from server: EOF

And this is what the LND logs look like at the same time:

2021-12-01 00:04:59.242 [INF] LTND: Version: 0.14.1-beta commit=v0.14.1-beta, build=production, logging=default, debuglevel=info
2021-12-01 00:04:59.242 [INF] LTND: Active chain: Bitcoin (network=mainnet)
2021-12-01 00:04:59.243 [INF] RPCS: RPC server listening on 192.168.100.4:20009
2021-12-01 00:04:59.250 [INF] RPCS: gRPC proxy started at 192.168.100.4:20008
2021-12-01 00:04:59.250 [INF] LTND: Opening the main database, this might take a few minutes...
2021-12-01 00:04:59.309 [INF] LTND: Using remote postgres database! Creating graph and channel state DB instances
2021-12-01 00:04:59.324 [INF] CHDB: Checking for schema update: latest_version=24, db_version=24
2021-12-01 00:04:59.333 [INF] LTND: Database(s) now open (time_to_open=82.397162ms)!
2021-12-01 00:04:59.339 [INF] LTND: We're not running within systemd
2021-12-01 00:04:59.339 [INF] LTND: Waiting for wallet encryption password. Use `lncli create` to create a wallet, `lncli unlock` to unlock an existing wallet, or `lncli changepassword` to change the password of an existing wallet and unlock it.

2021-12-01 00:05:52.278 [CRT] CHDB: Caught unhandled error: context canceled
2021-12-01 00:05:52.278 [INF] CHDB: Sending request for shutdown
2021-12-01 00:05:52.279 [INF] LTND: Received shutdown request.
2021-12-01 00:05:52.279 [INF] LTND: Shutting down...
2021-12-01 00:05:52.279 [INF] LTND: Gracefully shutting down.
2021-12-01 00:05:52.279 [ERR] LTND: Could not unload new wallet: wallet is not loaded
2021-12-01 00:05:52.280 [ERR] LTND: unable to set up wallet password listeners: context canceled
2021-12-01 00:05:52.280 [ERR] LTND: Shutting down because error in main method: error creating wallet config: unable to set up wallet password listeners: context canceled
2021-12-01 00:05:52.285 [INF] LTND: Shutdown complete
error creating wallet config: unable to set up wallet password listeners: context canceled

Expected behaviour

The wallet should be restored and LND should then be able to start up and operate normally from that point.

Actual behaviour

LND just crashes with the error described above, the wallet is not restored. If I try again the same sequence repeats.

[dongcarl]

I've experienced the same thing even when creating a new seed.

The error messages on the lncli side (matches OP):

rpc error: code = Unavailable desc = error reading from server: EOF

The error message on the lnd side (matches OP):

[ERR] LTND: Shutting down because error in main method: error creating wallet config: unable to set up wallet password listeners: context canceled

Environment:

• lnd v0.14.1-beta
• lnd configured to use postgres backend on localhost + neutrino from Bitcoin Core

[Roasbeef]

If y'all crank up logging to trace --debuglevel=trace is anything relevant printed out?

Also does postgres emit any relevant logs?

[guggero]

Just trying to narrow this down: Does the problem also happen if you set db.postgres.timeout=0 in the config?

[dongcarl]

Here's the log with debuglevel=trace and me going through the create flow:

2021-12-10 18:44:44.646 [DBG] BTCN: Attempting to connect to 127.0.0.1:8333 (reqid 1)
2021-12-10 18:44:44.647 [DBG] BTCN: Failed to connect to 127.0.0.1:8333 (reqid 1): dial tcp 127.0.0.1:8333: connect: connection refused
2021-12-10 18:44:44.647 [DBG] BTCN: Retrying connection to 127.0.0.1:8333 (reqid 1) in 10s
2021-12-10 18:44:54.647 [DBG] BTCN: Attempting to connect to 127.0.0.1:8333 (reqid 1)
2021-12-10 18:44:54.648 [DBG] BTCN: Failed to connect to 127.0.0.1:8333 (reqid 1): dial tcp 127.0.0.1:8333: connect: connection refused
2021-12-10 18:44:54.649 [DBG] BTCN: Retrying connection to 127.0.0.1:8333 (reqid 1) in 15s
2021-12-10 18:44:56.960 [ERR] LTND: Could not unload new wallet: wallet is not loaded
2021-12-10 18:44:56.960 [ERR] LTND: unable to set up wallet password listeners: failed to create address bucket: context canceled
2021-12-10 18:44:56.960 [TRC] BTCN: Connection manager stopped
2021-12-10 18:44:56.960 [TRC] BTCN: Connection handler done
2021-12-10 18:44:56.960 [INF] BTCN: Canceling block subscription: id=1
2021-12-10 18:44:57.010 [DBG] BTCN: Stopping block notifications subscription manager
2021-12-10 18:44:57.011 [INF] BTCN: Block manager shutting down
2021-12-10 18:44:57.011 [TRC] BTCN: Block handler done
2021-12-10 18:44:57.011 [INF] BTCN: Address manager shutting down
2021-12-10 18:44:57.013 [TRC] BTCN: Address handler done
2021-12-10 18:44:57.013 [TRC] BTCN: Peer handler done
2021-12-10 18:44:57.013 [ERR] LTND: Shutting down because error in main method: error creating wallet config: unable to set up wallet password listeners: failed to create address bucket: context canceled
2021-12-10 18:44:57.017 [INF] LTND: Shutdown complete

Then, I restarted LND, and got logs:

2021-12-10 18:45:57.206 [INF] LTND: Version: 0.14.1-beta commit=v0.14.1-beta, build=production, logging=default, debuglevel=trace
2021-12-10 18:45:57.206 [INF] LTND: Active chain: Bitcoin (network=mainnet)
2021-12-10 18:45:57.208 [DBG] NTFR: ChainNotifier RPC server successfully register with root gRPC server
2021-12-10 18:45:57.208 [DBG] WLKT: WalletKit RPC server successfully registered with root gRPC server
2021-12-10 18:45:57.208 [DBG] RRPC: Router RPC server successfully register with root gRPC server
2021-12-10 18:45:57.208 [DBG] ARPC: Autopilot RPC server successfully register with root gRPC server
2021-12-10 18:45:57.208 [DBG] IRPC: Invoices RPC server successfully registered with root gRPC server
2021-12-10 18:45:57.208 [DBG] VRPC: Versioner RPC server successfully registered with root gRPC server
2021-12-10 18:45:57.208 [DBG] SGNR: Signer RPC server successfully register with root gRPC server
2021-12-10 18:45:57.208 [INF] RPCS: RPC server listening on 127.0.0.1:10009
2021-12-10 18:45:57.209 [DBG] NTFR: ChainNotifier REST server successfully registered with root REST server
2021-12-10 18:45:57.209 [DBG] WLKT: WalletKit REST server successfully registered with root REST server
2021-12-10 18:45:57.209 [DBG] RRPC: Router REST server successfully registered with root REST server
2021-12-10 18:45:57.209 [DBG] ARPC: Autopilot REST server successfully registered with root REST server
2021-12-10 18:45:57.209 [DBG] IRPC: Invoices REST server successfully registered with root REST server
2021-12-10 18:45:57.210 [DBG] VRPC: Versioner REST server successfully registered with root REST server
2021-12-10 18:45:57.210 [DBG] SGNR: Signer REST server successfully registered with root REST server
2021-12-10 18:45:57.210 [INF] RPCS: gRPC proxy started at 127.0.0.1:8080
2021-12-10 18:45:57.210 [INF] LTND: Opening the main database, this might take a few minutes...
2021-12-10 18:45:57.243 [INF] LTND: Using remote postgres database! Creating graph and channel state DB instances
2021-12-10 18:45:57.249 [ERR] LTND: unable to open graph DB: unable to create new channel graph: context canceled
2021-12-10 18:45:57.249 [ERR] LTND: Shutting down because error in main method: unable to open databases: unable to open graph DB: unable to create new channel graph: context canceled
2021-12-10 18:45:57.250 [INF] LTND: Shutdown complete

---

After I use db.postgres.timeout=0, I was able to successfully go through the create flow, ending in:

lnd successfully initialized!

However, it seems like lnd still encountered an error and quit after it was initialized:

2021-12-10 18:47:44.168 [INF] LNWL: Opened wallet
2021-12-10 18:47:44.274 [INF] CHRE: Primary chain is set to: bitcoin
2021-12-10 18:47:44.279 [ERR] LTND: unable to create partial chain control: --feeurl parameter required when running neutrino on mainnet
2021-12-10 18:47:44.279 [TRC] BTCN: Connection manager stopped
2021-12-10 18:47:44.279 [TRC] BTCN: Connection handler done
2021-12-10 18:47:44.280 [INF] BTCN: Canceling block subscription: id=1
2021-12-10 18:47:44.330 [DBG] BTCN: Stopping block notifications subscription manager
2021-12-10 18:47:44.330 [INF] BTCN: Block manager shutting down
2021-12-10 18:47:44.330 [TRC] BTCN: Block handler done
2021-12-10 18:47:44.331 [INF] BTCN: Address manager shutting down
2021-12-10 18:47:44.333 [TRC] BTCN: Address handler done
2021-12-10 18:47:44.333 [TRC] BTCN: Peer handler done
2021-12-10 18:47:44.334 [ERR] LTND: Shutting down because error in main method: error creating wallet config: unable to create partial chain control: --feeurl parameter required when running neutrino on mainnet
2021-12-10 18:47:44.337 [INF] LTND: Shutdown complete

[guggero]

Okay, so this definitely has something to do with the timeout.

Were you running with Neutrino? The error you got seems to be unrelated to postgres: unable to create partial chain control: --feeurl parameter required when running neutrino on mainnet

[miketwenty1]

similar to @dongcarl - starting from scratch is failing for me #6103 my logs differed a bit.

[dongcarl]

So setting the timeout to 0 and supplying a feeurl works, however, I think there still might be a problem since I was accessing postgres on localhost and 10s should be plenty for a timeout...

[joostjager]

How long does it take now to open the database? (log: Database(s) now open (time_to_open=xxx ms)!)

Also in the works is #6111 which speeds up db opens on postgres a lot.

[dongcarl]

Ah, it takes 2m47s... I assumed the db.postgres.timeout to just be for the TCP connection, and not for opening the database itself (which I assume takes some extra processing on the lnd side?)