Xud: lnd unlock issues

[kilrau]

lndltc reports that it was succesfully unlocked, but actually wasn't. E.g. calling lndltc-lncli getinfo returns that it is still locked. Unlockling via lndltc-lncli unlock also reports the "Success" message, but it turns out lndltc is still locked.

mainnet > lndltc-lncli getinfo
[lncli] Wallet is encrypted. Please unlock using 'lncli unlock', or set password using 'lncli create' if this is the first time starting lnd.
mainnet > lndltc-lncli unlock
Input wallet password: 

lnd successfully unlocked!
mainnet > lndltc-lncli getinfo
[lncli] Wallet is encrypted. Please unlock using 'lncli unlock', or set password using 'lncli create' if this is the first time starting lnd.

Restarting lndltc fixes this. Can be easily reproduced by simply starting up testnet/mainnet.

[kilrau]

Also reported in https://github.com/ExchangeUnion/xud/issues/1319#issuecomment-553943392

[kilrau]

I know you were looking into this in greater detail over the past days. Please kindly leave your findings here @erkarl

[erkarl]

@kilrau I feel like there are multiple issues going on with lndltc unlock. The first one is that upon a fresh sync lndltc crashes once litecoind is synced. Restarting and unlocking lndltc solves the problem.

[kilrau]

As discussed, let's build new images, push & test again @erkarl

[erkarl]

xud image updated.

[kilrau]

I just reproduced this with lndbtc. I set my mainnet config to connect to my external bitcoind, which is still syncing hence not available. I suspect it has to do with the chainbackend not being ready when lnd starts having unlock issues:

mainnet > status
┌───────────┬────────────────────────────────────────────────┐
│ SERVICE   │ STATUS                                         │
├───────────┼────────────────────────────────────────────────┤
│ bitcoind  │ Unavailable (Connection to external failed)    │
├───────────┼────────────────────────────────────────────────┤
│ litecoind │ Syncing 0.00% (0/884000)                       │
├───────────┼────────────────────────────────────────────────┤
│ geth      │ Ready (Connected to external)                  │
├───────────┼────────────────────────────────────────────────┤
│ lndbtc    │ Wallet locked. Unlock with xucli unlock.       │
├───────────┼────────────────────────────────────────────────┤
│ lndltc    │ Waiting for sync                               │
├───────────┼────────────────────────────────────────────────┤
│ raiden    │ Ready                                          │
├───────────┼────────────────────────────────────────────────┤
│ xud       │ Waiting for lndbtc, lndltc                     │
└───────────┴────────────────────────────────────────────────┘
mainnet > lndbtc-lncli unlock
Input wallet password: 

lnd successfully unlocked!
mainnet > lndbtc-lncli getinfo
[lncli] Wallet is encrypted. Please unlock using 'lncli unlock', or set password using 'lncli create' if this is the first time starting lnd.

[erkarl]

logs lndbtc would have been helpful to see if xud tried to unlock it after it crashed/stopped.

[sangaman]

That's helpful, I can try to simulate by bringing down bitcoind.

[kilrau]

Two different scenarios:

1. External bitcoind is configured in mainnet.conf, and available on my local network, but e.g. ports not open or rpc password wrong -> leads to scenario described above. Will provide logs once I'm back home to reproduce.
2. External bitcoind is configured in mainnet.conf, but I'm out of my local network and bitcoind is not available at all -> lead to the following lnd failure (logs):

mainnet > unlock
Enter master xud password: 
xud was unlocked succesfully
The following wallets were unlocked: LTC, BTC
mainnet > lndbtc-lncli getinfo
[lncli] rpc error: code = Unavailable desc = all SubConns are in TransientFailure, latest connection error: connection error: desc = "transport: Error while dialing dial tcp 127.0.0.1:10009: connect: connection refused"

[kilrau]

One more addon which shows pretty clearly that lnd's don't unlock when chain backends are not ready (in this case both bitcoind & litecoind):

mainnet > unlock
Enter master xud password: 
xud was unlocked succesfully
The following wallets were unlocked: BTC, LTC
mainnet > status
┌───────────┬────────────────────────────────────────────────┐
│ SERVICE   │ STATUS                                         │
├───────────┼────────────────────────────────────────────────┤
│ bitcoind  │ Unavailable (Connection to external failed)    │
├───────────┼────────────────────────────────────────────────┤
│ litecoind │ Rewinding blocks...                            │
├───────────┼────────────────────────────────────────────────┤
│ geth      │ Ready (Connected to external)                  │
├───────────┼────────────────────────────────────────────────┤
│ lndbtc    │ Wallet locked. Unlock with xucli unlock.       │
├───────────┼────────────────────────────────────────────────┤
│ lndltc    │ Wallet locked. Unlock with xucli unlock.       │
├───────────┼────────────────────────────────────────────────┤
│ raiden    │ Ready                                          │
├───────────┼────────────────────────────────────────────────┤
│ xud       │ Waiting for lndbtc, lndltc                     │
└───────────┴────────────────────────────────────────────────┘

[sangaman]

What seems to happen here is that if lnd is unlocked while the backing bitcoind node is unavailable, lnd responds to the unlock call indicating a success but then immediately exits after it can't reach bitcoind. When you then try lndbtc-lncli getinfo you get that error indicating it's not reachable because it's no longer running. Docker doesn't always seem to automatically restart lnd from my testing - it's not clear why to me so that might need some more investigation.

It also seems that lnd exits immediately if bitcoind is online but is in the block verification stage which can take up to a few minutes upon startup.

2020-02-17 04:26:02.339 [INF] LNWL: Opened wallet
2020-02-17 04:26:02.450 [INF] LTND: Primary chain is set to: bitcoin
2020-02-17 04:26:02.459 [ERR] LTND: Unable to create chain control: unable to connect to bitcoind: -28: Loading block index...
2020-02-17 04:26:02.459 [INF] LTND: Shutdown complete
Unable to create chain control: unable to connect to bitcoind: -28: Loading block index...

When lnd does get restarted, xud wasn't always automatically re-unlocking it because of an edge-case bug with the auto unlock logic. That should be fixed in https://github.com/ExchangeUnion/xud/pull/1394. I believe what was happening is that lnd comes online when the docker environment is brought up, crashes after the first unlock, then gets restarted, automatically unlocked, and crashes again since bitcoind/litecoind is still initializing. After that no more automatic unlocks would happen because of these rapid back-to-back lnd restarts.

I'm not sure if lnd's behavior is by design - they might be amenable to a PR that checks if the backing node is online before responding that the unlock was a success. We could also probably handle this more gracefully within xud by not merely unlocking lnd but also attempting a getinfo before reporting that it was successfully unlocked. That would prevent the possibility that we report a particular lnd instance as "unlocked" only for the user to find that lnd is still unavailable. I can make a separate PR for that, but the one above should at least eventually unlock lnd when bitcoind or litecoind is properly configured/online.

From the perspective of docker, we could also look into waiting for bitcoind/litecoind to finish the block verification stage (in other words, when they can respond to a regular rpc call like getblockchaininfo) before starting lnd and xud.

[kilrau]

Another case disovered by @erkarl :+1:

so what's happening with lnds is that:

1. xucli unlock
2. lnds get stuck to Opened wallet
3. xud marks lnds as disconnected

what is working:

1. start docker environment
2. ssh into lnd containers and manually lncli unlock
3. xucli unlock
4. success, xud getinfo reports lnds as connected

[kilrau]

Just ran into this too. xud-docker up

• lndltc stuck at 2020-02-26 18:14:22.939 [INF] LNWL: Opened wallet
• xud logs show this (no more LND-LTC entries thereafter):

26/02/2020 18:14:33.605 [LND-LTC] error: getinfo error: Error: 14 UNAVAILABLE: failed to connect to all addresses
    at Object.exports.createStatusError (/app/node_modules/grpc/src/common.js:91:15)
    at Object.onReceiveStatus (/app/node_modules/grpc/src/client_interceptors.js:1209:28)
    at InterceptingListener._callNext (/app/node_modules/grpc/src/client_interceptors.js:568:42)
    at InterceptingListener.onReceiveStatus (/app/node_modules/grpc/src/client_interceptors.js:618:8)
    at callback (/app/node_modules/grpc/src/client_interceptors.js:847:24)
26/02/2020 18:14:33.605 [LND-LTC] error: could not verify connection at lndltc:10009, error: {}, retrying in 5000 ms
26/02/2020 18:14:38.607 [LND-LTC] info: trying to verify connection to lnd at lndltc:10009

• xucli getinfo shows lnd-LTC is Disconnected
• restart lndltc, lndltc-lncli unlock -> all good

[kilrau]

And another case. LNDLTC took a moment, but now is up and well:

testnet > lndltc-lncli getinfo
{
    "version": "0.9.0-beta commit=v0.9.0-beta",
    "identity_pubkey": "0355b06265a7290663d8cb4339c9961af4e28d63d5f83228724b56c9ed74d279e5",
    "alias": "0355b06265a7290663d8",
    "color": "#3399ff",
    "num_pending_channels": 0,
    "num_active_channels": 0,
    "num_inactive_channels": 0,
    "num_peers": 1,
    "block_height": 1384580,
    "block_hash": "0e6be33bcaa54f4ed9c5db67d1c53d11b89ae2cd21bb07ca4d7fdd6573056791",
    "best_header_timestamp": "1582743262",
    "synced_to_chain": true,
    "synced_to_graph": true,
    "testnet": true,
    "chains": [
        {
            "chain": "litecoin",
            "network": "testnet"
        }
    ],
    "uris": [
        "03[e-mail]:20735"
    ],
    "features": {
        "0": {
            "name": "data-loss-protect",
            "is_required": true,
            "is_known": true
        },
        "5": {
            "name": "upfront-shutdown-script",
            "is_required": false,
            "is_known": true
        },
        "7": {
            "name": "gossip-queries",
            "is_required": false,
            "is_known": true
        },
        "9": {
            "name": "tlv-onion",
            "is_required": false,
            "is_known": true
        },
        "13": {
            "name": "static-remote-key",
            "is_required": false,
            "is_known": true
        },
        "15": {
            "name": "payment-addr",
            "is_required": false,
            "is_known": true
        },
        "17": {
            "name": "multi-path-payments",
            "is_required": false,
            "is_known": true
        }
    }
}

but xud is stuck with

LND-LTC Info:
┌──────────┬────────────────────────────────────┐
│ Status   │ lnd-LTC is WaitingUnlock           │
├──────────┼────────────────────────────────────┤
│ Version  │                                    │
├──────────┼────────────────────────────────────┤
│ Address  │                                    │
├──────────┼────────────────────────────────────┤
│ Alias    │                                    │
├──────────┼────────────────────────────────────┤
│ Channels │ Active: 0 | Pending: 0 | Closed: 0 │
├──────────┼────────────────────────────────────┤
│ Network  │                                    │
└──────────┴────────────────────────────────────┘ 

testnet-2020-02-26-19-51-01.log
lnd.log
xud.log

[erkarl]

my current flow on mainnet with lnd unlocking is:

1. start environment and unlock
2. status says Container running for lnds
3. restart lndbtc
4. status says Wallet is locked.
5. lndbtc-lncli unlock
6. success, repeat for ltc

the lnds are not automatically unlocked