Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Don't allow manual close of restored channels #3321

Closed
stefanwouldgo opened this issue Jul 17, 2019 · 20 comments · Fixed by #4525
Closed

Don't allow manual close of restored channels #3321

stefanwouldgo opened this issue Jul 17, 2019 · 20 comments · Fixed by #4525
Assignees
Labels
backups channels P3 might get fixed, nice to have recovery Related to the backup/restoration of LND data (e.g. wallet seeds) safety General label for issues/PRs related to the safety of using the software SCB Related to static channel backup v0.12
Milestone

Comments

@stefanwouldgo
Copy link

Background

I was running LND 0.6.1 on bitcoin 0.18.0 on my old phone (Termux). Copying channel updates by inotify. Then my micro sd containing .lnd died.

After I received my new card, I tried restoring both offchain and onchain funds using
lncli create -multi_file=channels.backup (on 0.6.1 again), but LND crashed. Sorry, I didn't get any logs.

Instead, I tried the same on the just released 0.7.0. This time, it didn't crash, and the onchain balance got restored, but the channels didn't get closed. I used to have two channels open with funds on my side. One didn't show up at all, the other remained in waiting_close_channels. When I tried to force-close this one, LND crashed again, saying something along the lines of "chain-link missing".

So I tried it a third time, this time first doing just lncli create (with the seed), then later lncli restorechanbackup. This again restored the onchain funds. One channel is again in waiting_close_channels, and this time, the other channel is also here, but it's in pending_force_close_channels (and the commitment-tx has long been confirmed).

Your environment

  • version of lnd

0.7.0 (from 0.6.1)

  • which operating system (uname -a on *Nix)

Linux localhost 3.4.0-perf-gbccb33a #1 SMP PREEMPT Fri Jul 10 09:23:01 2015 armv7l Android

  • version of btcd, bitcoind, or other backend

bitcoind 0.18.0

  • any other relevant environment details

Steps to reproduce

probably hard to reproduce. Kill your .lnd with open channels, then try to restore.

Expected behaviour

All open channels should be closed and the funds be returned to my wallet.

Actual behaviour

Onchain funds got returned, but it appears that one force-closed channel isn't recognized as returned to us while another is kept open, and makes lnd crash on force-close.

@wpaulino
Copy link
Contributor

Could you provide logs of the recovery process along with the errors that cause the crash?

@cfromknecht
Copy link
Contributor

cfromknecht commented Jul 17, 2019

When I tried to force-close this one, LND crashed again, saying something along the lines of "chain-link missing".

You can't force close restored channels as you don't have any commitments, the DLP protocol should request a force close from the remote side once you are able to reconnect.

As @wpaulino some logs will be needed to figure out exactly what's going on

@stefanwouldgo
Copy link
Author

I guess this portion of the logs is relevant, if privacy-killing:

2019-07-11 08:47:33.021 [INF] NTFN: Dispatching confirmed spend notification for outpoint=e8d2c8a62808377520c7926ece00c925f942cdff832bca5d6c6b08695bddc180:0 at height=584903 2019-07-11 08:47:33.125 [WRN] CNCT: Unprompted commitment broadcast for ChannelPoint(e8d2c8a62808377520c7926ece00c925f942cdff832bca5d6c6b08695bddc180:0)
2019-07-11 08:47:33.125 [WRN] CNCT: Remote node broadcast state #18, which is more than 1 beyond best known state #0!!! Attempting recovery...
2019-07-11 08:47:33.126 [INF] CNCT: Recovered commit point(023e2a39aba2501787242cef37e4e236672e12b5cdac5accbb01ba9bcd5ffc9175) for channel(e8d2c8a62808377520c7926ece00c925f942cdff832bca5d6c6b08695bddc180:0)! Now attempting to use it to sweep our funds...
2019-07-11 08:47:33.127 [INF] CNCT: Unilateral close of ChannelPoint(e8d2c8a62808377520c7926ece00c925f942cdff832bca5d6c6b08695bddc180:0) detected
2019-07-11 08:47:33.147 [INF] CNCT: ChannelArbitrator(e8d2c8a62808377520c7926ece00c925f942cdff832bca5d6c6b08695bddc180:0): remote party has closed channel out on-chain
2019-07-11 08:47:33.306 [INF] CHBU: Updating on-disk multi SCB backup: num_old_chans=0, num_new_chans=0
2019-07-11 08:47:33.332 [INF] NTFN: New confirmation subscription: txid=bef38f19cf9adf21f92da432cf477b060721caeb22e8d1bbdf9e1825e1780bdf, num_confs=1
2019-07-11 08:47:33.333 [INF] NTFN: New confirmation subscription: conf_id=1, txid=bef38f19cf9adf21f92da432cf477b060721caeb22e8d1bbdf9e1825e1780bdf, height_hint=583962
2019-07-11 08:47:33.359 [INF] CNCT: ChannelArbitrator(e8d2c8a62808377520c7926ece00c925f942cdff832bca5d6c6b08695bddc180:0): still awaiting contract resolution
2019-07-11 08:47:33.440 [INF] CHBU: Updating backup file at /data/data/com.termux/files/home/.lnd/data/chain/bitcoin/mainnet/channel.backup
2019-07-11 08:47:33.470 [INF] CHBU: Swapping old multi backup file from /data/data/com.termux/files/home/.lnd/data/chain/bitcoin/mainnet/temp-dont-use.backup to /data/data/com.termux/files/home/.lnd/data/chain/bitcoin/mainnet/channel.backup
2019-07-11 08:47:37.004 [INF] NTFN: Dispatching confirmed spend notification for outpoint=b1e2a036daf3e559d8b0c6c8ec8e430778ca5d4d7f0602fb14ead947ef60fcba:0 at height=584903 2019-07-11 08:47:37.018 [WRN] CNCT: Unprompted commitment broadcast for ChannelPoint(b1e2a036daf3e559d8b0c6c8ec8e430778ca5d4d7f0602fb14ead947ef60fcba:0)
2019-07-11 08:47:37.021 [WRN] CNCT: Remote node broadcast state #25, which is more than 1 beyond best known state #0!!! Attempting recovery...
2019-07-11 08:47:37.023 [INF] CNCT: Recovered commit point(0271efe6a8518d4b4bf189e44a1eeddaea14d873140a60c613926430109c65fe8f) for channel(b1e2a036daf3e559d8b0c6c8ec8e430778ca5d4d7f0602fb14ead947ef60fcba:0)! Now attempting to use it to sweep our funds...
2019-07-11 08:47:37.026 [INF] CNCT: Unilateral close of ChannelPoint(b1e2a036daf3e559d8b0c6c8ec8e430778ca5d4d7f0602fb14ead947ef60fcba:0) detected
2019-07-11 08:47:37.038 [INF] CNCT: ChannelArbitrator(b1e2a036daf3e559d8b0c6c8ec8e430778ca5d4d7f0602fb14ead947ef60fcba:0): remote party has closed channel out on-chain
2019-07-11 08:47:37.275 [INF] CHBU: Updating on-disk multi SCB backup: num_old_chans=0, num_new_chans=0
2019-07-11 08:47:37.289 [INF] CNCT: ChannelArbitrator(b1e2a036daf3e559d8b0c6c8ec8e430778ca5d4d7f0602fb14ead947ef60fcba:0): contract resolutions empty, marking channel as fully resolved!

@wpaulino
Copy link
Contributor

Looking at these outputs on-chain, they seem to all have been swept back to your wallet (assuming the funds were on your side of the channel). Are these channels still showing under pendingchannels? If so, could you restart with --debuglevel=CNCT=debug and provide those logs?

@stefanwouldgo
Copy link
Author

I filtered only the CNCT lines. Let me know if you need more!

2019-07-19 12:28:37.479 [INF] CNCT: Creating ChannelArbitrators for 2 active channels
2019-07-19 12:28:37.501 [DBG] CNCT: New ChainEventSubscription(id=0) for ChannelPoint(0dfdfea27fd8cf14b7e1da1dfe0231f2c8cc2ce7adea755f777c31db5396b511:0)
2019-07-19 12:28:37.501 [DBG] CNCT: New ChainEventSubscription(id=0) for ChannelPoint(0bbc93b20ff29ff564b88f5e41005cddcea6de76ac5692f47cfae9f5cc94a9c4:0)
2019-07-19 12:28:37.527 [INF] CNCT: Creating ChannelArbitrators for 1 closing channels
2019-07-19 12:28:37.533 [DBG] CNCT: Starting chain watcher for ChannelPoint(0bbc93b20ff29ff564b88f5e41005cddcea6de76ac5692f47cfae9f5cc94a9c4:0)
2019-07-19 12:28:37.533 [DBG] CNCT: Starting chain watcher for ChannelPoint(0dfdfea27fd8cf14b7e1da1dfe0231f2c8cc2ce7adea755f777c31db5396b511:0)
2019-07-19 12:28:37.627 [INF] CNCT: Close observer for ChannelPoint(0bbc93b20ff29ff564b88f5e41005cddcea6de76ac5692f47cfae9f5cc94a9c4:0) active
2019-07-19 12:28:37.640 [INF] CNCT: Close observer for ChannelPoint(0dfdfea27fd8cf14b7e1da1dfe0231f2c8cc2ce7adea755f777c31db5396b511:0) active
2019-07-19 12:28:37.640 [DBG] CNCT: Starting ChannelArbitrator(0dfdfea27fd8cf14b7e1da1dfe0231f2c8cc2ce7adea755f777c31db5396b511:0), htlc_set=(map[contractcourt.HtlcSetKey]co$tractcourt.htlcSet) (len=2) {
2019-07-19 12:28:37.677 [INF] CNCT: ChannelArbitrator(0dfdfea27fd8cf14b7e1da1dfe0231f2c8cc2ce7adea755f777c31db5396b511:0): starting state=StateDefault
2019-07-19 12:28:37.737 [DBG] CNCT: ChannelArbitrator(0dfdfea27fd8cf14b7e1da1dfe0231f2c8cc2ce7adea755f777c31db5396b511:0): new block (height=586053) examining active HTLC's
2019-07-19 12:28:37.738 [DBG] CNCT: ChannelArbitrator(0dfdfea27fd8cf14b7e1da1dfe0231f2c8cc2ce7adea755f777c31db5396b511:0): checking chain actions at height=586053
2019-07-19 12:28:37.739 [DBG] CNCT: Starting ChannelArbitrator(0bbc93b20ff29ff564b88f5e41005cddcea6de76ac5692f47cfae9f5cc94a9c4:0), htlc_set=(map[contractcourt.HtlcSetKey]co$tractcourt.htlcSet) (len=2) {
2019-07-19 12:28:37.741 [INF] CNCT: ChannelArbitrator(0bbc93b20ff29ff564b88f5e41005cddcea6de76ac5692f47cfae9f5cc94a9c4:0): starting state=StateDefault
2019-07-19 12:28:37.742 [DBG] CNCT: ChannelArbitrator(0dfdfea27fd8cf14b7e1da1dfe0231f2c8cc2ce7adea755f777c31db5396b511:0): new block (height=586053) examining active HTLC's
2019-07-19 12:28:37.745 [DBG] CNCT: ChannelArbitrator(0dfdfea27fd8cf14b7e1da1dfe0231f2c8cc2ce7adea755f777c31db5396b511:0): checking chain actions at height=586053
2019-07-19 12:28:37.814 [DBG] CNCT: ChannelArbitrator(0bbc93b20ff29ff564b88f5e41005cddcea6de76ac5692f47cfae9f5cc94a9c4:0): new block (height=586053) examining active HTLC's
2019-07-19 12:28:37.815 [DBG] CNCT: ChannelArbitrator(0bbc93b20ff29ff564b88f5e41005cddcea6de76ac5692f47cfae9f5cc94a9c4:0): checking chain actions at height=586053
2019-07-19 12:28:37.815 [DBG] CNCT: Starting ChannelArbitrator(e8d2c8a62808377520c7926ece00c925f942cdff832bca5d6c6b08695bddc180:0), htlc_set=(map[contractcourt.HtlcSetKey]co$tractcourt.htlcSet) <nil>
2019-07-19 12:28:37.815 [DBG] CNCT: ChannelArbitrator(0bbc93b20ff29ff564b88f5e41005cddcea6de76ac5692f47cfae9f5cc94a9c4:0): new block (height=586053) examining active HTLC's
2019-07-19 12:28:37.816 [DBG] CNCT: ChannelArbitrator(0bbc93b20ff29ff564b88f5e41005cddcea6de76ac5692f47cfae9f5cc94a9c4:0): checking chain actions at height=586053
2019-07-19 12:28:37.818 [INF] CNCT: ChannelArbitrator(e8d2c8a62808377520c7926ece00c925f942cdff832bca5d6c6b08695bddc180:0): starting state=StateWaitingFullResolution
2019-07-19 12:28:37.883 [INF] CNCT: ChannelArbitrator(e8d2c8a62808377520c7926ece00c925f942cdff832bca5d6c6b08695bddc180:0): still awaiting contract resolution
2019-07-19 12:28:37.886 [INF] CNCT: ChannelArbitrator(e8d2c8a62808377520c7926ece00c925f942cdff832bca5d6c6b08695bddc180:0): relaunching 1 contract resolvers
2019-07-19 12:28:37.886 [DBG] CNCT: ChannelArbitrator(e8d2c8a62808377520c7926ece00c925f942cdff832bca5d6c6b08695bddc180:0): attempting to resolve *contractcourt.commitSweepRe$olver
2019-07-19 12:28:37.888 [DBG] CNCT: ChannelArbitrator(e8d2c8a62808377520c7926ece00c925f942cdff832bca5d6c6b08695bddc180:0): contract *contractcourt.commitSweepResolver not ye$ resolved
2019-07-19 12:28:37.889 [DBG] CNCT: *contractcourt.commitSweepResolver(e8d2c8a62808377520c7926ece00c925f942cdff832bca5d6c6b08695bddc180:0): waiting for commit tx to confirm
2019-07-19 12:33:56.678 [DBG] CNCT: New ChainEventSubscription(id=1) for ChannelPoint(0bbc93b20ff29ff564b88f5e41005cddcea6de76ac5692f47cfae9f5cc94a9c4:0)
2019-07-19 12:33:56.714 [INF] CNCT: Attempting to update ContractSignals for ChannelPoint(0bbc93b20ff29ff564b88f5e41005cddcea6de76ac5692f47cfae9f5cc94a9c4:0)
2019-07-19 12:34:16.914 [DBG] CNCT: New ChainEventSubscription(id=1) for ChannelPoint(0dfdfea27fd8cf14b7e1da1dfe0231f2c8cc2ce7adea755f777c31db5396b511:0)

@stefanwouldgo
Copy link
Author

It appears LND is now trying to sweep something but thinks its own txs are invalid:

2019-07-19 13:18:33.281 [INF] NTFN: Dispatching 1 confirmation notification for txid=bef38f19cf9adf21f92da432cf477b060721caeb22e8d1bbdf9e1825e1780bdf                [70/1939]2019-07-19 13:18:33.290 [INF] CNCT: *contractcourt.commitSweepResolver(e8d2c8a62808377520c7926ece00c925f942cdff832bca5d6c6b08695bddc180:0): sweeping commit output
2019-07-19 13:18:33.435 [INF] SWPR: Sweep request received: out_point=bef38f19cf9adf21f92da432cf477b060721caeb22e8d1bbdf9e1825e1780bdf:0, witness_type=CommitmentNoDelay, time_lock=0, amount=0.03481695 BTC, fee_preference=6 blocks
2019-07-19 13:18:33.472 [INF] NTFN: New spend subscription: spend_id=3, outpoint=bef38f19cf9adf21f92da432cf477b060721caeb22e8d1bbdf9e1825e1780bdf:0, height_hint=583963
2019-07-19 13:18:33.675 [INF] SWPR: Candidate sweep set of size=1, has yield=0.03475521 BTC
2019-07-19 13:18:33.676 [INF] SWPR: Sweep candidates at height=586057 with fee_rate=14066 sat/kw, yield 1 distinct txns
2019-07-19 13:18:55.848 [INF] CRTR: Processed channels=0 updates=52 nodes=0 in last 59.999694824s
2019-07-19 13:19:03.775 [INF] SWPR: Candidate sweep set of size=1, has yield=0.03475521 BTC
2019-07-19 13:19:03.934 [INF] SWPR: Creating sweep transaction for 1 inputs (0 CSV, 0 CLTV) using 14066 sat/kw
2019-07-19 13:19:04.015 [INF] LNWL: Inserting unconfirmed transaction 510889495df6172c94cc3c8f9cd3d3505a36f47ad986161c3b87a6905cec9173
2019-07-19 13:19:04.210 [INF] LNWL: Removed invalid transaction: (*wire.MsgTx)(0x863a6480)({
 Version: (int32) 2,
 TxIn: ([]*wire.TxIn) (len=1 cap=15) {
  (*wire.TxIn)(0x96774480)({
   PreviousOutPoint: (wire.OutPoint) bef38f19cf9adf21f92da432cf477b060721caeb22e8d1bbdf9e1825e1780bdf:0,
   SignatureScript: ([]uint8) <nil>,
   Witness: (wire.TxWitness) (len=2 cap=2) {
    ([]uint8) (len=72 cap=144) {
     00000000  30 45 02 21 00 dd 9c df  18 8f 2b 49 dd 08 29 4d  |0E.!......+I..)M|
     00000010  fd b5 eb 62 b8 49 2e 0e  0b 9d 64 ef 90 a3 8d 63  |...b.I....d....c|
     00000020  1e 30 c1 05 a1 02 20 44  db 1b e1 b1 41 64 3b 40  |.0.... D....Ad;@|
     00000030  47 c9 66 ef b5 f0 b3 4d  81 21 70 f5 05 23 1f 43  |G.f....M.!p..#.C|
     00000040  dd 5b a8 ac 46 dc 07 01                           |.[..F...|
    },
    ([]uint8) (len=33 cap=33) {
     00000000  02 fe 7d 9c 04 55 b6 e0  ee 77 bb c7 1e b9 6a bf  |..}..U...w....j.|
     00000010  c7 dc 38 b2 6c f8 a3 de  81 5b 21 21 a2 22 52 29  |..8.l....[!!."R)|
     00000020  92                                                |.|
    }
   },
   Sequence: (uint32) 0
  })
 },
 TxOut: ([]*wire.TxOut) (len=1 cap=15) {
  (*wire.TxOut)(0x863a64a0)({
   Value: (int64) 3475521,
   PkScript: ([]uint8) (len=22 cap=500) {
    00000000  00 14 14 9f da 07 bd 18  8e eb da e1 50 81 8b 87  |............P...|
    00000010  42 ad 68 f0 18 e6                                 |B.h...|
   }
  })
 LockTime: (uint32) 586057
})

2019-07-19 13:19:38.656 [INF] DISC: Broadcasting 87 new announcements in 9 sub batches
2019-07-19 13:19:55.848 [INF] CRTR: Processed channels=0 updates=67 nodes=0 in last 59.999420165s
2019-07-19 13:20:55.848 [INF] CRTR: Processed channels=0 updates=44 nodes=0 in last 59.999664306s
2019-07-19 13:21:08.656 [INF] DISC: Broadcasting 76 new announcements in 8 sub batches
2019-07-19 13:21:55.848 [INF] CRTR: Processed channels=0 updates=38 nodes=1 in last 59.999725344s
2019-07-19 13:22:16.909 [INF] CRTR: Pruning channel graph using block 00000000000000000005fbf9ee82aeab4cc498c4e68bfcc56819cec800794fad (height=586058)
2019-07-19 13:22:32.283 [INF] CRTR: Block 00000000000000000005fbf9ee82aeab4cc498c4e68bfcc56819cec800794fad (height=586058) closed 0 channels
2019-07-19 13:22:32.516 [INF] NTFN: New block: height=586058, sha=00000000000000000005fbf9ee82aeab4cc498c4e68bfcc56819cec800794fad
2019-07-19 13:22:32.590 [DBG] CNCT: ChannelArbitrator(0bbc93b20ff29ff564b88f5e41005cddcea6de76ac5692f47cfae9f5cc94a9c4:0): new block (height=586058) examining active HTLC's
2019-07-19 13:22:32.593 [DBG] CNCT: ChannelArbitrator(0bbc93b20ff29ff564b88f5e41005cddcea6de76ac5692f47cfae9f5cc94a9c4:0): checking chain actions at height=586058
2019-07-19 13:22:32.590 [DBG] CNCT: ChannelArbitrator(0dfdfea27fd8cf14b7e1da1dfe0231f2c8cc2ce7adea755f777c31db5396b511:0): new block (height=586058) examining active HTLC's
2019-07-19 13:22:32.596 [DBG] CNCT: ChannelArbitrator(0dfdfea27fd8cf14b7e1da1dfe0231f2c8cc2ce7adea755f777c31db5396b511:0): checking chain actions at height=586058
2019-07-19 13:22:32.595 [INF] UTXN: Attempting to graduate height=586058: num_kids=0, num_babies=0
2019-07-19 13:22:32.625 [INF] SWPR: Candidate sweep set of size=1, has yield=0.03475521 BTC
2019-07-19 13:22:32.632 [INF] SWPR: Sweep candidates at height=586058 with fee_rate=14064 sat/kw, yield 1 distinct txns
2019-07-19 13:22:38.656 [INF] DISC: Broadcasting 62 new announcements in 7 sub batches
2019-07-19 13:22:55.848 [INF] CRTR: Processed channels=0 updates=46 nodes=0 in last 59.999603272s
2019-07-19 13:23:04.642 [INF] SWPR: Candidate sweep set of size=1, has yield=0.03475521 BTC
2019-07-19 13:23:04.642 [INF] SWPR: Creating sweep transaction for 1 inputs (0 CSV, 0 CLTV) using 14064 sat/kw
2019-07-19 13:23:04.681 [INF] LNWL: Inserting unconfirmed transaction 1cda7d221bb85f92fc9e0d824751a83781ad21d26aaff7d0fa136cfdf168c457
2019-07-19 13:23:17.704 [INF] LNWL: Removed invalid transaction: (*wire.MsgTx)(0x864608e0)({
 Version: (int32) 2,
 TxIn: ([]*wire.TxIn) (len=1 cap=15) {
  (*wire.TxIn)(0x86069140)({
   PreviousOutPoint: (wire.OutPoint) bef38f19cf9adf21f92da432cf477b060721caeb22e8d1bbdf9e1825e1780bdf:0,
   SignatureScript: ([]uint8) <nil>,
   Witness: (wire.TxWitness) (len=2 cap=2) {
    ([]uint8) (len=72 cap=144) {
     00000000  30 45 02 21 00 d4 f1 db  58 7a 2d b4 12 c7 34 50  |0E.!....Xz-...4P|
     00000010  f6 1c 34 11 b9 34 6a 55  6c f4 12 9f b3 6f eb 04  |..4..4jUl....o..|
     00000020  9e 00 d9 bc 0f 02 20 0a  ee 0a 20 bf 7a b1 dd 76  |...... ... .z..v|
     00000030  ac ef f4 f2 50 9f 51 21  39 0f 35 32 a0 c3 d3 54  |....P.Q!9.52...T|
     00000040  4c 73 11 f5 94 9f 1d 01                           |Ls......|
    },
    ([]uint8) (len=33 cap=33) {
     00000000  02 fe 7d 9c 04 55 b6 e0  ee 77 bb c7 1e b9 6a bf  |..}..U...w....j.|
     00000010  c7 dc 38 b2 6c f8 a3 de  81 5b 21 21 a2 22 52 29  |..8.l....[!!."R)|
     00000020  92                                                |.|
    }
   },
   Sequence: (uint32) 0
  })
 },
 TxOut: ([]*wire.TxOut) (len=1 cap=15) {
  (*wire.TxOut)(0x86460900)({
   Value: (int64) 3475521,
   PkScript: ([]uint8) (len=22 cap=500) {
    00000000  00 14 14 9f da 07 bd 18  8e eb da e1 50 81 8b 87  |............P...|
    00000010  42 ad 68 f0 18 e6                                 |B.h...|
   }
  })
 },
 LockTime: (uint32) 586058
})

2019-07-19 13:23:20.966 [INF] CRTR: Pruning channel graph using block 0000000000000000000bd139144dc3fe9a9723b884a8700afe9c77cf5a52e5c4 (height=586059)
2019-07-19 13:23:33.764 [INF] UTXN: NurseryReport: building nursery report for channel e8d2c8a62808377520c7926ece00c925f942cdff832bca5d6c6b08695bddc180:0
2019-07-19 13:23:47.241 [INF] CRTR: Block 0000000000000000000bd139144dc3fe9a9723b884a8700afe9c77cf5a52e5c4 (height=586059) closed 0 channels
2019-07-19 13:23:48.240 [INF] NTFN: New block: height=586059, sha=0000000000000000000bd139144dc3fe9a9723b884a8700afe9c77cf5a52e5c4
2019-07-19 13:23:48.269 [INF] UTXN: Attempting to graduate height=586059: num_kids=0, num_babies=0
2019-07-19 13:23:48.269 [DBG] CNCT: ChannelArbitrator(0bbc93b20ff29ff564b88f5e41005cddcea6de76ac5692f47cfae9f5cc94a9c4:0): new block (height=586059) examining active HTLC's
2019-07-19 13:23:48.272 [DBG] CNCT: ChannelArbitrator(0bbc93b20ff29ff564b88f5e41005cddcea6de76ac5692f47cfae9f5cc94a9c4:0): checking chain actions at height=586059
2019-07-19 13:23:48.269 [DBG] CNCT: ChannelArbitrator(0dfdfea27fd8cf14b7e1da1dfe0231f2c8cc2ce7adea755f777c31db5396b511:0): new block (height=586059) examining active HTLC's
2019-07-19 13:23:48.275 [DBG] CNCT: ChannelArbitrator(0dfdfea27fd8cf14b7e1da1dfe0231f2c8cc2ce7adea755f777c31db5396b511:0): checking chain actions at height=586059
2019-07-19 13:23:48.359 [INF] SWPR: Sweep candidates at height=586059 with fee_rate=14064 sat/kw, yield 0 distinct txns

@wpaulino
Copy link
Contributor

The channel e8d2c8a62808377520c7926ece00c925f942cdff832bca5d6c6b08695bddc180 seems to be fully resolved on-chain. Assuming you swept it in a previous instance, the relevant wallet transaction would be 6c4b141662bd5286f47e81d42e7078c1f741f912fe2b7a9f9f6814b03cb2eb26, which at the time of writing this currently has an unconfirmed spend. I don't think there's an issue with this channel other than us detecting we resolved it in a previous instance and marking it as resolved again.

As for 0bbc93b20ff29ff564b88f5e41005cddcea6de76ac5692f47cfae9f5cc94a9c4, it's been force closed on-chain, but it looks like lnd has yet to detect its spend. This can take a while as it needs to scan blocks from the height the channel was created to the tip of the chain. We have a cache that streamlines this process, but it's not useful here since you lost data. If you let lnd run for a bit, it should detect the spend and sweep the output.

@wpaulino wpaulino changed the title Restoring channels hits multiple hickups Recognize previously restored channels Jul 25, 2019
@wpaulino wpaulino added backups channels P3 might get fixed, nice to have recovery Related to the backup/restoration of LND data (e.g. wallet seeds) safety General label for issues/PRs related to the safety of using the software SCB Related to static channel backup labels Jul 25, 2019
@stefanwouldgo
Copy link
Author

A month later, both channels still look the same. One says pending force closing, the other waiting close. Can I do anything to make lnd recognize what happened?

@wpaulino
Copy link
Contributor

For the pending force close, it will always stay in this state because of the issue outlined in my previous comment.

Regarding the other channel, has lnd been running without being stopped throughout the whole month? What are the latest logs for the channel after a restart?

@stefanwouldgo
Copy link
Author

So is there any way I can mark the force closed channel as resolved? It looks in the logs below like LND is waiting for a commit tx to confirm.

No, LND hasn't been running for a month straight, the platform I am working on isn't stable enough for that yet. But I think it has been running for at least a week multiple times now.

Here are the CNCT logs after a restart:
2019-08-30 08:43:18.112 [INF] CNCT: Creating ChannelArbitrators for 1 active channels 2019-08-30 08:43:18.117 [DBG] CNCT: New ChainEventSubscription(id=0) for ChannelPoint(0bbc93b20ff29ff564b88f5e41005cddcea6de76ac5692f47cfae9f5cc94a9c4:0) 2019-08-30 08:43:18.143 [INF] CNCT: Creating ChannelArbitrators for 1 closing channels 2019-08-30 08:43:18.143 [DBG] CNCT: Starting chain watcher for ChannelPoint(0bbc93b20ff29ff564b88f5e41005cddcea6de76ac5692f47cfae9f5cc94a9c4:0) 2019-08-30 08:43:18.204 [INF] CNCT: Close observer for ChannelPoint(0bbc93b20ff29ff564b88f5e41005cddcea6de76ac5692f47cfae9f5cc94a9c4:0) active 2019-08-30 08:43:18.204 [DBG] CNCT: Starting ChannelArbitrator(0bbc93b20ff29ff564b88f5e41005cddcea6de76ac5692f47cfae9f5cc94a9c4:0), htlc_set=(map[contractcourt.HtlcSetKey]contractcourt.htlcSet) (len=2) { 2019-08-30 08:43:18.204 [INF] CNCT: ChannelArbitrator(0bbc93b20ff29ff564b88f5e41005cddcea6de76ac5692f47cfae9f5cc94a9c4:0): starting state=StateDefault 2019-08-30 08:43:18.244 [DBG] CNCT: ChannelArbitrator(0bbc93b20ff29ff564b88f5e41005cddcea6de76ac5692f47cfae9f5cc94a9c4:0): new block (height=592413) examining active HTLC's 2019-08-30 08:43:18.244 [DBG] CNCT: ChannelArbitrator(0bbc93b20ff29ff564b88f5e41005cddcea6de76ac5692f47cfae9f5cc94a9c4:0): checking chain actions at height=592413 2019-08-30 08:43:18.244 [DBG] CNCT: Starting ChannelArbitrator(e8d2c8a62808377520c7926ece00c925f942cdff832bca5d6c6b08695bddc180:0), htlc_set=(map[contractcourt.HtlcSetKey]contractcourt.htlcSet) <nil> 2019-08-30 08:43:18.247 [DBG] CNCT: ChannelArbitrator(0bbc93b20ff29ff564b88f5e41005cddcea6de76ac5692f47cfae9f5cc94a9c4:0): new block (height=592413) examining active HTLC's 2019-08-30 08:43:18.252 [DBG] CNCT: ChannelArbitrator(0bbc93b20ff29ff564b88f5e41005cddcea6de76ac5692f47cfae9f5cc94a9c4:0): checking chain actions at height=592413 2019-08-30 08:43:18.252 [INF] CNCT: ChannelArbitrator(e8d2c8a62808377520c7926ece00c925f942cdff832bca5d6c6b08695bddc180:0): starting state=StateWaitingFullResolution 2019-08-30 08:43:18.292 [INF] CNCT: ChannelArbitrator(e8d2c8a62808377520c7926ece00c925f942cdff832bca5d6c6b08695bddc180:0): still awaiting contract resolution 2019-08-30 08:43:18.296 [INF] CNCT: ChannelArbitrator(e8d2c8a62808377520c7926ece00c925f942cdff832bca5d6c6b08695bddc180:0): relaunching 1 contract resolvers 2019-08-30 08:43:18.300 [DBG] CNCT: ChannelArbitrator(e8d2c8a62808377520c7926ece00c925f942cdff832bca5d6c6b08695bddc180:0): attempting to resolve *contractcourt.commitSweepResolver 2019-08-30 08:43:18.301 [DBG] CNCT: ChannelArbitrator(e8d2c8a62808377520c7926ece00c925f942cdff832bca5d6c6b08695bddc180:0): contract *contractcourt.commitSweepResolver not yet resolved 2019-08-30 08:43:18.303 [DBG] CNCT: *contractcourt.commitSweepResolver(e8d2c8a62808377520c7926ece00c925f942cdff832bca5d6c6b08695bddc180:0): waiting for commit tx to confirm 2019-08-30 08:43:35.889 [DBG] CNCT: New ChainEventSubscription(id=1) for ChannelPoint(0bbc93b20ff29ff564b88f5e41005cddcea6de76ac5692f47cfae9f5cc94a9c4:0) 2019-08-30 08:43:35.891 [INF] CNCT: Attempting to update ContractSignals for ChannelPoint(0bbc93b20ff29ff564b88f5e41005cddcea6de76ac5692f47cfae9f5cc94a9c4:0)

@wpaulino
Copy link
Contributor

wpaulino commented Aug 30, 2019

Could you also include non-CNCT logs for both channels?

@stefanwouldgo
Copy link
Author

0bbc93b20ff29ff564b88f5e41005cddcea6de76ac5692f47cfae9f5cc94a9c4:

2019-08-30 08:43:18.117 [DBG] CNCT: New ChainEventSubscription(id=0) for ChannelPoint(0bbc93b20ff29ff564b88f5e41005cddcea6de76ac5692f47cfae9f5cc94a9c4:0) [246/1943]2019-08-30 08:43:18.143 [DBG] CNCT: Starting chain watcher for ChannelPoint(0bbc93b20ff29ff564b88f5e41005cddcea6de76ac5692f47cfae9f5cc94a9c4:0) 2019-08-30 08:43:18.144 [INF] NTFN: New spend subscription: spend_id=1, outpoint=0bbc93b20ff29ff564b88f5e41005cddcea6de76ac5692f47cfae9f5cc94a9c4:0, height_hint=592413 2019-08-30 08:43:18.204 [INF] CNCT: Close observer for ChannelPoint(0bbc93b20ff29ff564b88f5e41005cddcea6de76ac5692f47cfae9f5cc94a9c4:0) active 2019-08-30 08:43:18.204 [DBG] CNCT: Starting ChannelArbitrator(0bbc93b20ff29ff564b88f5e41005cddcea6de76ac5692f47cfae9f5cc94a9c4:0), htlc_set=(map[contractcourt.HtlcSetKey]contractcourt.htlcSet) (len=2) { 2019-08-30 08:43:18.204 [INF] CNCT: ChannelArbitrator(0bbc93b20ff29ff564b88f5e41005cddcea6de76ac5692f47cfae9f5cc94a9c4:0): starting state=StateDefault 2019-08-30 08:43:18.244 [DBG] CNCT: ChannelArbitrator(0bbc93b20ff29ff564b88f5e41005cddcea6de76ac5692f47cfae9f5cc94a9c4:0): new block (height=592413) examining active HTLC's 2019-08-30 08:43:18.244 [DBG] CNCT: ChannelArbitrator(0bbc93b20ff29ff564b88f5e41005cddcea6de76ac5692f47cfae9f5cc94a9c4:0): checking chain actions at height=592413 2019-08-30 08:43:18.247 [DBG] CNCT: ChannelArbitrator(0bbc93b20ff29ff564b88f5e41005cddcea6de76ac5692f47cfae9f5cc94a9c4:0): new block (height=592413) examining active HTLC's 2019-08-30 08:43:18.252 [DBG] CNCT: ChannelArbitrator(0bbc93b20ff29ff564b88f5e41005cddcea6de76ac5692f47cfae9f5cc94a9c4:0): checking chain actions at height=592413 2019-08-30 08:43:35.841 [INF] PEER: NodeKey(0331f80652fb840239df8dc99205792bba2e559a05469915804c08420230e23c7c) loading ChannelPoint(0bbc93b20ff29ff564b88f5e41005cddcea6de76ac5692f47cfae9f5cc94a9c4:0) 2019-08-30 08:43:35.889 [DBG] CNCT: New ChainEventSubscription(id=1) for ChannelPoint(0bbc93b20ff29ff564b88f5e41005cddcea6de76ac5692f47cfae9f5cc94a9c4:0) 2019-08-30 08:43:35.890 [INF] HSWC: ChannelLink(0bbc93b20ff29ff564b88f5e41005cddcea6de76ac5692f47cfae9f5cc94a9c4:0) is starting 2019-08-30 08:43:35.891 [INF] HSWC: HTLC manager for ChannelPoint(0bbc93b20ff29ff564b88f5e41005cddcea6de76ac5692f47cfae9f5cc94a9c4:0) started, bandwidth=0 mSAT 2019-08-30 08:43:35.892 [INF] HSWC: Attempting to re-resynchronize ChannelPoint(0bbc93b20ff29ff564b88f5e41005cddcea6de76ac5692f47cfae9f5cc94a9c4:0) 2019-08-30 08:43:35.891 [INF] CNCT: Attempting to update ContractSignals for ChannelPoint(0bbc93b20ff29ff564b88f5e41005cddcea6de76ac5692f47cfae9f5cc94a9c4:0) 2019-08-30 08:44:10.896 [INF] HSWC: ChannelLink(0bbc93b20ff29ff564b88f5e41005cddcea6de76ac5692f47cfae9f5cc94a9c4:0) has exited 2019-08-30 08:44:10.897 [INF] HSWC: ChannelLink(0bbc93b20ff29ff564b88f5e41005cddcea6de76ac5692f47cfae9f5cc94a9c4:0) is stopping 2019-08-30 08:54:16.253 [DBG] CNCT: ChannelArbitrator(0bbc93b20ff29ff564b88f5e41005cddcea6de76ac5692f47cfae9f5cc94a9c4:0): new block (height=592414) examining active HTLC's 2019-08-30 08:54:16.254 [DBG] CNCT: ChannelArbitrator(0bbc93b20ff29ff564b88f5e41005cddcea6de76ac5692f47cfae9f5cc94a9c4:0): checking chain actions at height=592414 2019-08-30 09:27:22.643 [DBG] CNCT: ChannelArbitrator(0bbc93b20ff29ff564b88f5e41005cddcea6de76ac5692f47cfae9f5cc94a9c4:0): new block (height=592415) examining active HTLC's 2019-08-30 09:27:22.686 [DBG] CNCT: ChannelArbitrator(0bbc93b20ff29ff564b88f5e41005cddcea6de76ac5692f47cfae9f5cc94a9c4:0): checking chain actions at height=592415 2019-08-30 09:31:13.355 [DBG] CNCT: ChannelArbitrator(0bbc93b20ff29ff564b88f5e41005cddcea6de76ac5692f47cfae9f5cc94a9c4:0): new block (height=592416) examining active HTLC's 2019-08-30 09:31:13.359 [DBG] CNCT: ChannelArbitrator(0bbc93b20ff29ff564b88f5e41005cddcea6de76ac5692f47cfae9f5cc94a9c4:0): checking chain actions at height=592416 2019-08-30 09:48:26.113 [DBG] CNCT: ChannelArbitrator(0bbc93b20ff29ff564b88f5e41005cddcea6de76ac5692f47cfae9f5cc94a9c4:0): new block (height=592417) examining active HTLC's 2019-08-30 09:48:26.113 [DBG] CNCT: ChannelArbitrator(0bbc93b20ff29ff564b88f5e41005cddcea6de76ac5692f47cfae9f5cc94a9c4:0): checking chain actions at height=592417 2019-08-30 09:48:28.764 [DBG] CNCT: Stopping ChannelArbitrator(0bbc93b20ff29ff564b88f5e41005cddcea6de76ac5692f47cfae9f5cc94a9c4:0) 2019-08-30 16:16:05.752 [DBG] CNCT: New ChainEventSubscription(id=0) for ChannelPoint(0bbc93b20ff29ff564b88f5e41005cddcea6de76ac5692f47cfae9f5cc94a9c4:0) 2019-08-30 16:16:05.795 [DBG] CNCT: Starting chain watcher for ChannelPoint(0bbc93b20ff29ff564b88f5e41005cddcea6de76ac5692f47cfae9f5cc94a9c4:0) 2019-08-30 16:16:05.808 [INF] NTFN: New spend subscription: spend_id=1, outpoint=0bbc93b20ff29ff564b88f5e41005cddcea6de76ac5692f47cfae9f5cc94a9c4:0, height_hint=592417 2019-08-30 16:16:05.896 [INF] CNCT: Close observer for ChannelPoint(0bbc93b20ff29ff564b88f5e41005cddcea6de76ac5692f47cfae9f5cc94a9c4:0) active 2019-08-30 16:16:05.896 [DBG] CNCT: Starting ChannelArbitrator(0bbc93b20ff29ff564b88f5e41005cddcea6de76ac5692f47cfae9f5cc94a9c4:0), htlc_set=(map[contractcourt.HtlcSetKey]co$tractcourt.htlcSet) (len=2) { 2019-08-30 16:16:05.914 [INF] CNCT: ChannelArbitrator(0bbc93b20ff29ff564b88f5e41005cddcea6de76ac5692f47cfae9f5cc94a9c4:0): starting state=StateDefault 2019-08-30 16:16:05.960 [DBG] CNCT: ChannelArbitrator(0bbc93b20ff29ff564b88f5e41005cddcea6de76ac5692f47cfae9f5cc94a9c4:0): new block (height=592460) examining active HTLC's 2019-08-30 16:16:05.961 [DBG] CNCT: ChannelArbitrator(0bbc93b20ff29ff564b88f5e41005cddcea6de76ac5692f47cfae9f5cc94a9c4:0): checking chain actions at height=592460 2019-08-30 16:16:05.972 [DBG] CNCT: ChannelArbitrator(0bbc93b20ff29ff564b88f5e41005cddcea6de76ac5692f47cfae9f5cc94a9c4:0): new block (height=592460) examining active HTLC's 2019-08-30 16:16:05.973 [DBG] CNCT: ChannelArbitrator(0bbc93b20ff29ff564b88f5e41005cddcea6de76ac5692f47cfae9f5cc94a9c4:0): checking chain actions at height=592460 2019-08-30 16:17:39.380 [INF] PEER: NodeKey(0331f80652fb840239df8dc99205792bba2e559a05469915804c08420230e23c7c) loading ChannelPoint(0bbc93b20ff29ff564b88f5e41005cddcea6de76$c5692f47cfae9f5cc94a9c4:0) 2019-08-30 16:17:40.588 [DBG] CNCT: New ChainEventSubscription(id=1) for ChannelPoint(0bbc93b20ff29ff564b88f5e41005cddcea6de76ac5692f47cfae9f5cc94a9c4:0) [204/1943]2019-08-30 16:17:40.609 [INF] HSWC: ChannelLink(0bbc93b20ff29ff564b88f5e41005cddcea6de76ac5692f47cfae9f5cc94a9c4:0) is starting 2019-08-30 16:17:40.619 [INF] CNCT: Attempting to update ContractSignals for ChannelPoint(0bbc93b20ff29ff564b88f5e41005cddcea6de76ac5692f47cfae9f5cc94a9c4:0) 2019-08-30 16:17:40.620 [INF] HSWC: HTLC manager for ChannelPoint(0bbc93b20ff29ff564b88f5e41005cddcea6de76ac5692f47cfae9f5cc94a9c4:0) started, bandwidth=0 mSAT 2019-08-30 16:17:40.620 [INF] HSWC: Attempting to re-resynchronize ChannelPoint(0bbc93b20ff29ff564b88f5e41005cddcea6de76ac5692f47cfae9f5cc94a9c4:0) 2019-08-30 16:18:12.295 [DBG] CNCT: ChannelArbitrator(0bbc93b20ff29ff564b88f5e41005cddcea6de76ac5692f47cfae9f5cc94a9c4:0): new block (height=592461) examining active HTLC's 2019-08-30 16:18:12.296 [DBG] CNCT: ChannelArbitrator(0bbc93b20ff29ff564b88f5e41005cddcea6de76ac5692f47cfae9f5cc94a9c4:0): checking chain actions at height=592461 2019-08-30 16:18:15.624 [INF] HSWC: ChannelLink(0bbc93b20ff29ff564b88f5e41005cddcea6de76ac5692f47cfae9f5cc94a9c4:0) has exited 2019-08-30 16:18:15.625 [INF] HSWC: ChannelLink(0bbc93b20ff29ff564b88f5e41005cddcea6de76ac5692f47cfae9f5cc94a9c4:0) is stopping 2019-08-30 16:27:57.107 [DBG] CNCT: ChannelArbitrator(0bbc93b20ff29ff564b88f5e41005cddcea6de76ac5692f47cfae9f5cc94a9c4:0): new block (height=592462) examining active HTLC's 2019-08-30 16:27:57.107 [DBG] CNCT: ChannelArbitrator(0bbc93b20ff29ff564b88f5e41005cddcea6de76ac5692f47cfae9f5cc94a9c4:0): checking chain actions at height=592462 2019-08-30 16:43:32.687 [DBG] CNCT: ChannelArbitrator(0bbc93b20ff29ff564b88f5e41005cddcea6de76ac5692f47cfae9f5cc94a9c4:0): new block (height=592463) examining active HTLC's 2019-08-30 16:43:32.691 [DBG] CNCT: ChannelArbitrator(0bbc93b20ff29ff564b88f5e41005cddcea6de76ac5692f47cfae9f5cc94a9c4:0): checking chain actions at height=592463 2019-08-30 16:44:24.776 [DBG] CNCT: ChannelArbitrator(0bbc93b20ff29ff564b88f5e41005cddcea6de76ac5692f47cfae9f5cc94a9c4:0): new block (height=592464) examining active HTLC's 2019-08-30 16:44:24.776 [DBG] CNCT: ChannelArbitrator(0bbc93b20ff29ff564b88f5e41005cddcea6de76ac5692f47cfae9f5cc94a9c4:0): checking chain actions at height=592464 2019-08-30 16:44:42.633 [DBG] CNCT: ChannelArbitrator(0bbc93b20ff29ff564b88f5e41005cddcea6de76ac5692f47cfae9f5cc94a9c4:0): new block (height=592465) examining active HTLC's 2019-08-30 16:44:42.633 [DBG] CNCT: ChannelArbitrator(0bbc93b20ff29ff564b88f5e41005cddcea6de76ac5692f47cfae9f5cc94a9c4:0): checking chain actions at height=592465 2019-08-30 16:53:42.772 [DBG] CNCT: ChannelArbitrator(0bbc93b20ff29ff564b88f5e41005cddcea6de76ac5692f47cfae9f5cc94a9c4:0): new block (height=592466) examining active HTLC's 2019-08-30 16:53:42.772 [DBG] CNCT: ChannelArbitrator(0bbc93b20ff29ff564b88f5e41005cddcea6de76ac5692f47cfae9f5cc94a9c4:0): checking chain actions at height=592466 2019-08-30 17:01:46.276 [DBG] CNCT: ChannelArbitrator(0bbc93b20ff29ff564b88f5e41005cddcea6de76ac5692f47cfae9f5cc94a9c4:0): new block (height=592467) examining active HTLC's 2019-08-30 17:01:46.276 [DBG] CNCT: ChannelArbitrator(0bbc93b20ff29ff564b88f5e41005cddcea6de76ac5692f47cfae9f5cc94a9c4:0): checking chain actions at height=592467 2019-08-30 17:14:18.320 [DBG] CNCT: ChannelArbitrator(0bbc93b20ff29ff564b88f5e41005cddcea6de76ac5692f47cfae9f5cc94a9c4:0): new block (height=592468) examining active HTLC's 2019-08-30 17:14:18.320 [DBG] CNCT: ChannelArbitrator(0bbc93b20ff29ff564b88f5e41005cddcea6de76ac5692f47cfae9f5cc94a9c4:0): checking chain actions at height=592468 2019-08-30 17:15:06.264 [DBG] CNCT: ChannelArbitrator(0bbc93b20ff29ff564b88f5e41005cddcea6de76ac5692f47cfae9f5cc94a9c4:0): new block (height=592469) examining active HTLC's 2019-08-30 17:15:06.271 [DBG] CNCT: ChannelArbitrator(0bbc93b20ff29ff564b88f5e41005cddcea6de76ac5692f47cfae9f5cc94a9c4:0): checking chain actions at height=592469 2019-08-30 17:18:34.004 [DBG] CNCT: ChannelArbitrator(0bbc93b20ff29ff564b88f5e41005cddcea6de76ac5692f47cfae9f5cc94a9c4:0): new block (height=592470) examining active HTLC's 2019-08-30 17:18:34.005 [DBG] CNCT: ChannelArbitrator(0bbc93b20ff29ff564b88f5e41005cddcea6de76ac5692f47cfae9f5cc94a9c4:0): checking chain actions at height=592470 2019-08-30 17:26:08.268 [DBG] CNCT: ChannelArbitrator(0bbc93b20ff29ff564b88f5e41005cddcea6de76ac5692f47cfae9f5cc94a9c4:0): new block (height=592471) examining active HTLC's 2019-08-30 17:26:08.268 [DBG] CNCT: ChannelArbitrator(0bbc93b20ff29ff564b88f5e41005cddcea6de76ac5692f47cfae9f5cc94a9c4:0): checking chain actions at height=592471 2019-08-30 17:29:52.846 [DBG] CNCT: ChannelArbitrator(0bbc93b20ff29ff564b88f5e41005cddcea6de76ac5692f47cfae9f5cc94a9c4:0): new block (height=592472) examining active HTLC's 2019-08-30 17:29:52.846 [DBG] CNCT: ChannelArbitrator(0bbc93b20ff29ff564b88f5e41005cddcea6de76ac5692f47cfae9f5cc94a9c4:0): checking chain actions at height=592472 2019-08-30 17:31:50.109 [INF] PEER: NodeKey(0331f80652fb840239df8dc99205792bba2e559a05469915804c08420230e23c7c) loading ChannelPoint(0bbc93b20ff29ff564b88f5e41005cddcea6de76ac5692f47cfae9f5cc94a9c4:0) 2019-08-30 17:31:50.212 [DBG] CNCT: New ChainEventSubscription(id=2) for ChannelPoint(0bbc93b20ff29ff564b88f5e41005cddcea6de76ac5692f47cfae9f5cc94a9c4:0) 2019-08-30 17:31:50.236 [INF] HSWC: ChannelLink(0bbc93b20ff29ff564b88f5e41005cddcea6de76ac5692f47cfae9f5cc94a9c4:0) is starting 2019-08-30 17:31:50.240 [INF] CNCT: Attempting to update ContractSignals for ChannelPoint(0bbc93b20ff29ff564b88f5e41005cddcea6de76ac5692f47cfae9f5cc94a9c4:0) 2019-08-30 17:31:50.251 [INF] HSWC: HTLC manager for ChannelPoint(0bbc93b20ff29ff564b88f5e41005cddcea6de76ac5692f47cfae9f5cc94a9c4:0) started, bandwidth=0 mSAT 2019-08-30 17:31:50.251 [INF] HSWC: Attempting to re-resynchronize ChannelPoint(0bbc93b20ff29ff564b88f5e41005cddcea6de76ac5692f47cfae9f5cc94a9c4:0) 2019-08-30 17:32:25.300 [INF] HSWC: ChannelLink(0bbc93b20ff29ff564b88f5e41005cddcea6de76ac5692f47cfae9f5cc94a9c4:0) has exited 2019-08-30 17:32:25.328 [INF] HSWC: ChannelLink(0bbc93b20ff29ff564b88f5e41005cddcea6de76ac5692f47cfae9f5cc94a9c4:0) is stopping 2019-08-30 17:33:56.134 [DBG] CNCT: ChannelArbitrator(0bbc93b20ff29ff564b88f5e41005cddcea6de76ac5692f47cfae9f5cc94a9c4:0): new block (height=592473) examining active HTLC's 2019-08-30 17:33:56.135 [DBG] CNCT: ChannelArbitrator(0bbc93b20ff29ff564b88f5e41005cddcea6de76ac5692f47cfae9f5cc94a9c4:0): checking chain actions at height=592473

@stefanwouldgo
Copy link
Author

e8d2c:
2019-08-30 08:43:18.244 [DBG] CNCT: Starting ChannelArbitrator(e8d2c8a62808377520c7926ece00c925f942cdff832bca5d6c6b08695bddc180:0), htlc_set=(map[contractcourt.HtlcSetKey]contractcourt.htlcSet) <nil> 2019-08-30 08:43:18.252 [INF] CNCT: ChannelArbitrator(e8d2c8a62808377520c7926ece00c925f942cdff832bca5d6c6b08695bddc180:0): starting state=StateWaitingFullResolution 2019-08-30 08:43:18.292 [INF] CNCT: ChannelArbitrator(e8d2c8a62808377520c7926ece00c925f942cdff832bca5d6c6b08695bddc180:0): still awaiting contract resolution 2019-08-30 08:43:18.296 [INF] CNCT: ChannelArbitrator(e8d2c8a62808377520c7926ece00c925f942cdff832bca5d6c6b08695bddc180:0): relaunching 1 contract resolvers 2019-08-30 08:43:18.300 [DBG] CNCT: ChannelArbitrator(e8d2c8a62808377520c7926ece00c925f942cdff832bca5d6c6b08695bddc180:0): attempting to resolve *contractcourt.commitSweepResolver 2019-08-30 08:43:18.301 [DBG] CNCT: ChannelArbitrator(e8d2c8a62808377520c7926ece00c925f942cdff832bca5d6c6b08695bddc180:0): contract *contractcourt.commitSweepResolver not yet resolved 2019-08-30 08:43:18.303 [DBG] CNCT: *contractcourt.commitSweepResolver(e8d2c8a62808377520c7926ece00c925f942cdff832bca5d6c6b08695bddc180:0): waiting for commit tx to confirm 2019-08-30 08:44:52.518 [INF] UTXN: NurseryReport: building nursery report for channel e8d2c8a62808377520c7926ece00c925f942cdff832bca5d6c6b08695bddc180:0 2019-08-30 09:48:28.729 [ERR] CNCT: ChannelArbitrator(e8d2c8a62808377520c7926ece00c925f942cdff832bca5d6c6b08695bddc180:0): unable to progress resolver: quitting 2019-08-30 09:48:28.764 [DBG] CNCT: Stopping ChannelArbitrator(e8d2c8a62808377520c7926ece00c925f942cdff832bca5d6c6b08695bddc180:0) 2019-08-30 16:16:05.961 [DBG] CNCT: Starting ChannelArbitrator(e8d2c8a62808377520c7926ece00c925f942cdff832bca5d6c6b08695bddc180:0), htlc_set=(map[contractcourt.HtlcSetKey]contractcourt.htlcSet) <nil> 2019-08-30 16:16:05.965 [INF] CNCT: ChannelArbitrator(e8d2c8a62808377520c7926ece00c925f942cdff832bca5d6c6b08695bddc180:0): starting state=StateWaitingFullResolution 2019-08-30 16:16:06.011 [INF] CNCT: ChannelArbitrator(e8d2c8a62808377520c7926ece00c925f942cdff832bca5d6c6b08695bddc180:0): still awaiting contract resolution 2019-08-30 16:16:06.015 [INF] CNCT: ChannelArbitrator(e8d2c8a62808377520c7926ece00c925f942cdff832bca5d6c6b08695bddc180:0): relaunching 1 contract resolvers 2019-08-30 16:16:06.015 [DBG] CNCT: ChannelArbitrator(e8d2c8a62808377520c7926ece00c925f942cdff832bca5d6c6b08695bddc180:0): attempting to resolve *contractcourt.commitSweepResolver 2019-08-30 16:16:06.017 [DBG] CNCT: ChannelArbitrator(e8d2c8a62808377520c7926ece00c925f942cdff832bca5d6c6b08695bddc180:0): contract *contractcourt.commitSweepResolver not yet resolved 2019-08-30 16:16:06.027 [DBG] CNCT: *contractcourt.commitSweepResolver(e8d2c8a62808377520c7926ece00c925f942cdff832bca5d6c6b08695bddc180:0): waiting for commit tx to confirm 2019-08-30 16:16:17.596 [INF] UTXN: NurseryReport: building nursery report for channel e8d2c8a62808377520c7926ece00c925f942cdff832bca5d6c6b08695bddc180:0 2019-08-30 19:26:54.878 [INF] CNCT: *contractcourt.commitSweepResolver(e8d2c8a62808377520c7926ece00c925f942cdff832bca5d6c6b08695bddc180:0): sweeping commit output 2019-08-30 22:09:25.797 [ERR] CNCT: *contractcourt.commitSweepResolver(e8d2c8a62808377520c7926ece00c925f942cdff832bca5d6c6b08695bddc180:0): unable to sweep input: remote party swept utxo 2019-08-30 22:09:25.797 [ERR] CNCT: ChannelArbitrator(e8d2c8a62808377520c7926ece00c925f942cdff832bca5d6c6b08695bddc180:0): unable to progress resolver: remote party swept utxo 2019-08-31 08:34:38.368 [INF] UTXN: NurseryReport: building nursery report for channel e8d2c8a62808377520c7926ece00c925f942cdff832bca5d6c6b08695bddc180:0

@wpaulino
Copy link
Contributor

Sorry for the delay on this @stefanwouldgo. I looked at the logs for the waiting close channel 0bbc93b20ff29ff564b88f5e41005cddcea6de76ac5692f47cfae9f5cc94a9c4. The channel is still open on-chain, so it seems that you haven't been able to connect to your channel peer to receive a key needed to sweep your funds.

@stefanwouldgo
Copy link
Author

Sorry for the delay on this @stefanwouldgo. I looked at the logs for the waiting close channel 0bbc93b20ff29ff564b88f5e41005cddcea6de76ac5692f47cfae9f5cc94a9c4. The channel is still open on-chain, so it seems that you haven't been able to connect to your channel peer to receive a key needed to sweep your funds.

LND (0.8.2) now only seems to look for the other channel:
[ERR] CNCT: Unable to retrieve commitment point for channel(e8d2c8a62808377520c7926ece00c925f942cdff832bca5d6c6b08695bddc180:0) with lost state: no commit point found. Retrying in 10m0s., even though this seems to have been force-closed and spent multiple times onchain. It's now listed as both 'waiting close' and 'pending force close'.

The remaining open channel hasn't been mentioned in the logs for some time, but is still listed as waiting close. IIUC, there is no way to close this channel without cooperation from the channel partner, which doesn't seem to happen.

However, I don't understand the case of the force-closed channel. Why has it been respent so many times and shouldn't LND know the private keys for that?

@wpaulino
Copy link
Contributor

[ERR] CNCT: Unable to retrieve commitment point for channel(e8d2c8a62808377520c7926ece00c925f942cdff832bca5d6c6b08695bddc180:0) with lost state: no commit point found. Retrying in 10m0s.

You're seeing this error because you haven't been able to connect to the peer since you launched the latest recovery attempt, but looking at the channel on-chain, it has been closed and the funds have went into a different channel that you likely opened. This means it was probably swept in one of your previous recovery attempts where you were able to connect to the peer.

@stefanwouldgo
Copy link
Author

stefanwouldgo commented Feb 25, 2020 via email

@Roasbeef
Copy link
Member

Roasbeef commented May 5, 2020

I think this can be closed?

@stefanwouldgo
Copy link
Author

I think this can be closed?

I don't think so. I have just updated my LND to 0.10, and both channels are still pending. One pending close - I think that can probably not be resolved without the data from the other side. But another one pending force close (!) - I really think this is an unresolved bug in LND.

@Roasbeef Roasbeef added this to the 0.12.0 milestone Jul 22, 2020
@Roasbeef Roasbeef added the v0.12 label Jul 22, 2020
@Roasbeef Roasbeef added this to To do in v0.12.0-beta Jul 22, 2020
@guggero
Copy link
Collaborator

guggero commented Aug 12, 2020

I finally got to take a look at this.

There seem to be multiple problems:

  1. lnd crashed when restoring the channel backup: I think that was already resolved with chanbackup: continue recovery if channel already exists #3737 in 0.8.2. As the node with the crash was running 0.6.1 and later 0.7.0 that would explain the crashes in my eyes.
  2. A channel restored from channel backup (e8d2c8a62808377520c7926ece00c925f942cdff832bca5d6c6b08695bddc180) can manually be force closed which brings the state machine in a state that it cannot recover from. This is likely a bug and I'm trying to reproduce and then fix that.
  3. The second channel that is still open on chain (0bbc93b20ff29ff564b88f5e41005cddcea6de76ac5692f47cfae9f5cc94a9c4) that cannot be closed. Recovering with SCB requires the cooperation of the other peer. Maybe it's as simple as finding the peer and trying to manually connect to it. I'll contact you over another channel to try to resolve this.

To address point 2, I did a few tests:

  1. Try restoring an SCB with some channels that are already fully resolved: Success, needs a chain rescan but fully resolves all channels after a while. No action needed here.
  2. Try restoring an SCB and while the channel is being resolved, manually force close. If the remote peer isn't online to advance the channel into the StatusLocalDataLoss state, then lnd crashes when trying to publish the commitment TX (as it doesn't have it). --> Needs a fix and I'm working on it. Channels restored from SCB should not be allowed to be closed manually.

@guggero guggero changed the title Recognize previously restored channels Don't allow manual close of restored channels Aug 12, 2020
v0.12.0-beta automation moved this from To do to Done Aug 13, 2020
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
backups channels P3 might get fixed, nice to have recovery Related to the backup/restoration of LND data (e.g. wallet seeds) safety General label for issues/PRs related to the safety of using the software SCB Related to static channel backup v0.12
Projects
No open projects
v0.12.0-beta
  
Done
5 participants