LND autounlock doesn't work if lnd backend changed

[kilrau]

In xud-docker, if lnd is restarted via docker restart, ExchangeUnion/xud-docker#724 (comment), xud unlocks lnd automatically without problems. If lnd is restarted with a different backend though (e.g. Neutrino -> bitcoind), this doesn't work. also xucli unlock doesn't unlock lnd's in that case, manually running lndbtc-lncli unlock works. Restarting xud fixes this and xucli unlock successfully unlocks lnds.

[sangaman]

Just so I'm clear on what's happening:

1. We start xud, unlock it, and xud unlocks an lnd server using a neutrino backend.

2. We shutdown lnd (while xud remains running) and restart lnd using a different backend (bitcoind) but locked by the same password.

3. Lnd doesn't auto unlock as we'd expect.

Is all that correct?

[reliveyy]

Yes. @sangaman

The xud will mark lnd as locked when any gRPC call returned UNIMPLEMENTED. So I designed the case below

1. bash xud.sh -b fix-lnd-mode-switching
2. bash xud.sh -b fix-lnd-mode-switching --bitcoind.mode=native

Now lndbtc shows "Wallet locked". In xud-ctl shell

Step 1. Try unlock

Enter master xud password: 
xud is running and unlocked, try checking its status with 'xucli getinfo'

Result: lndbtc is still locked. (xud init service is disabled in this case)

Step 2. Try getinfo then unlock

LND-BTC Info: lnd-BTC is Disconnected

Enter master xud password: 
xud is running and unlocked, try checking its status with 'xucli getinfo'

I did this step because any RPC call to lnd with UNIMPLEMENTED should emit locked event in xud LndClient.

Result: lndbtc is still locked. (xud init service is disabled in this case too)

Step 3. Restart xud then unlock

Result: lndbtc is unlocked.

[kilrau]

Is all that correct?

Correct. Here the full flow: ExchangeUnion/xud-docker#724 (comment)

[reliveyy]

@sangaman So I think one problem is that the xucli unlock command communicates with xud GrpcInitService. While this init service believes the underlying lnd is unlocked.

[sangaman]

@kilrau @reliveyy Is the tls cert changing between lnd restarts? If it's a different lnd instance with a different data dir I would expect that to be the case. I see a lot of ssl_transport_security.cc:1245] Handshake failed with fatal error SSL_ERROR_SSL: error:1416F086:SSL routines:tls_process_server_certificate:certificate verify failed in the logs of the comment you linked to, and it looks like xud is simply unable to communicate with lnd at all. When we restart xud we also reload the tls certs for lnd, so that might be what is causing the issue to get resolved after a restart.

@sangaman So I think one problem is that the xucli unlock command communicates with xud GrpcInitService. While this init service believes the underlying lnd is unlocked.

I'm not sure this is the issue, since xud is already unlocked when the lnd restart happens.

[kilrau]

I tried to reproduce this today to check on the certs by doing the same light -> native -> light flow as in ExchangeUnion/xud-docker#724 (comment) . This time I managed to get lndbtc failing to start after switching from light to native:

Sep 24 13:01:36.000 [notice] Parsing GEOIP IPv6 file /usr/share/tor/geoip6.
Sep 24 13:01:37.000 [warn] You are running Tor as root. You don't need to, and you probably shouldn't.
Sep 24 13:01:37.000 [notice] Bootstrapped 0% (starting): Starting
Sep 24 13:01:37.000 [notice] Starting with guard context "default"
2020-09-24 13:01:37,649 INFO spawned: 'lnd' with pid 32
2020-09-24 13:01:37,649 INFO success: tor entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)
[entrypoint] Enabling native mode
Waiting for lnd-bitcoin onion address...
Onion address for lnd-bitcoin is vsrtuyxkppv5symnybg4wt4yqoxkuc552ovclcdvf3meds444quiaiad.onion
Attempting automatic RPC configuration to bitcoind
unable to load RPC credentials for bitcoind: unable to extract RPC credentials: open /root/.bitcoin/bitcoin.conf: no such file or directory, cannot start w/o RPC connection
2020-09-24 13:01:37,847 CRIT uncaptured python exception, closing channel <POutputDispatcher at 140222670001248 for <Subprocess at 140222670267488 with name lnd in state STARTING> (stderr)> (<class 'OSError'>:[Errno 29] Invalid seek [/usr/lib/python3.8/site-packages/supervisor/supervisord.py|runforever|218] [/usr/lib/python3.8/site-packages/supervisor/dispatchers.py|handle_read_event|270] [/usr/lib/python3.8/site-packages/supervisor/dispatchers.py|record_output|204] [/usr/lib/python3.8/site-packages/supervisor/dispatchers.py|_log|173] [/usr/lib/python3.8/site-packages/supervisor/loggers.py|info|327] [/usr/lib/python3.8/site-packages/supervisor/loggers.py|log|345] [/usr/lib/python3.8/site-packages/supervisor/loggers.py|emit|227] [/usr/lib/python3.8/site-packages/supervisor/loggers.py|doRollover|264])
2020-09-24 13:01:37,849 INFO exited: lnd (exit status 1; not expected)
Sep 24 13:01:38.000 [notice] Bootstrapped 5% (conn): Connecting to a relay
Sep 24 13:01:38.000 [notice] Bootstrapped 10% (conn_done): Connected to a relay
Sep 24 13:01:38.000 [notice] Bootstrapped 14% (handshake): Handshaking with a relay
Sep 24 13:01:38.000 [notice] Bootstrapped 15% (handshake_done): Handshake with a relay done
Sep 24 13:01:38.000 [notice] Bootstrapped 75% (enough_dirinfo): Loaded enough directory info to build circuits
Sep 24 13:01:38.000 [notice] Bootstrapped 90% (ap_handshake_done): Handshake finished with a relay to build circuits
Sep 24 13:01:38.000 [notice] Bootstrapped 95% (circuit_create): Establishing a Tor circuit
Sep 24 13:01:39.000 [notice] Bootstrapped 100% (done): Done
2020-09-24 13:01:40,714 INFO spawned: 'lnd' with pid 55
[entrypoint] Enabling native mode
Waiting for lnd-bitcoin onion address...
Onion address for lnd-bitcoin is vsrtuyxkppv5symnybg4wt4yqoxkuc552ovclcdvf3meds444quiaiad.onion
Attempting automatic RPC configuration to bitcoind
unable to load RPC credentials for bitcoind: unable to extract RPC credentials: open /root/.bitcoin/bitcoin.conf: no such file or directory, cannot start w/o RPC connection
2020-09-24 13:01:40,842 CRIT uncaptured python exception, closing channel <POutputDispatcher at 140222670001248 for <Subprocess at 140222670267488 with name lnd in state STARTING> (stderr)> (<class 'OSError'>:[Errno 29] Invalid seek [/usr/lib/python3.8/site-packages/supervisor/supervisord.py|runforever|218] [/usr/lib/python3.8/site-packages/supervisor/dispatchers.py|handle_read_event|270] [/usr/lib/python3.8/site-packages/supervisor/dispatchers.py|record_output|204] [/usr/lib/python3.8/site-packages/supervisor/dispatchers.py|_log|173] [/usr/lib/python3.8/site-packages/supervisor/loggers.py|info|327] [/usr/lib/python3.8/site-packages/supervisor/loggers.py|log|345] [/usr/lib/python3.8/site-packages/supervisor/loggers.py|emit|227] [/usr/lib/python3.8/site-packages/supervisor/loggers.py|doRollover|264])
2020-09-24 13:01:40,855 INFO exited: lnd (exit status 1; not expected)
2020-09-24 13:01:43,860 INFO spawned: 'lnd' with pid 94
[entrypoint] Enabling native mode
Waiting for lnd-bitcoin onion address...
Onion address for lnd-bitcoin is vsrtuyxkppv5symnybg4wt4yqoxkuc552ovclcdvf3meds444quiaiad.onion
Attempting automatic RPC configuration to bitcoind
unable to load RPC credentials for bitcoind: unable to extract RPC credentials: open /root/.bitcoin/bitcoin.conf: no such file or directory, cannot start w/o RPC connection
2020-09-24 13:01:43,947 CRIT uncaptured python exception, closing channel <POutputDispatcher at 140222670001248 for <Subprocess at 140222670267488 with name lnd in state STARTING> (stderr)> (<class 'OSError'>:[Errno 29] Invalid seek [/usr/lib/python3.8/site-packages/supervisor/supervisord.py|runforever|218] [/usr/lib/python3.8/site-packages/supervisor/dispatchers.py|handle_read_event|270] [/usr/lib/python3.8/site-packages/supervisor/dispatchers.py|record_output|204] [/usr/lib/python3.8/site-packages/supervisor/dispatchers.py|_log|173] [/usr/lib/python3.8/site-packages/supervisor/loggers.py|info|327] [/usr/lib/python3.8/site-packages/supervisor/loggers.py|log|345] [/usr/lib/python3.8/site-packages/supervisor/loggers.py|emit|227] [/usr/lib/python3.8/site-packages/supervisor/loggers.py|doRollover|264])
2020-09-24 13:01:43,950 INFO exited: lnd (exit status 1; not expected)
2020-09-24 13:01:44,951 INFO gave up: lnd entered FATAL state, too many start retries too quickly

Certificates didn't change so far. Will try once more.