Force-closed channel balance not returned to wallet

[mkke]

Background

A channel I opened was force-closed by remote end (on 2018-04-11), but the balance hasn't yet returned to the wallet. Funding txid is a47291f7a68adfdb6c58c81d4a7c4f9772159c1814c9f0769f16601a9e07fcc7:

    {
        "tx_hash": "a47291f7a68adfdb6c58c81d4a7c4f9772159c1814c9f0769f16601a9e07fcc7",
        "amount": "-2763952",
        "num_confirmations": 2714,
        "block_hash": "000000000000000000048a7fc0e4cc81f4f96379364d05a2d613549c05f25af1",
        "block_height": 517441,
        "time_stamp": "1523314110",
        "total_fees": "1377",
        "dest_addresses": [
            "bc1qt6khw0xtlkl4kwyzhz9ufur9n9zqef66ls92sm",
            "bc1qnlcv99v5kr55w0a9ycdha58spgctldxtzsutp7hvp2xvn2gdnjdqkgafd3"
        ]
    },

Last log entries are:

[INF] NTFN: Dispatching spend notification for outpoint=a47291f7a68adfdb6c58c81d4a7c4f9772159c1814c9f0769f16601a9e07fcc7:1
[WRN] CNCT: Unprompted commitment broadcast for ChannelPoint(a47291f7a68adfdb6c58c81d4a7c4f9772159c1814c9f0769f16601a9e07fcc7:1) 
[INF] CNCT: Unilateral close of ChannelPoint(a47291f7a68adfdb6c58c81d4a7c4f9772159c1814c9f0769f16601a9e07fcc7:1) detected
[WRN] HSWC: Remote peer has closed ChannelPoint(a47291f7a68adfdb6c58c81d4a7c4f9772159c1814c9f0769f16601a9e07fcc7:1) on-chain
[INF] HSWC: ChannelLink(a47291f7a68adfdb6c58c81d4a7c4f9772159c1814c9f0769f16601a9e07fcc7:1) has exited
[INF] CNCT: ChannelArbitrator(a47291f7a68adfdb6c58c81d4a7c4f9772159c1814c9f0769f16601a9e07fcc7:1): remote party has closed channel out on-chain
[INF] CNCT: ChannelArbitrator(a47291f7a68adfdb6c58c81d4a7c4f9772159c1814c9f0769f16601a9e07fcc7:1): contract resolutions empty, exiting
[INF] CNCT: Marking ChannelPoint(a47291f7a68adfdb6c58c81d4a7c4f9772159c1814c9f0769f16601a9e07fcc7:1) fully resolved
[INF] PEER: ChannelPoint(a47291f7a68adfdb6c58c81d4a7c4f9772159c1814c9f0769f16601a9e07fcc7:1) has been breached, wiping channel
[INF] HSWC: ChannelLink(a47291f7a68adfdb6c58c81d4a7c4f9772159c1814c9f0769f16601a9e07fcc7:1) is stopping

I tried the new wallet recovery procedure, but it wasn't picked up.

Your environment

• Linux bitcoin 4.9.0-5-amd64 Fix name typo in README #1 SMP Debian 4.9.65-3+deb9u2 (2018-01-04) x86_64 GNU/Linux
• bitcoin-0.16.0-x86_64-linux

Channel was created with lnd Version 0.4.1-beta commit=13945de8060ad42e077988c1cf69e205dc11e528.

Steps to reproduce

Lnd was restarted while the funding was running.

Expected behaviour

Balance returned to wallet.

Actual behaviour

Channel disappears from channel list, but balance not returned.

I'm attaching log entries containing the txid:
a47291f7a68adfdb6c58c81d4a7c4f9772159c1814c9f0769f16601a9e07fcc7.log

[Roasbeef]

[INF] HSWC: ChannelLink(a47291f7a68adfdb6c58c81d4a7c4f9772159c1814c9f0769f16601a9e07fcc7:1) has exited
[INF] CNCT: ChannelArbitrator(a47291f7a68adfdb6c58c81d4a7c4f9772159c1814c9f0769f16601a9e07fcc7:1): remote party has closed channel out on-chain
[INF] CNCT: ChannelArbitrator(a47291f7a68adfdb6c58c81d4a7c4f9772159c1814c9f0769f16601a9e07fcc7:1): contract resolutions empty, exiting
[INF] CNCT: Marking ChannelPoint(a47291f7a68adfdb6c58c81d4a7c4f9772159c1814c9f0769f16601a9e07fcc7:1) fully resolved

Looking at those logs, and the the transaction on-chain the remote party broadcast the commitment transaction. Since they broadcast the transaction there's no time-lock required, and the funds are available immediately.

[Roasbeef]

Do you have any further logs of any of the last updates to the commitment transaction? It appears you were connected to a c-lightning node. They'll force close channels if they don't like fees we offer. It's a bit of an epidemic on mainnet atm, as it results in a ton of unnecessary force closes.

The odd thing here is that the commitment clearly pays out to you, but lnd didn't detect that output as paying to us.

[Roasbeef]

Do you have logs of the initial funding of the channel?

[mkke]

Here is the funding and the last updates before the channel was closed.

a47291f7a68adfdb6c58c81d4a7c4f9772159c1814c9f0769f16601a9e07fcc7.funding.log
a47291f7a68adfdb6c58c81d4a7c4f9772159c1814c9f0769f16601a9e07fcc7.final.log

[mkke]

I've tried the wallet recovery again with this change included (commit bdf3f4d), but the close isn't picked up (should be in block 517626):

2018-05-05 01:18:26.954 [INF] LNWL: Seed birthday surpassed, starting recovery of wallet from height=511999 hash=0000000000000000003b4861760c37c3c74b53a5e7c9af0db8dae84e1f43e565 with recovery-window=250
2018-05-05 01:18:27.023 [INF] LNWL: Scanning 2 blocks for recoverable addresses
2018-05-05 01:18:44.306 [INF] LNWL: Scanning 2000 blocks for recoverable addresses
2018-05-05 01:32:28.335 [INF] LNWL: Recovered 1 external addrs at height=513678 hash=0000000000000000001e98bf0e2e29284932200cd0ee37ad0104b896de4f6d0c
2018-05-05 01:32:28.336 [INF] LNWL: Found 1 spends from watched outpoints at height=513678 hash=0000000000000000001e98bf0e2e29284932200cd0ee37ad0104b896de4f6d0c
2018-05-05 01:32:28.813 [INF] LNWL: Recovered 1 internal addrs at height=513679 hash=0000000000000000002a16d88f6b61b035f188b4b30a151c83dff3b1844eeb4d
2018-05-05 01:32:28.813 [INF] LNWL: Found 1 spends from watched outpoints at height=513679 hash=0000000000000000002a16d88f6b61b035f188b4b30a151c83dff3b1844eeb4d
2018-05-05 01:33:32.720 [INF] LNWL: Recovered 1 internal addrs at height=513927 hash=00000000000000000010633704a0ef5b8820b39ce826a0f38845b2e99860d803
2018-05-05 01:33:32.720 [INF] LNWL: Found 1 spends from watched outpoints at height=513927 hash=00000000000000000010633704a0ef5b8820b39ce826a0f38845b2e99860d803
2018-05-05 01:33:35.476 [INF] LNWL: Recovered 1 internal addrs at height=513938 hash=0000000000000000001d6d210457bd60dcc4ec5c77b3d46f8fba1315cb1c0d89
2018-05-05 01:33:35.479 [INF] LNWL: Found 1 spends from watched outpoints at height=513938 hash=0000000000000000001d6d210457bd60dcc4ec5c77b3d46f8fba1315cb1c0d89
2018-05-05 01:34:11.445 [INF] LNWL: Scanning 2000 blocks for recoverable addresses
2018-05-05 01:35:36.925 [INF] LNWL: Recovered 1 external addrs at height=514260 hash=0000000000000000004f96b552d6a6bc923a5a930003cbb2e2538b1b9d722f43
2018-05-05 01:35:36.925 [INF] LNWL: Found 1 spends from watched outpoints at height=514260 hash=0000000000000000004f96b552d6a6bc923a5a930003cbb2e2538b1b9d722f43
2018-05-05 01:36:05.464 [INF] LNWL: Recovered 1 external addrs at height=514358 hash=000000000000000000368a61df3d7f13f8d4e092dd0fe36d3ab98d3908ffaf97
2018-05-05 01:36:05.464 [INF] LNWL: Found 1 spends from watched outpoints at height=514358 hash=000000000000000000368a61df3d7f13f8d4e092dd0fe36d3ab98d3908ffaf97
2018-05-05 01:36:27.773 [INF] LNWL: Recovered 1 external addrs at height=514416 hash=0000000000000000002d48a65f9562fb94c156dc96443ec04b51dff8fc84e31e
2018-05-05 01:36:27.774 [INF] LNWL: Found 1 spends from watched outpoints at height=514416 hash=0000000000000000002d48a65f9562fb94c156dc96443ec04b51dff8fc84e31e
2018-05-05 01:36:35.548 [INF] LNWL: Recovered 1 internal addrs at height=514439 hash=0000000000000000002c08e17fcf61b6ce0f1ea22ec8d9c2284264de45c570c9
2018-05-05 01:36:35.548 [INF] LNWL: Found 1 spends from watched outpoints at height=514439 hash=0000000000000000002c08e17fcf61b6ce0f1ea22ec8d9c2284264de45c570c9
2018-05-05 01:39:28.889 [INF] LNWL: Recovered 1 external addrs at height=514907 hash=000000000000000000125a7638c0078ce8bde0df34569cb64fd879ee59d4d579
2018-05-05 01:39:28.897 [INF] LNWL: Found 1 spends from watched outpoints at height=514907 hash=000000000000000000125a7638c0078ce8bde0df34569cb64fd879ee59d4d579
2018-05-05 01:47:04.781 [INF] LNWL: Scanning 2000 blocks for recoverable addresses
2018-05-05 01:48:18.305 [INF] LNWL: Recovered 1 external addrs at height=516268 hash=0000000000000000000138854c76fae73c6d35899612339c35e66352d4e7dcf9
2018-05-05 01:48:18.375 [INF] LNWL: Found 1 spends from watched outpoints at height=516268 hash=0000000000000000000138854c76fae73c6d35899612339c35e66352d4e7dcf9
2018-05-05 01:54:39.494 [INF] LNWL: Recovered 3 internal addrs at height=517441 hash=000000000000000000048a7fc0e4cc81f4f96379364d05a2d613549c05f25af1
2018-05-05 01:54:39.495 [INF] LNWL: Found 3 spends from watched outpoints at height=517441 hash=000000000000000000048a7fc0e4cc81f4f96379364d05a2d613549c05f25af1
2018-05-05 01:57:58.774 [INF] LNWL: Scanning 2000 blocks for recoverable addresses
2018-05-05 01:58:15.528 [INF] LNWL: Recovered 1 internal addrs at height=518037 hash=000000000000000000328b6adf68011262b580e5eeb4cee514f7c14d35f992b0
2018-05-05 01:58:15.528 [INF] LNWL: Found 1 spends from watched outpoints at height=518037 hash=000000000000000000328b6adf68011262b580e5eeb4cee514f7c14d35f992b0
2018-05-05 02:05:21.819 [INF] LNWL: Recovered 3 external addrs at height=518986 hash=000000000000000000096f1f7ffadf6c6659e2d19e560620a9fa239eed24e709
2018-05-05 02:05:21.843 [INF] LNWL: Found 3 spends from watched outpoints at height=518986 hash=000000000000000000096f1f7ffadf6c6659e2d19e560620a9fa239eed24e709
2018-05-05 02:05:22.870 [INF] LNWL: Recovered 1 external addrs at height=518988 hash=0000000000000000000653230d186c55b8f8f7e9b443790daf5a9f04494b8560
2018-05-05 02:05:22.876 [INF] LNWL: Found 1 spends from watched outpoints at height=518988 hash=0000000000000000000653230d186c55b8f8f7e9b443790daf5a9f04494b8560
2018-05-05 02:12:04.352 [INF] LNWL: Caught up to height 520000
2018-05-05 02:12:15.848 [INF] LNWL: Scanning 1230 blocks for recoverable addresses
2018-05-05 02:22:10.177 [INF] LNWL: Done catching up block hashes
2018-05-05 02:22:10.911 [INF] LNWL: Started rescan from block 0000000000000000001495150694180deeddb27b2e85327deb4f6e1597eb6467 (height 521230) for 43 addresses
2018-05-05 02:22:11.050 [INF] LNWL: Starting rescan from block 0000000000000000001495150694180deeddb27b2e85327deb4f6e1597eb6467
2018-05-05 02:22:15.321 [INF] LNWL: Rescan finished at 521237 (0000000000000000003c9b392176e322549d1cf529da6aeb9893f2b3e8ce5f87)
2018-05-05 02:22:17.565 [INF] LNWL: Catching up block hashes to height 521237, this might take a while
2018-05-05 02:22:17.712 [INF] LNWL: Done catching up block hashes
2018-05-05 02:22:17.712 [INF] LNWL: Finished rescan for 43 addresses (synced to block 0000000000000000003c9b392176e322549d1cf529da6aeb9893f2b3e8ce5f87, height 521237)

[Roasbeef]

The close was to a special output type that isn't strictly just creating an output under the sole control of the wallet. As a result, it won't be picked up doing a regular seed rescan. The underlying issue that led to this output being forgotten on chain has been fixed in the latest master, and will soon be bundled in the upcoming 0.4.2 release.

[mkke]

I've retried the wallet recovery with the new release 0.4.2-beta commit=7cf5ebe2650b6798182e10be198c7ffc1f1d6e19, but it is still not picked up.