Avoid cascading failure: give up on incoming HTLCs in time if outgoing is stuck.

onchaind/onchaind.c

@@ -1499,12 +1499,16 @@ static void handle_preimage(struct tracked_output **outs,
 		if (!ripemd160_eq(&outs[i]->htlc.ripemd, &ripemd))
 			continue;
 
-		/* Too late? */
+		/* If HTLC has timed out, we will already have
+		 * proposed a "ignore this, it's their problem".  But
+		 * now try this proposal instead! */
 		if (outs[i]->resolved) {
-			status_broken("HTLC already resolved by %s"
-				     " when we found preimage",
-				     tx_type_name(outs[i]->resolved->tx_type));
-			return;
+			if (outs[i]->resolved->tx_type != SELF) {
+				status_broken("HTLC already resolved by %s"
+					      " when we found preimage",
+					      tx_type_name(outs[i]->resolved->tx_type));
+				return;
+			}
 		}
 
 		/* stash the payment_hash so we can track this coin movement */

plugins/bcli.c

@@ -179,9 +179,9 @@ static char *args_string(const tal_t *ctx, const char **args)
 	return ret;
 }
 
-static char *bcli_args(struct bitcoin_cli *bcli)
+static char *bcli_args(const tal_t *ctx, struct bitcoin_cli *bcli)
 {
-    return args_string(bcli, bcli->args);
+    return args_string(ctx, bcli->args);
 }
 
 /* Only set as destructor once bcli is in current. */
@@ -197,6 +197,7 @@ static void retry_bcli(void *cb_arg)
 	tal_del_destructor(bcli, destroy_bcli);
 
 	list_add_tail(&bitcoind->pending[bcli->prio], &bcli->list);
+	tal_free(bcli->output);
 	next_bcli(bcli->prio);
 }
 
@@ -216,15 +217,15 @@ static void bcli_failure(struct bitcoin_cli *bcli,
 		           "we have been retrying command for "
 		           "--bitcoin-retry-timeout=%"PRIu64" seconds; "
 		           "bitcoind setup or our --bitcoin-* configs broken?",
-		           bcli_args(bcli),
+		           bcli_args(tmpctx, bcli),
 		           exitstatus,
 		           bitcoind->error_count,
 		           (int)bcli->output_bytes,
 		           bcli->output,
 		           bitcoind->retry_timeout);
 
 	plugin_log(bcli->cmd->plugin, LOG_UNUSUAL, "%s exited with status %u",
-		   bcli_args(bcli), exitstatus);
+		   bcli_args(tmpctx, bcli), exitstatus);
 	bitcoind->error_count++;
 
 	/* Retry in 1 second */
@@ -242,19 +243,19 @@ static void bcli_finished(struct io_conn *conn UNUSED, struct bitcoin_cli *bcli)
 	if (msec > 10000)
 		plugin_log(bcli->cmd->plugin, LOG_UNUSUAL,
 		           "bitcoin-cli: finished %s (%"PRIu64" ms)",
-		           bcli_args(bcli), msec);
+		           bcli_args(tmpctx, bcli), msec);
 
 	assert(bitcoind->num_requests[prio] > 0);
 
 	/* FIXME: If we waited for SIGCHILD, this could never hang! */
 	while ((ret = waitpid(bcli->pid, &status, 0)) < 0 && errno == EINTR);
 	if (ret != bcli->pid)
-		plugin_err(bcli->cmd->plugin, "%s %s", bcli_args(bcli),
+		plugin_err(bcli->cmd->plugin, "%s %s", bcli_args(tmpctx, bcli),
 		           ret == 0 ? "not exited?" : strerror(errno));
 
 	if (!WIFEXITED(status))
 		plugin_err(bcli->cmd->plugin, "%s died with signal %i",
-		           bcli_args(bcli),
+		           bcli_args(tmpctx, bcli),
 		           WTERMSIG(status));
 
 	/* Implicit nonzero_exit_ok == false */
@@ -380,7 +381,7 @@ static struct command_result *command_err_bcli_badjson(struct bitcoin_cli *bcli,
 						       const char *errmsg)
 {
 	char *err = tal_fmt(bcli, "%s: bad JSON: %s (%.*s)",
-			    bcli_args(bcli), errmsg,
+			    bcli_args(tmpctx, bcli), errmsg,
 			    (int)bcli->output_bytes, bcli->output);
 	return command_done_err(bcli->cmd, BCLI_ERROR, err, NULL);
 }
@@ -537,7 +538,7 @@ static struct command_result *process_sendrawtransaction(struct bitcoin_cli *bcl
 	if (bcli->exitstatus)
 		plugin_log(bcli->cmd->plugin, LOG_DBG,
 			   "sendrawtx exit %i (%s) %.*s",
-			   *bcli->exitstatus, bcli_args(bcli),
+			   *bcli->exitstatus, bcli_args(tmpctx, bcli),
 			   *bcli->exitstatus ?
 				(u32)bcli->output_bytes-1 : 0,
 				bcli->output);

tests/test_closing.py

@@ -11,6 +11,7 @@
     first_scid
 )
 
+import bitcoin
 import os
 import queue
 import pytest
@@ -3793,3 +3794,78 @@ def test_closing_anchorspend_htlc_tx_rbf(node_factory, bitcoind):
 
     # And this will mine it!
     bitcoind.generate_block(1, needfeerate=4990)
+
+
+@pytest.mark.xfail(strict=True)
+@pytest.mark.developer("needs dev_disconnect")
+@pytest.mark.parametrize("anchors", [False, True])
+def test_htlc_no_force_close(node_factory, bitcoind, anchors):
+    """l2<->l3 force closes while an HTLC is in flight from l1, but l2 can't timeout because the feerate has spiked.  It should do so anyway."""
+    opts = [{}, {}, {'disconnect': ['-WIRE_UPDATE_FULFILL_HTLC']}]
+    if anchors:
+        for opt in opts:
+            opt['experimental-anchors'] = None
+
+    l1, l2, l3 = node_factory.line_graph(3, opts=opts)
+
+    MSATS = 12300000
+    inv = l3.rpc.invoice(MSATS, 'label', 'description')
+
+    route = [{'amount_msat': MSATS + 1 + MSATS * 10 // 1000000,
+              'id': l2.info['id'],
+              'delay': 16,
+              'channel': first_scid(l1, l2)},
+             {'amount_msat': MSATS,
+              'id': l3.info['id'],
+              'delay': 10,
+              'channel': first_scid(l2, l3)}]
+    l1.rpc.sendpay(route, inv['payment_hash'],
+                   payment_secret=inv['payment_secret'])
+    l3.daemon.wait_for_log('dev_disconnect')
+
+    htlc_txs = []
+
+    # l3 drops to chain, holding htlc (but we stop it xmitting txs)
+    def censoring_sendrawtx(r):
+        htlc_txs.append(r['params'][0])
+        return {'id': r['id'], 'result': {}}
+
+    l3.daemon.rpcproxy.mock_rpc('sendrawtransaction', censoring_sendrawtx)
+
+    # l3 gets upset, drops to chain when there are < 4 blocks remaining.
+    # But tx doesn't get mined...
+    bitcoind.generate_block(8)
+    l3.daemon.wait_for_log("Peer permanent failure in CHANNELD_NORMAL: Fulfilled HTLC 0 SENT_REMOVE_.* cltv 114 hit deadline")
+
+    # l2 closes drops the commitment tx at block 115 (one block after timeout)
+    bitcoind.generate_block(4)
+    l2.daemon.wait_for_log("Peer permanent failure in CHANNELD_NORMAL: Offered HTLC 0 SENT_ADD_ACK_REVOCATION cltv 114 hit deadline")
+    l1.set_feerates((15000, 15000, 15000, 15000))
+
+    # Two more blocks, with no htlc tx.
+    bitcoind.generate_block(1, wait_for_mempool=1)
+    # Make sure l2 sees it onchain!
+    wait_for(lambda: only_one(l2.rpc.listpeerchannels(l3.info['id'])['channels'])['state'] == 'ONCHAIN')
+    # Don't let l2's htlc timeout tx get mined either!
+    bitcoind.generate_block(1, needfeerate=9999999)
+
+    # l2 will have abandoned l2->l3 HTLC to close l1->l2.
+    l2.daemon.wait_for_log(r'Abandoning unresolved onchain HTLC at block 117 \(expired at 114\) to avoid peer closing incoming HTLC at block 120')
+
+    # l1 should not have force-closed, htlc should be finished by l2.
+    assert not l1.daemon.is_in_log('Peer permanent failure in CHANNELD_NORMAL')
+    wait_for(lambda: only_one(l1.rpc.listpeerchannels()['channels'])['htlcs'] == [])
+
+    # Now, surprise!  l3 fulfills htlc (l2 loses out!)
+    assert htlc_txs != []
+    for tx in htlc_txs:
+        try:
+            bitcoind.rpc.sendrawtransaction(tx)
+        except bitcoin.rpc.VerifyError:
+            pass
+
+    # l2 should note this, but not crash, at least.
+    bitcoind.generate_block(1, wait_for_mempool=1)
+    sync_blockheight(bitcoind, [l1, l2, l3])
+
+    # FIXME: l2 should complain!