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.

Sign up for GitHub

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

Jump to bottom

Channel Waiting Close with transaction not broadcast and cannot force close #5552

Closed
raymondclowe opened this issue Jul 22, 2021 · 3 comments
Closed

Channel Waiting Close with transaction not broadcast and cannot force close #5552

raymondclowe opened this issue Jul 22, 2021 · 3 comments

Comments

@raymondclowe
Copy link

Background

This is similar, perhaps identical, to issue #5341 . If I should talk about it there instead please let me know.

I am trying to close a channel and unable to do so. I used the web interface RTL to try to close it, and it is now in the Wait Closing Channel state but has been for many hours.

When I open up the "Wait Closing Channel Information" it shows me a transaction ID, but this transaction is not visible in mempool.space and not visible in my local mempool.

I've been in similar situations before because the two nodes I have set up never seem to work. Therefore I have experience opening, closing, force closing channels.

But in the previous cases I could force close using the channel point to get another transaction broadcast, but this time it doesn't work so I'm stuck.

Your environment

  • lnd version 0.13.0-beta commit=v0.13.0-beta
  • Microsoft Windows [Version 10.0.19043.1110]
  • Bitcoin Core RPC client version v0.21.1

Here are all the pending channels; the problematic one is the one with node 03858f3b77447b572733e6e888cbbf36b8bc8483bb9716041953bb284495655522

lnd\lncli pendingchannels
{
    "total_limbo_balance": "19251",
    "pending_open_channels": [
    ],
    "pending_closing_channels": [
    ],
    "pending_force_closing_channels": [
        {
            "channel": {
                "remote_node_pub": "035e4ff418fc8b5554c5d9eea66396c227bd429a3251c8cbc711002ba215bfc226",
                "channel_point": "a0738545c608cb8914b3d9e88b99a4ffa50e1320e4cc9c84bc5280a6c6ff10ec:0",
                "capacity": "20000",
                "local_balance": "19251",
                "remote_balance": "0",
                "local_chan_reserve_sat": "0",
                "remote_chan_reserve_sat": "0",
                "initiator": "INITIATOR_LOCAL",
                "commitment_type": "STATIC_REMOTE_KEY"
            },
            "closing_txid": "265e0ace57ff389b87b7a72cca1e2306fd5c5498747f15d65514229841dedf81",
            "limbo_balance": "19251",
            "maturity_height": 692225,
            "blocks_til_maturity": 139,
            "recovered_balance": "0",
            "pending_htlcs": [
            ],
            "anchor": "LIMBO"
        }
    ],
    "waiting_close_channels": [
        {
            "channel": {
                "remote_node_pub": "03858f3b77447b572733e6e888cbbf36b8bc8483bb9716041953bb284495655522",
                "channel_point": "ca62dbe5454b5f13ad7228e8bafeb297096de6ee6cfbd2e1a8208d292065c972:1",
                "capacity": "20000",
                "local_balance": "0",
                "remote_balance": "19401",
                "local_chan_reserve_sat": "573",
                "remote_chan_reserve_sat": "573",
                "initiator": "INITIATOR_REMOTE",
                "commitment_type": "STATIC_REMOTE_KEY"
            },
            "limbo_balance": "0",
            "commitments": {
                "local_txid": "4797a8f2ddeab9c459fce84502ea6a610bbd128243a9148812486ee16adac5ec",
                "remote_txid": "39385b480d12e62f202072864549b866233124b601273352b46de56188e4ab53",
                "remote_pending_txid": "",
                "local_commit_fee_sat": "599",
                "remote_commit_fee_sat": "599",
                "remote_pending_commit_fee_sat": "0"
            }
        }
    ]
}

I have already reached out to the operator of that node, advised him of the situation, and suggested he force close from his end. If that works then this is academic from my perspective, but perhaps useful data to see a stuck case??

The problematic channel mentioned above has two transactions mentioned;

"4797a8f2ddeab9c459fce84502ea6a610bbd128243a9148812486ee16adac5ec",
                "remote_txid": "39385b480d12e62f202072864549b866233124b601273352b46de56188e4ab53"

I can't see these in mempool.space. I also can't see the local one in the local mempool.

bitcoin-cli.exe" getmempoolentry 4797a8f2ddeab9c459fce84502ea6a610bbd128243a9148812486ee16adac5ec
error code: -5
error message:
Transaction not in mempool

Steps to reproduce

lnd\lncli closechannel ca62dbe5454b5f13ad7228e8bafeb297096de6ee6cfbd2e1a8208d292065c972 1 --force

Expected behaviour

After doing lncli closechannel it should reply almost immediately with the tx id of a new transactioni

Actual behaviour

I try to force close but after 8 hours nothing has happened so I press ctrl-C and it looks like this:

lnd\lncli closechannel ca62dbe5454b5f13ad7228e8bafeb297096de6ee6cfbd2e1a8208d292065c972 1 --force
[lncli] rpc error: code = Canceled desc = context canceled
@Roasbeef
Copy link
Member

What do you see in the logs while attempting to force close (possibly grepping for the outpoint TXID)?

@raymondclowe
Copy link
Author

raymondclowe commented Jul 22, 2021 •
edited

The channel finally closed, I don't know why. Therefore the problem is 'solved'.

I did search at the logs and cannot see anything in them about the closing TX until the point at which it was successful a few hours ago, at which point it all looks normal.

There is no trace of the failed attempt to force close, at least not including the TX ID.

As it is already closed I can't try again to repro the issue of the close command not responding.

log of the eventual successful force close, with a couple of minutes either side, is included below.

I'll keep the logs for reference by otherwise this node I'll be disconnecting as it never worked right.

Thank you for your time. I presume this issue can be closed now.


2021-07-22 13:53:08.973 [WRN] BTCN: Query(928) from peer 46.4.89.121:8333 failed, rescheduling: did not get response before timeout
2021-07-22 13:53:08.973 [WRN] BTCN: Query(928) failed with error: did not get response before timeout. Timing out.
2021-07-22 13:53:08.974 [INF] CRTR: Processed channels=1 updates=0 nodes=0 in last 8m51.7183261s
2021-07-22 13:53:12.987 [WRN] BTCN: Query(928) from peer 46.4.89.121:8333 failed, rescheduling: did not get response before timeout
2021-07-22 13:53:20.998 [WRN] BTCN: Query(928) from peer 46.4.89.121:8333 failed, rescheduling: did not get response before timeout
2021-07-22 13:53:22.715 [INF] WTCL: (legacy) Client stats: tasks(received=0 accepted=0 ineligible=0) sessions(acquired=0 exhausted=0)
2021-07-22 13:53:22.715 [INF] WTCL: (anchor) Client stats: tasks(received=0 accepted=0 ineligible=0) sessions(acquired=0 exhausted=0)
2021-07-22 13:53:37.003 [WRN] BTCN: Query(928) from peer 46.4.89.121:8333 failed, rescheduling: did not get response before timeout
2021-07-22 13:53:44.005 [WRN] BTCN: Query(929) from peer 46.4.89.121:8333 failed, rescheduling: did not get response before timeout
2021-07-22 13:53:44.005 [WRN] BTCN: Query(929) failed with error: did not get response before timeout. Timing out.
2021-07-22 13:53:48.012 [WRN] BTCN: Query(929) from peer 46.4.89.121:8333 failed, rescheduling: did not get response before timeout
2021-07-22 13:53:56.026 [WRN] BTCN: Query(929) from peer 46.4.89.121:8333 failed, rescheduling: did not get response before timeout
2021-07-22 13:54:12.032 [WRN] BTCN: Query(929) from peer 46.4.89.121:8333 failed, rescheduling: did not get response before timeout
2021-07-22 13:54:14.699 [WRN] BTCN: Query(930) from peer 46.4.89.121:8333 failed, rescheduling: did not get response before timeout
2021-07-22 13:54:14.699 [WRN] BTCN: Query(930) failed with error: did not get response before timeout. Timing out.
2021-07-22 13:54:18.713 [WRN] BTCN: Query(930) from peer 46.4.89.121:8333 failed, rescheduling: did not get response before timeout
2021-07-22 13:54:22.721 [INF] WTCL: (anchor) Client stats: tasks(received=0 accepted=0 ineligible=0) sessions(acquired=0 exhausted=0)
2021-07-22 13:54:22.721 [INF] WTCL: (legacy) Client stats: tasks(received=0 accepted=0 ineligible=0) sessions(acquired=0 exhausted=0)
2021-07-22 13:54:26.730 [WRN] BTCN: Query(930) from peer 46.4.89.121:8333 failed, rescheduling: did not get response before timeout
2021-07-22 13:54:40.830 [INF] CRTR: Processed channels=2 updates=0 nodes=0 in last 1m31.8563685s
2021-07-22 13:54:42.313 [WRN] BTCN: Query(931) from peer 46.4.89.121:8333 failed, rescheduling: did not get response before timeout
2021-07-22 13:54:42.313 [WRN] BTCN: Query(931) failed with error: did not get response before timeout. Timing out.
2021-07-22 13:54:46.324 [WRN] BTCN: Query(931) from peer 46.4.89.121:8333 failed, rescheduling: did not get response before timeout
2021-07-22 13:54:54.326 [WRN] BTCN: Query(931) from peer 46.4.89.121:8333 failed, rescheduling: did not get response before timeout
2021-07-22 13:55:04.517 [INF] CRTR: Processed channels=1 updates=1 nodes=0 in last 23.6858219s
2021-07-22 13:55:04.540 [WRN] CNCT: Unable to disable channel a0738545c608cb8914b3d9e88b99a4ffa50e1320e4cc9c84bc5280a6c6ff10ec:0 on close: edge not found
2021-07-22 13:55:04.540 [ERR] RPCS: unable to force close transaction: channel is already in the process of being force closed
2021-07-22 13:55:04.541 [ERR] RPCS: [/lnrpc.Lightning/CloseChannel]: channel is already in the process of being force closed
2021-07-22 13:55:04.567 [INF] CNCT: ChannelArbitrator(ca62dbe5454b5f13ad7228e8bafeb297096de6ee6cfbd2e1a8208d292065c972:1): force closing chan
2021-07-22 13:55:04.571 [INF] HSWC: Removing channel link with ChannelID(72c96520298d20a8e1d2fb6ceee66d0997b2febae82872ad135f4b45e5db62cb)
2021-07-22 13:55:04.585 [INF] CNCT: Broadcasting force close transaction 4797a8f2ddeab9c459fce84502ea6a610bbd128243a9148812486ee16adac5ec, ChannelPoint(ca62dbe5454b5f13ad7228e8bafeb297096de6ee6cfbd2e1a8208d292065c972:1): (*wire.MsgTx)(0x17217c40)({
 Version: (int32) 2,
 TxIn: ([]*wire.TxIn) (len=1 cap=1) {
  (*wire.TxIn)(0x17e2f480)({
   PreviousOutPoint: (wire.OutPoint) ca62dbe5454b5f13ad7228e8bafeb297096de6ee6cfbd2e1a8208d292065c972:1,
   SignatureScript: ([]uint8) <nil>,
   Witness: (wire.TxWitness) (len=4 cap=4) {
    ([]uint8) <nil>,
    ([]uint8) (len=72 cap=144) {
     00000000  30 45 02 21 00 e7 95 c0  ff 9a 85 61 f2 59 39 3c  |0E.!.......a.Y9<|
     00000010  1d 84 55 5b b8 65 60 49  ac 9b a2 e3 f7 e9 1d a7  |..U[.e`I........|
     00000020  b5 b9 74 7f 82 02 20 37  15 71 dc 45 be 71 67 4b  |..t... 7.q.E.qgK|
     00000030  a1 05 24 60 cd 9d d5 d8  bc cf 44 55 b5 46 8f cc  |..$`......DU.F..|
     00000040  ea 1f be 76 b2 67 0c 01                           |...v.g..|
    },
    ([]uint8) (len=71 cap=144) {
     00000000  30 44 02 20 24 65 08 c3  f4 fd 3d ee 66 c3 cd 55  |0D. $e....=.f..U|
     00000010  a0 be bf 1d aa ef c2 b1  6c cc 6c 18 ce 8b 9d b7  |........l.l.....|
     00000020  cb 5a eb 2a 02 20 16 dc  49 d2 8f 7a 14 b4 e2 87  |.Z.*. ..I..z....|
     00000030  9b 83 97 e0 9b 01 0c 3b  6f 09 be dc 1f 96 ad c9  |.......;o.......|
     00000040  33 e1 bc bd c8 10 01                              |3......|
    },
    ([]uint8) (len=71 cap=500) {
     00000000  52 21 02 88 f2 f0 0c 2d  ff b0 34 cf 81 be 16 6e  |R!.....-..4....n|
     00000010  a1 ca 0a 57 48 24 93 01  80 ee a6 2d ad 6e 28 9e  |...WH$.....-.n(.|
     00000020  16 82 11 21 03 8e 06 90  48 93 76 85 16 c3 c0 55  |...!....H.v....U|
     00000030  10 a8 a8 59 9f 14 2d 70  7a 47 c5 ea 16 d6 e3 ce  |...Y..-pzG......|
     00000040  4e 7a eb 41 f2 52 ae                              |Nz.A.R.|
    }
   },
   Sequence: (uint32) 2161559150
  })
 },
 TxOut: ([]*wire.TxOut) (len=1 cap=1) {
  (*wire.TxOut)(0x19862978)({
   Value: (int64) 19401,
   PkScript: ([]uint8) (len=22 cap=22) {
    00000000  00 14 e1 ab 13 56 9e 83  a2 bb 7b 4b 62 51 3d 8a  |.....V....{KbQ=.|
    00000010  0d c2 f8 5b c5 a0                                 |...[..|
   }
  })
 },
 LockTime: (uint32) 543292726
})

2021-07-22 13:55:04.589 [INF] LNWL: Inserting unconfirmed transaction 4797a8f2ddeab9c459fce84502ea6a610bbd128243a9148812486ee16adac5ec
2021-07-22 13:55:04.621 [INF] CNCT: ChannelArbitrator(ca62dbe5454b5f13ad7228e8bafeb297096de6ee6cfbd2e1a8208d292065c972:1): trigger userTrigger moving from state StateCommitmentBroadcasted to StateCommitmentBroadcasted
2021-07-22 13:55:04.622 [ERR] RPCS: unable to force close transaction: channel is already in the process of being force closed
2021-07-22 13:55:04.622 [ERR] RPCS: [/lnrpc.Lightning/CloseChannel]: channel is already in the process of being force closed
2021-07-22 13:55:04.622 [INF] PEER: Waiting for confirmation of cooperative close of ChannelPoint(ca62dbe5454b5f13ad7228e8bafeb297096de6ee6cfbd2e1a8208d292065c972:1) with txid: 4797a8f2ddeab9c459fce84502ea6a610bbd128243a9148812486ee16adac5ec
2021-07-22 13:55:04.622 [INF] NTFN: New confirmation subscription: conf_id=5, txid=4797a8f2ddeab9c459fce84502ea6a610bbd128243a9148812486ee16adac5ec, num_confs=1 height_hint=692022
2021-07-22 13:55:04.622 [ERR] RPCS: [/lnrpc.Lightning/CloseChannel]: rpc error: code = Internal desc = transport: transport: the stream is done or WriteHeader was already called
2021-07-22 13:55:05.990 [WRN] BTCN: Query(932) from peer 46.4.89.121:8333 failed, rescheduling: did not get response before timeout
2021-07-22 13:55:05.990 [WRN] BTCN: Query(932) failed with error: did not get response before timeout. Timing out.
2021-07-22 13:55:10.007 [WRN] BTCN: Query(932) from peer 46.4.89.121:8333 failed, rescheduling: did not get response before timeout
2021-07-22 13:55:17.596 [INF] NTFN: New block: height=692112, sha=0000000000000000000c4d06c0574664d66862964bc20c7a86d98dad3511c62d
2021-07-22 13:55:17.597 [INF] UTXN: Attempting to graduate height=692112: num_kids=0, num_babies=0
2021-07-22 13:55:18.016 [WRN] BTCN: Query(932) from peer 46.4.89.121:8333 failed, rescheduling: did not get response before timeout
2021-07-22 13:55:22.713 [INF] WTCL: (legacy) Client stats: tasks(received=0 accepted=0 ineligible=0) sessions(acquired=0 exhausted=0)
2021-07-22 13:55:22.713 [INF] WTCL: (anchor) Client stats: tasks(received=0 accepted=0 ineligible=0) sessions(acquired=0 exhausted=0)
2021-07-22 13:55:28.053 [WRN] BTCN: Query(933) from peer 46.4.89.121:8333 failed, rescheduling: did not get response before timeout
2021-07-22 13:55:28.053 [WRN] BTCN: Query(933) failed with error: did not get response before timeout. Timing out.
2021-07-22 13:55:28.053 [INF] CRTR: Pruning channel graph using block 0000000000000000000c4d06c0574664d66862964bc20c7a86d98dad3511c62d (height=692112)
2021-07-22 13:55:28.065 [INF] CRTR: Block 0000000000000000000c4d06c0574664d66862964bc20c7a86d98dad3511c62d (height=692112) closed 0 channels
2021-07-22 13:55:32.060 [WRN] BTCN: Query(933) from peer 46.4.89.121:8333 failed, rescheduling: did not get response before timeout
2021-07-22 13:55:40.078 [WRN] BTCN: Query(933) from peer 46.4.89.121:8333 failed, rescheduling: did not get response before timeout
2021-07-22 13:55:50.558 [WRN] BTCN: Query(934) from peer 46.4.89.121:8333 failed, rescheduling: did not get response before timeout
2021-07-22 13:55:50.558 [WRN] BTCN: Query(934) failed with error: did not get response before timeout. Timing out.
2021-07-22 13:55:54.576 [WRN] BTCN: Query(934) from peer 46.4.89.121:8333 failed, rescheduling: did not get response before timeout
2021-07-22 13:56:02.579 [WRN] BTCN: Query(934) from peer 46.4.89.121:8333 failed, rescheduling: did not get response before timeout
2021-07-22 13:56:16.811 [WRN] BTCN: Query(935) from peer 46.4.89.121:8333 failed, rescheduling: did not get response before timeout
2021-07-22 13:56:16.812 [WRN] BTCN: Query(935) failed with error: did not get response before timeout. Timing out.
2021-07-22 13:56:20.820 [WRN] BTCN: Query(935) from peer 46.4.89.121:8333 failed, rescheduling: did not get response before timeout
2021-07-22 13:56:22.725 [INF] WTCL: (anchor) Client stats: tasks(received=0 accepted=0 ineligible=0) sessions(acquired=0 exhausted=0)
2021-07-22 13:56:22.725 [INF] WTCL: (legacy) Client stats: tasks(received=0 accepted=0 ineligible=0) sessions(acquired=0 exhausted=0)
2021-07-22 13:56:28.835 [WRN] BTCN: Query(935) from peer 46.4.89.121:8333 failed, rescheduling: did not get response before timeout
2021-07-22 13:56:41.290 [INF] NTFN: New block: height=692113, sha=000000000000000000091daa74693f4fe0c643babbc8c4560e938d865816f2c7
2021-07-22 13:56:41.291 [INF] NTFN: Dispatching 1 confirmation notification for txid=4797a8f2ddeab9c459fce84502ea6a610bbd128243a9148812486ee16adac5ec
2021-07-22 13:56:41.291 [INF] UTXN: Attempting to graduate height=692113: num_kids=0, num_babies=0
2021-07-22 13:56:41.292 [INF] NTFN: Dispatching confirmed spend notification for outpoint=ca62dbe5454b5f13ad7228e8bafeb297096de6ee6cfbd2e1a8208d292065c972:1, script=0 9e74c413d69da1f157d2183ddd9c80ab6c71e2b92102cb72e1237a047d98de9b at current height=692113: 4797a8f2ddeab9c459fce84502ea6a610bbd128243a9148812486ee16adac5ec[0] spending ca62dbe5454b5f13ad7228e8bafeb297096de6ee6cfbd2e1a8208d292065c972:1 at height=692113
2021-07-22 13:56:41.292 [INF] PEER: ChannelPoint(ca62dbe5454b5f13ad7228e8bafeb297096de6ee6cfbd2e1a8208d292065c972:1) is now closed at height 692113
2021-07-22 13:56:41.293 [INF] CNCT: Local unilateral close of ChannelPoint(ca62dbe5454b5f13ad7228e8bafeb297096de6ee6cfbd2e1a8208d292065c972:1) detected
2021-07-22 13:56:41.294 [INF] CNCT: ChannelArbitrator(ca62dbe5454b5f13ad7228e8bafeb297096de6ee6cfbd2e1a8208d292065c972:1): local on-chain channel close
2021-07-22 13:56:41.391 [INF] CNCT: ChannelArbitrator(ca62dbe5454b5f13ad7228e8bafeb297096de6ee6cfbd2e1a8208d292065c972:1): trigger localCloseTrigger moving from state StateCommitmentBroadcasted to StateContractClosed
2021-07-22 13:56:41.391 [INF] CHBU: Updating on-disk multi SCB backup: num_old_chans=1, num_new_chans=0
2021-07-22 13:56:41.391 [WRN] CHFT: could not remove channel: channel: ca62dbe5454b5f13ad7228e8bafeb297096de6ee6cfbd2e1a8208d292065c972:1 not present
2021-07-22 13:56:41.397 [INF] CHBU: Updating backup file at C:\Users\raymo\AppData\Local\Lnd\data\chain\bitcoin\mainnet\channel.backup
2021-07-22 13:56:41.400 [INF] CHBU: Swapping old multi backup file from C:\Users\raymo\AppData\Local\Lnd\data\chain\bitcoin\mainnet\temp-dont-use.backup to C:\Users\raymo\AppData\Local\Lnd\data\chain\bitcoin\mainnet\channel.backup
2021-07-22 13:56:41.405 [INF] CNCT: ChannelArbitrator(ca62dbe5454b5f13ad7228e8bafeb297096de6ee6cfbd2e1a8208d292065c972:1): contract resolutions empty, marking channel as fully resolved!
2021-07-22 13:56:41.424 [INF] CNCT: ChannelPoint(ca62dbe5454b5f13ad7228e8bafeb297096de6ee6cfbd2e1a8208d292065c972:1) has been fully resolved on-chain at height=692113
2021-07-22 13:56:41.424 [INF] CNCT: Marking ChannelPoint(ca62dbe5454b5f13ad7228e8bafeb297096de6ee6cfbd2e1a8208d292065c972:1) fully resolved
2021-07-22 13:56:41.425 [INF] CHDB: Pruning link node 03858f3b77447b572733e6e888cbbf36b8bc8483bb9716041953bb284495655522 with zero open channels from database
2021-07-22 13:56:41.543 [WRN] BTCN: Query(936) from peer 46.4.89.121:8333 failed, rescheduling: did not get response before timeout
2021-07-22 13:56:41.543 [WRN] BTCN: Query(936) failed with error: did not get response before timeout. Timing out.
2021-07-22 13:56:41.543 [INF] CRTR: Pruning channel graph using block 000000000000000000091daa74693f4fe0c643babbc8c4560e938d865816f2c7 (height=692113)
2021-07-22 13:56:41.546 [INF] CHDB: Pruned unconnected node 03858f3b77447b572733e6e888cbbf36b8bc8483bb9716041953bb284495655522 from channel graph
2021-07-22 13:56:41.546 [INF] CHDB: Pruned 1 unconnected nodes from the channel graph
2021-07-22 13:56:41.558 [INF] CRTR: Block 000000000000000000091daa74693f4fe0c643babbc8c4560e938d865816f2c7 (height=692113) closed 1 channels
2021-07-22 13:56:45.551 [WRN] BTCN: Query(936) from peer 46.4.89.121:8333 failed, rescheduling: did not get response before timeout
2021-07-22 13:56:53.564 [WRN] BTCN: Query(936) from peer 46.4.89.121:8333 failed, rescheduling: did not get response before timeout

@Roasbeef
Copy link
Member

I'm guessing you might've hit a longer timeout with the neutrino backend during broadcast of the initial force close transaction.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@Roasbeef @raymondclowe