Lnd: newaddress hangs if not caught up

[devrandom]

During initial catchup, the following command hangs with no feedback:

lncli newaddress np2wkh

[sangaman]

I could not reproduce this behavior. I'm running the latest lnd code. If I wipe the .lnd directory and then start lnd and run lncli newaddress np2wkh while lnd is still catching up, I get a normal response with an address.

[devrandom]

Did you have wallet password on or off?

[sangaman]

No wallet password, I was running with --noencryptwallet.

[devrandom]

I believe I saw the issue with encrypted wallet. Alternatively, maybe this has been fixed since.

[sangaman]

I just started over from scratch with an encrypted wallet, it looked like I may have recreated it as it hung for ~15 seconds or so before finally spitting out an address. It didn't take long when I tried with an unencrypted wallet, maybe a second or two. So it's different behavior from what I observed before, but I'm using pretty modest resources on this machine so it could just be a performance issue if anything.

[halseth]

Should not have anything to do with encrypted wallet or not, since running with --noencryptwallet is still actually encrypting the wallet, just with a standard passphrase 😛

[sansari]

I'm hitting this issue right now. Using a wallet password I provided, it unlocks the wallet, but then running lncli newaddress np2wkh or lncli newaddress p2wkh hangs indefinitely (I've left it for more than 10 mins to see, but still hung).

In my case, I'm running lnd against bitcoind (a recently added capability), and all is caught up when I run the newaddress command. It's fully reproducible for me right now, so if you guys have any suggested steps to debug or provide more info, happy to do so.

EDIT: I suppose I should clarify in that I'm not hitting the issue "while catching up", but rather just hitting it in general now.

EDIT2: one thing I'm seeing that may be relevant, "2018-01-18 17:39:30.444 [INF] LTND: Waiting for chain backend to finish sync, start_height=1259560" ... its showing this output from LND even though my bitcoind testnet is sync'd already. Almost as if LND thinks bitcoind is not sync'd, even though it is?

[halseth]

Yeah, sounds like lnd believes the backend is not caught up. Any ideas @aakselrod?

[LordStapy]

I've had the same issue using bitcoind as chain backend, for me the problem seems fixed putting bitcoind.zmqpath=tcp://127.0.0.1:29000 in lnd.conf under the bitcoind section. Now i can get lnd synced and can generate a new address.
REF: https://github.com/lightningnetwork/lnd/issues/621#issuecomment-358652636

[aakselrod]

@sansari, could you please post your lnd.conf, bitcoin.conf, and the log from lnd initial startup and sync? Alternatively, can you make sure your bitcoind binary is built with ZMQ support if you built it yourself?

[sansari]

After a lot of further investigation, I eventually did confirm that my lnd process was simply unable to connect with bitcoind, rather than lnd thinking bitcoind was not sync'd. There were a number of issues:

• At first, I would see a panic: runtime error: index out of range as noted above, and indeed adding that option @LordStapy noted fixed that issue (perhaps this should show a different error message, noting it was looking to connect via ZMQ but couldn't?)
• Then, I noticed it was getting a lot of 'connection refused' errors in the lnd output, indicating it simply couldn't talk to the bitcoind process. Occasionally, that error would not show up and instead I'd see a [ERR] LNWL: read tcp 127.0.0.1:55509->127.0.0.1:18332: i/o timeout error
• Eventually @Roasbeef noted that my bitcoind process needed to be compiled with ZMQ (it was not, I had installed via homebrew)... so basically lnd was saying it waiting for bitcoind to sync, but actually just never connecting.

So, I put up a PR to update the docs a bit for usage with bitcoind: https://github.com/lightningnetwork/lnd/pull/639. That said, I think the way it handles this case is problematic for two reasons:

1. Is the message "waiting for chain backend to sync" referring to lnd's catchup or to bitcoind sync? I had assumed it was the latter, but once I got it working lnd then finally indicated it was syncing and did a catchup against bitcoind. So, perhaps the wording could clarify that it's trying to sync 'lnd', not that it's waiting for 'bitcoind' to sync?
2. That message is the last output of lnd, and it is still "responsive" during that time, i.e. you can run other commands like walletbalance etc. and it will respond. So it appears as though all is well, even though we have a critical failure of connecting to the bitcoind backend. (Of course, the exception to this is the newaddress command hangs)

Perhaps, beyond the documentation to ensure ZMQ is working between the two, there could be some more error output and/or even a process exit to ensure the user really knows the link is not there (forgive me, I'm still learning about lnd so am not sure if a process exit is far too extreme for that case).

[sangaman]

I've been seeing this issue again running in neutrino mode when starting up a new instance and trying to make an address after initial sync completes. newaddress hangs, and the workaround is for me to restart lnd at which point calling newaddress a second time works.

[Roasbeef]

With the way initial sync is done atm, lnd may be under high load for a minute or so while it process all the data. We know how to optimize this, but there're higher priority items that we're working on. During this point, if you switch to trace logging, you'll likely see a lot of activity.

[Kixunil]

I thought I have this exact problem, but looking at output of lnd, it isn't caught up yet, so I'll wait. It'd be nice if lncli provided feedback.

What bothers me is lnd syncing from height 0, even though it doesn't make sense, since SegWit was activated in August and LN didn't exist before. Am I missing something?

[Kixunil]

I've noticed the address in logs, so I tried again and it worked immediately.

[Roasbeef]

lnd syncs from height zero as it needs to verify the header chain.

[Kixunil]

I'm curious why. If it's getting a chain from trusted node, it should be already verified.

[jherven]

I'm having the same problem, "lncli newaddress np2wkh" hangs for kind of forever (It actually created a adress once but took 10+ hours) and at lnd startup it also waits for "chain backend to finish sync" for a really long time.

Comments above made me also suspect a ZMQ problem, ended up writing a small program that also subscribes and I can see both rawtx and rawblock output so I guess that my bitcoind is running as expected with ZMQ.

[medisoft]

Same problem

2018-04-05 13:36:16.963 [INF] HSWC: Restoring in-memory circuit state from disk
2018-04-05 13:36:16.963 [INF] HSWC: Payment circuits loaded: num_pending=0, num_open=0
2018-04-05 13:36:17.055 [INF] RPCS: gRPC proxy started at 127.0.0.1:8080
2018-04-05 13:36:17.055 [INF] RPCS: RPC server listening on 127.0.0.1:10009
2018-04-05 13:36:17.059 [INF] LTND: Waiting for chain backend to finish sync, start_height=1291539
2018-04-05 13:36:31.113 [INF] LNWL: Catching up block hashes to height 220000, this might take a while

[Roasbeef]

In your log, lnd is still catching up the chain backend, only a limited set
of rpcs are allotted before the chain backend is fully synced.

On Thu, Apr 5, 2018, 11:37 AM Mario Medina [e-mail] wrote:

Same problem

2018-04-05 13:36:16.963 [INF] HSWC: Restoring in-memory circuit state from
disk
2018-04-05 13:36:16.963 [INF] HSWC: Payment circuits loaded:
num_pending=0, num_open=0
2018-04-05 13:36:17.055 [INF] RPCS: gRPC proxy started at 127.0.0.1:8080
2018-04-05 13:36:17.055 [INF] RPCS: RPC server listening on
127.0.0.1:10009
2018-04-05 13:36:17.059 [INF] LTND: Waiting for chain backend to finish
sync, start_height=1291539
2018-04-05 13:36:31.113 [INF] LNWL: Catching up block hashes to height
220000, this might take a while

—
You are receiving this because you were mentioned.
Reply to this email directly, view it on GitHub
https://github.com/lightningnetwork/lnd/issues/444#issuecomment-379035721,
or mute the thread
https://github.com/notifications/unsubscribe-auth/AA87LvXBDuawKM1waCT4AUGn7-JI--Xaks5tlmRjgaJpZM4QvimW
.

[bruceleeroy18]

I am having same problem. (working on litecoind).

These are in my litecoin.conf, and lnd.conf. (litecoind. zmq... for lnd.conf)
zmqpubrawblock=tcp://127.0.0.1:28332
zmqpubrawtx=tcp://127.0.0.1:28332

Could the following be true in this case as well? @sansari "Eventually @Roasbeef noted that my bitcoind process needed to be compiled with ZMQ (it was not, I had installed via homebrew)... so basically lnd was saying it waiting for bitcoind to sync, but actually just never connecting."

Excerpt from lncli getinfo
"block_height": 1383274,
"block_hash": "3930e07795cac1bbe87f8fbc2f064c94f463e457c23838567bd453db9a6cc539",
"synced_to_chain": false,
"testnet": false,

LND

2018-07-01 12:42:23.263 [INF] LNWL: Opened wallet
2018-07-01 12:42:24.477 [INF] LTND: Primary chain is set to: litecoin
2018-07-01 12:42:24.510 [INF] LTND: Initializing litecoind backed fee estimator
2018-07-01 12:42:30.739 [INF] LNWL: Started listening for blocks via ZMQ on tcp://127.0.0.1:28332
2018-07-01 12:42:46.774 [INF] LNWL: The wallet has been unlocked without a time limit
2018-07-01 12:42:46.914 [INF] LTND: LightningWallet opened
2018-07-01 12:42:49.369 [INF] LNWL: Catching up block hashes to height 1380238, this will take a while...
2018-07-01 12:42:49.417 [INF] HSWC: Restoring in-memory circuit state from disk
2018-07-01 12:42:49.421 [INF] HSWC: Payment circuits loaded: num_pending=0, num_open=0
2018-07-01 12:42:49.451 [INF] LNWL: Caught up to height 0
2018-07-01 12:42:49.585 [INF] RPCS: RPC server listening on 127.0.0.1:10009
2018-07-01 12:42:49.619 [INF] RPCS: gRPC proxy started at 127.0.0.1:8080
2018-07-01 12:42:52.162 [INF] LTND: Waiting for chain backend to finish sync, start_height=1380244

[roeierez]

I have investigated this hang in new address and I am sharing here my observations:
During initial sync the function syncWithChain (in btcwallet/wallet.go) is fetching the block headers from the btcd peers and commits them to the db every 10K blocks.
On start of every such batch the bucket with key "waddrmgrNamespaceKey" is locked for write (tx.ReadWriteBucket(waddrmgrNamespaceKey) and the same lock is attempted by the "NewAddress" function.
I think this causes the NewAddress function to wait and hang in the cases of slow connectivity or when the syncToChain flag "refuses" to turn true (it happens form time to time).
Also when the batch is completed, right after the Commit to the db a new attempt to open the bucket for write immediately executed which races with the NewAddress waiting go routine.
If you agree with me, I am interested to move forward with a PR for this issue

[Roasbeef]

Hey @roeierez yeah that sounds about correct! As is now it's _sometimes_ able to get a read transaction in before the main batched write transaction is in. One way to get around this would be to cache/load the very first address before we being the full initial chain catch up.