Confirmed cooperative close shows as pending

[chrisrico]

Background

A remote node cooperative closed a channel on 2018-04-06. The closing transaction was included in block 517166, but remained pending for two days, until I restarted LND.

Your environment

• 13945de
• 3.13.0-37-generic #50 Add database versioning  #64-Ubuntu SMP Mon Sep 22 21:28:38 UTC 2014 x86_64 x86_64 x86_64 GNU/Linux
• bitcoind v0.16.99.0-9cb2309

Steps to reproduce

Unsure.

Expected behaviour

Cooperative close should no longer be pending after confirmation.

Actual behaviour

It remained pending after 100 confirmations. Upon a restart of LND, the situation resolved itself. Relevant log entries below.

"pending_closing_channels": [
    {
        "channel": {
            "remote_node_pub": "028aa4db3f7d937758adc16bf55d6216bde744a611bc1cf746cfebbbd062c1ee75",
            "channel_point": "a3a008dab111d2ee3057e0547466c9afc06aef5c6e704fb0a4fac4931482facc:0",
            "capacity": "2500000",
            "local_balance": "1306",
            "remote_balance": "0"
        },
        "closing_txid": "12de439a78c01e9b60f5fe2ee294400ff9d6574198d341013aa1b2e422c307bb"
    }
]

$ zegrep "a3a008dab111d2ee3057e0547466c9afc06aef5c6e704fb0a4fac4931482facc|12de439a78c01e9b60f5fe2ee294400ff9d6574198d341013aa1b2e422c307bb" .lnd/logs/bitcoin/mainnet/lnd.log*
2018-04-06 22:21:20.938 [INF] NTFN: New spend subscription: utxo=a3a008dab111d2ee3057e0547466c9afc06aef5c6e704fb0a4fac4931482facc:0
2018-04-06 22:21:21.038 [INF] CNCT: Close observer for ChannelPoint(a3a008dab111d2ee3057e0547466c9afc06aef5c6e704fb0a4fac4931482facc:0) active
2018-04-06 22:21:21.282 [INF] CNCT: ChannelArbitrator(a3a008dab111d2ee3057e0547466c9afc06aef5c6e704fb0a4fac4931482facc:0): starting state=StateDefault
2018-04-06 22:22:52.966 [INF] NTFN: New spend subscription: utxo=a3a008dab111d2ee3057e0547466c9afc06aef5c6e704fb0a4fac4931482facc:0
2018-04-06 22:22:53.042 [INF] CNCT: Close observer for ChannelPoint(a3a008dab111d2ee3057e0547466c9afc06aef5c6e704fb0a4fac4931482facc:0) active
2018-04-06 22:22:54.122 [INF] CNCT: ChannelArbitrator(a3a008dab111d2ee3057e0547466c9afc06aef5c6e704fb0a4fac4931482facc:0): starting state=StateDefault
2018-04-06 22:26:22.383 [INF] NTFN: New spend subscription: utxo=a3a008dab111d2ee3057e0547466c9afc06aef5c6e704fb0a4fac4931482facc:0
2018-04-06 22:26:22.484 [INF] CNCT: Close observer for ChannelPoint(a3a008dab111d2ee3057e0547466c9afc06aef5c6e704fb0a4fac4931482facc:0) active
2018-04-06 22:26:22.875 [INF] CNCT: ChannelArbitrator(a3a008dab111d2ee3057e0547466c9afc06aef5c6e704fb0a4fac4931482facc:0): starting state=StateDefault
2018-04-06 22:29:20.260 [INF] NTFN: New spend subscription: utxo=a3a008dab111d2ee3057e0547466c9afc06aef5c6e704fb0a4fac4931482facc:0
2018-04-06 22:29:20.361 [INF] CNCT: Close observer for ChannelPoint(a3a008dab111d2ee3057e0547466c9afc06aef5c6e704fb0a4fac4931482facc:0) active
2018-04-06 22:29:20.900 [INF] CNCT: ChannelArbitrator(a3a008dab111d2ee3057e0547466c9afc06aef5c6e704fb0a4fac4931482facc:0): starting state=StateDefault
2018-04-06 23:37:05.887 [INF] NTFN: New spend subscription: utxo=a3a008dab111d2ee3057e0547466c9afc06aef5c6e704fb0a4fac4931482facc:0
2018-04-06 23:37:05.965 [INF] CNCT: Close observer for ChannelPoint(a3a008dab111d2ee3057e0547466c9afc06aef5c6e704fb0a4fac4931482facc:0) active
2018-04-06 23:37:07.025 [INF] CNCT: ChannelArbitrator(a3a008dab111d2ee3057e0547466c9afc06aef5c6e704fb0a4fac4931482facc:0): starting state=StateDefault
2018-04-07 11:55:37.365 [INF] PEER: NodeKey(028aa4db3f7d937758adc16bf55d6216bde744a611bc1cf746cfebbbd062c1ee75) loading ChannelPoint(a3a008dab111d2ee3057e0547466c9afc06aef5c6e704fb0a4fac4931482facc:0)
2018-04-07 11:55:37.366 [INF] HSWC: ChannelLink(a3a008dab111d2ee3057e0547466c9afc06aef5c6e704fb0a4fac4931482facc:0) is starting
2018-04-07 11:55:37.366 [INF] CNCT: Attempting to update ContractSignals for ChannelPoint(a3a008dab111d2ee3057e0547466c9afc06aef5c6e704fb0a4fac4931482facc:0)
2018-04-07 11:55:37.366 [INF] HSWC: HTLC manager for ChannelPoint(a3a008dab111d2ee3057e0547466c9afc06aef5c6e704fb0a4fac4931482facc:0) started, bandwidth=0 mSAT
2018-04-07 11:55:37.366 [INF] HSWC: Attempting to re-resynchronize ChannelPoint(a3a008dab111d2ee3057e0547466c9afc06aef5c6e704fb0a4fac4931482facc:0)
2018-04-07 11:55:37.392 [INF] HSWC: Received re-establishment message from remote side for channel(a3a008dab111d2ee3057e0547466c9afc06aef5c6e704fb0a4fac4931482facc:0)
2018-04-07 12:04:26.536 [INF] HSWC: ChannelLink(a3a008dab111d2ee3057e0547466c9afc06aef5c6e704fb0a4fac4931482facc:0) is stopping
2018-04-07 12:04:26.537 [INF] HSWC: ChannelLink(a3a008dab111d2ee3057e0547466c9afc06aef5c6e704fb0a4fac4931482facc:0) has exited
2018-04-07 23:09:32.851 [INF] PEER: NodeKey(028aa4db3f7d937758adc16bf55d6216bde744a611bc1cf746cfebbbd062c1ee75) loading ChannelPoint(a3a008dab111d2ee3057e0547466c9afc06aef5c6e704fb0a4fac4931482facc:0)
2018-04-07 23:09:32.854 [INF] HSWC: ChannelLink(a3a008dab111d2ee3057e0547466c9afc06aef5c6e704fb0a4fac4931482facc:0) is starting
2018-04-07 23:09:32.854 [INF] CNCT: Attempting to update ContractSignals for ChannelPoint(a3a008dab111d2ee3057e0547466c9afc06aef5c6e704fb0a4fac4931482facc:0)
2018-04-07 23:09:32.854 [INF] HSWC: HTLC manager for ChannelPoint(a3a008dab111d2ee3057e0547466c9afc06aef5c6e704fb0a4fac4931482facc:0) started, bandwidth=0 mSAT
2018-04-07 23:09:32.854 [INF] HSWC: Attempting to re-resynchronize ChannelPoint(a3a008dab111d2ee3057e0547466c9afc06aef5c6e704fb0a4fac4931482facc:0)
2018-04-07 23:09:32.870 [INF] HSWC: Received re-establishment message from remote side for channel(a3a008dab111d2ee3057e0547466c9afc06aef5c6e704fb0a4fac4931482facc:0)
2018-04-07 23:13:40.149 [INF] PEER: Ideal fee for closure of ChannelPoint(a3a008dab111d2ee3057e0547466c9afc06aef5c6e704fb0a4fac4931482facc:0) is: 926 sat
2018-04-07 23:13:40.149 [INF] HSWC: ChannelLink(a3a008dab111d2ee3057e0547466c9afc06aef5c6e704fb0a4fac4931482facc:0) is stopping
2018-04-07 23:13:40.149 [INF] PEER: ChannelPoint(a3a008dab111d2ee3057e0547466c9afc06aef5c6e704fb0a4fac4931482facc:0): sending shutdown message
2018-04-07 23:13:40.149 [INF] PEER: ChannelPoint(a3a008dab111d2ee3057e0547466c9afc06aef5c6e704fb0a4fac4931482facc:0): Responding to shutdown
2018-04-07 23:13:40.149 [INF] HSWC: ChannelLink(a3a008dab111d2ee3057e0547466c9afc06aef5c6e704fb0a4fac4931482facc:0) has exited
2018-04-07 23:13:40.223 [INF] PEER: ChannelPoint(a3a008dab111d2ee3057e0547466c9afc06aef5c6e704fb0a4fac4931482facc:0): computing fee compromise, ideal=926, last_sent=0, remote_offer=173
2018-04-07 23:13:40.224 [INF] PEER: ChannelPoint(a3a008dab111d2ee3057e0547466c9afc06aef5c6e704fb0a4fac4931482facc:0): proposing fee of 926 sat to close chan
2018-04-07 23:13:40.224 [INF] CNCT: Waiting for txid=2f43662dd16c8712d714d725e757889ae2c95bafe546c958ece3637c1a4e66e1 to close ChannelPoint(a3a008dab111d2ee3057e0547466c9afc06aef5c6e704fb0a4fac4931482facc:0) on chain
2018-04-07 23:13:40.282 [INF] PEER: ChannelPoint(a3a008dab111d2ee3057e0547466c9afc06aef5c6e704fb0a4fac4931482facc:0): computing fee compromise, ideal=926, last_sent=926, remote_offer=548
2018-04-07 23:13:40.282 [INF] PEER: ChannelPoint(a3a008dab111d2ee3057e0547466c9afc06aef5c6e704fb0a4fac4931482facc:0): proposing fee of 834 sat to close chan
2018-04-07 23:13:40.374 [INF] PEER: ChannelPoint(a3a008dab111d2ee3057e0547466c9afc06aef5c6e704fb0a4fac4931482facc:0): computing fee compromise, ideal=926, last_sent=834, remote_offer=690
2018-04-07 23:13:40.374 [INF] PEER: ChannelPoint(a3a008dab111d2ee3057e0547466c9afc06aef5c6e704fb0a4fac4931482facc:0): proposed remote fee is close enough, capitulating
2018-04-07 23:13:40.375 [INF] PEER: ChannelPoint(a3a008dab111d2ee3057e0547466c9afc06aef5c6e704fb0a4fac4931482facc:0): proposing fee of 690 sat to close chan
2018-04-07 23:13:40.375 [INF] PEER: ChannelPoint(a3a008dab111d2ee3057e0547466c9afc06aef5c6e704fb0a4fac4931482facc:0) fee of 0.0000069 BTC accepted, ending negotiation
2018-04-07 23:13:40.376 [INF] PEER: Broadcasting cooperative close tx: (*wire.MsgTx)(0xc42c468ec0)({
 Version: (int32) 2,
 TxIn: ([]*wire.TxIn) (len=1 cap=15) {
  (*wire.TxIn)(0xc4288efe60)({
   PreviousOutPoint: (wire.OutPoint) a3a008dab111d2ee3057e0547466c9afc06aef5c6e704fb0a4fac4931482facc:0,
   SignatureScript: ([]uint8) <nil>,
   Witness: (wire.TxWitness) (len=4 cap=4) {
    ([]uint8) <nil>,
    ([]uint8) (len=71 cap=144) {
     00000000  30 44 02 20 6a 86 6a 30  73 ee d4 15 86 f0 07 47  |0D. j.j0s......G|
     00000010  f9 7b f4 a1 b5 dc 9e 6d  a9 2d 8a c8 18 81 ef 1e  |.{.....m.-......|
     00000020  69 8b 0b cf 02 20 4a 2c  d8 4a b0 53 e9 91 c1 b0  |i.... J,.J.S....|
     00000030  21 bb 48 f9 15 a9 98 d1  9d 46 01 aa ed 67 ff 95  |!.H......F...g..|
     00000040  5a cb c7 05 17 0c 01                              |Z......|
    },
    ([]uint8) (len=71 cap=144) {
     00000000  30 44 02 20 32 8d 0b a9  93 1d a6 fe 78 90 22 5c  |0D. 2.......x."\|
     00000010  fb d6 3b 18 be 80 21 7a  39 1c 51 38 e6 86 9c 96  |..;...!z9.Q8....|
     00000020  7c 3b 80 0f 02 20 5c 41  24 53 19 a8 9e e3 b0 78  ||;... \A$S.....x|
     00000030  4b b1 9d 8c 94 54 1c 6c  b9 b3 a7 c7 87 83 6a 72  |K....T.l......jr|
     00000040  4c 95 60 32 5f ab 01                              |L.`2_..|
    },
    ([]uint8) (len=71 cap=500) {
     00000000  52 21 03 0c 5d a9 eb 51  39 3a 93 9f 4b 93 34 dc  |R!..]..Q9:..K.4.|
     00000010  91 50 8b 5c a3 5d e3 8a  a0 75 26 2b db 40 cc 54  |.P.\.]...u&+.@.T|
     00000020  4e 80 b9 21 03 65 b1 8a  a0 46 c2 9b 7d a5 9d 77  |N..!.e...F..}..w|
     00000030  b2 33 d1 1b 7b 34 ce f0  90 a6 3e ec cd d4 91 e7  |.3..{4....>.....|
     00000040  f5 6a 39 c7 42 52 ae                              |.j9.BR.|
    }
   },
   Sequence: (uint32) 4294967295
  })
 },
 TxOut: ([]*wire.TxOut) (len=2 cap=15) {
  (*wire.TxOut)(0xc424810620)({
   Value: (int64) 1306,
   PkScript: ([]uint8) (len=22 cap=500) {
    00000000  00 14 3d eb 25 4a 76 ec  84 c6 76 cd c9 c1 6a 46  |..=.%Jv...v...jF|
    00000010  bf 3b 41 b7 3b 6d                                 |.;A.;m|
   }
  }),
  (*wire.TxOut)(0xc424810640)({
   Value: (int64) 2498003,
   PkScript: ([]uint8) (len=23 cap=34) {
    00000000  a9 14 46 c0 58 24 51 33  93 26 4a e8 9c 2e a0 5e  |..F.X$Q3.&J....^|
    00000010  2d ff 68 45 3e b8 87                              |-.hE>..|
   }
  })
 },
 LockTime: (uint32) 0
})
2018-04-07 23:13:40.377 [INF] LNWL: Inserting unconfirmed transaction 12de439a78c01e9b60f5fe2ee294400ff9d6574198d341013aa1b2e422c307bb
2018-04-07 23:13:40.991 [INF] CNCT: Waiting for txid=6feea4525973af08eed486cb87cfd6b99eeac14c8734ec801fc610a02a70b587 to close ChannelPoint(a3a008dab111d2ee3057e0547466c9afc06aef5c6e704fb0a4fac4931482facc:0) on chain
2018-04-07 23:13:40.992 [INF] CNCT: Finalizing chan close for ChannelPoint(a3a008dab111d2ee3057e0547466c9afc06aef5c6e704fb0a4fac4931482facc:0)
2018-04-07 23:13:41.008 [INF] PEER: Waiting for confirmation of cooperative close of ChannelPoint(a3a008dab111d2ee3057e0547466c9afc06aef5c6e704fb0a4fac4931482facc:0) with txid: 12de439a78c01e9b60f5fe2ee294400ff9d6574198d341013aa1b2e422c307bb
2018-04-07 23:13:41.366 [INF] NTFN: Dispatching spend notification for outpoint=a3a008dab111d2ee3057e0547466c9afc06aef5c6e704fb0a4fac4931482facc:0
2018-04-07 23:13:41.366 [INF] NTFN: New confirmations subscription: txid=12de439a78c01e9b60f5fe2ee294400ff9d6574198d341013aa1b2e422c307bb, numconfs=1
2018-04-07 23:13:41.366 [INF] CNCT: Waiting for txid=12de439a78c01e9b60f5fe2ee294400ff9d6574198d341013aa1b2e422c307bb to close ChannelPoint(a3a008dab111d2ee3057e0547466c9afc06aef5c6e704fb0a4fac4931482facc:0) on chain
2018-04-07 23:13:41.366 [ERR] CNCT: Unable to fetch channel state for chan_point=a3a008dab111d2ee3057e0547466c9afc06aef5c6e704fb0a4fac4931482facc:0
2018-04-07 23:13:41.367 [INF] NTFN: New confirmations subscription: txid=12de439a78c01e9b60f5fe2ee294400ff9d6574198d341013aa1b2e422c307bb, numconfs=1
2018-04-07 23:19:58.392 [INF] LNWL: Marking unconfirmed transaction 12de439a78c01e9b60f5fe2ee294400ff9d6574198d341013aa1b2e422c307bb mined in block 517166
2018-04-07 23:19:58.409 [INF] NTFN: Dispatching 1 conf notification for 12de439a78c01e9b60f5fe2ee294400ff9d6574198d341013aa1b2e422c307bb
2018-04-07 23:19:58.409 [INF] NTFN: Dispatching 1 conf notification for 12de439a78c01e9b60f5fe2ee294400ff9d6574198d341013aa1b2e422c307bb
2018-04-07 23:19:58.409 [INF] PEER: ChannelPoint(a3a008dab111d2ee3057e0547466c9afc06aef5c6e704fb0a4fac4931482facc:0) is now closed at height 517166
2018-04-07 23:19:58.409 [INF] CNCT: ChannelPoint(a3a008dab111d2ee3057e0547466c9afc06aef5c6e704fb0a4fac4931482facc:0) is fully closed, at height: 517166
2018-04-07 23:19:58.410 [INF] CNCT: ChannelArbitrator(a3a008dab111d2ee3057e0547466c9afc06aef5c6e704fb0a4fac4931482facc:0) closing due to co-op closure
2018-04-07 23:19:58.431 [WRN] CNCT: unable to update latest close for ChannelPoint(a3a008dab111d2ee3057e0547466c9afc06aef5c6e704fb0a4fac4931482facc:0)
-- RESTARTED LND
2018-04-08 14:29:07.552 [INF] NTFN: New spend subscription: utxo=a3a008dab111d2ee3057e0547466c9afc06aef5c6e704fb0a4fac4931482facc:0
2018-04-08 14:29:29.349 [INF] NTFN: Dispatching spend notification for outpoint=a3a008dab111d2ee3057e0547466c9afc06aef5c6e704fb0a4fac4931482facc:0
2018-04-08 14:29:29.349 [INF] CNCT: Waiting for txid=12de439a78c01e9b60f5fe2ee294400ff9d6574198d341013aa1b2e422c307bb to close ChannelPoint(a3a008dab111d2ee3057e0547466c9afc06aef5c6e704fb0a4fac4931482facc:0) on chain
2018-04-08 14:29:29.349 [INF] NTFN: New confirmations subscription: txid=12de439a78c01e9b60f5fe2ee294400ff9d6574198d341013aa1b2e422c307bb, numconfs=1
2018-04-08 14:29:29.358 [INF] NTFN: Dispatching 1 conf notification for 12de439a78c01e9b60f5fe2ee294400ff9d6574198d341013aa1b2e422c307bb
2018-04-08 14:29:29.358 [INF] CNCT: ChannelPoint(a3a008dab111d2ee3057e0547466c9afc06aef5c6e704fb0a4fac4931482facc:0) is fully closed, at height: 517166
2018-04-08 14:29:29.358 [INF] CNCT: Marking ChannelPoint(a3a008dab111d2ee3057e0547466c9afc06aef5c6e704fb0a4fac4931482facc:0) fully resolved```

[lobsterpub]

I have the same issue and on the same build, but restarting LND did NOT resolve it.

[Roasbeef]

Which chain backend are you using @lobsterpub?

[Roasbeef]

The line of interest is:

2018-04-07 23:19:58.431 [WRN] CNCT: unable to update latest close for ChannelPoint(a3a008dab111d2ee3057e0547466c9afc06aef5c6e704fb0a4fac4931482facc:0)

We see that the channel has been closed, but when we go to close out the channel, we get an error, that unfortunately isn't logged. I think I know the culprit though...working on a fix locally

[Roasbeef]

Are there any relevant log lines after:

2018-04-07 23:19:58.431 [WRN] CNCT: unable to update latest close for ChannelPoint(a3a008dab111d2ee3057e0547466c9afc06aef5c6e704fb0a4fac4931482facc:0)

?

[Roasbeef]

Attempted to reproduce this a few times locally ensuring that btcd only generates spends from confirmed transactions, but everything worked out (ensuring I force fee negotiation). Will continue to look into this!

[Roasbeef]

What's the min fee rate of your node set to?

[chrisrico]

What search term should I use to find relevant lines? Every line including either the funding or closing txid is in my original post.

Which fee rate of which node? Min relay fee on bitcoind is 0.00001000 (default). I'm not seeing a min fee rate at the node level for lnd. Maybe --bitcoin.feerate? I don't have that set, so whatever the default is (I think 0.000001).

[Roasbeef]

Try setting it to 0.00000100

According to the logs, we ended up using a fee of 690 satoshis.

2018-04-07 23:13:40.375 [INF] PEER: ChannelPoint(a3a008dab111d2ee3057e0547466c9afc06aef5c6e704fb0a4fac4931482facc:0): proposing fee of 690 sat to close chan
2018-04-07 23:13:40.375 [INF] PEER: ChannelPoint(a3a008dab111d2ee3057e0547466c9afc06aef5c6e704fb0a4fac4931482facc:0) fee of 0.0000069 BTC accepted, ending negotiation
2018-04-07 23:13:40.376 [INF] PEER: Broadcasting cooperative close tx: (*wire.MsgTx)(0xc42c468ec0)({

[chrisrico]

bitcoind fee options are specified in BTC/kB, so 0.00001000 is actually 1 satoshi/byte. The closing transaction was 334 bytes so paid ~2 satoshis/byte. The transaction was relayed and confirmed, so it doesn't seem like a bitcoind issue to me.

  -minrelaytxfee=<amt>
       Fees (in BTC/kB) smaller than this are considered zero fee for relaying,
       mining and transaction creation (default: 0.00001)

Unless you're saying I should set the --bitcoin.feerate option on lnd to 0.00000100?

[Roasbeef]

What I mean is that it seems your bitcoind didn't initially accept this transaction, and that lowering the minrelay fee should resolve this. I've only seen this pop up on bitcoind and not btcd (which has a much lower default minrelay fee).

[Roasbeef]

Also:

Are there any relevant log lines after:

[chrisrico]

I provided all logs mentioning the funding or closing txid. I don't know what else is relevant.

[Roasbeef]

The lines after:

2018-04-07 23:19:58.409 [INF] PEER: ChannelPoint(a3a008dab111d2ee3057e0547466c9afc06aef5c6e704fb0a4fac4931482facc:0) is now closed at height 517166
2018-04-07 23:19:58.409 [INF] CNCT: ChannelPoint(a3a008dab111d2ee3057e0547466c9afc06aef5c6e704fb0a4fac4931482facc:0) is fully closed, at height: 517166
2018-04-07 23:19:58.410 [INF] CNCT: ChannelArbitrator(a3a008dab111d2ee3057e0547466c9afc06aef5c6e704fb0a4fac4931482facc:0) closing due to co-op closure
2018-04-07 23:19:58.431 [WRN] CNCT: unable to update latest close for ChannelPoint(a3a008dab111d2ee3057e0547466c9afc06aef5c6e704fb0a4fac4931482facc:0)

From those logs even, looks like everything was properly updated in the database.