pytest: test xpay gracefully handles failure after success.

We can create this scenario by having one path force close.  We take
the opportunity to log this, even in non-slow-mode, since it's interesting
(not our bug, but someone just lost money!).

Signed-off-by: Rusty Russell <[email protected]>

Author: rustyrussell

plugins/xpay/xpay.c

@@ -519,6 +519,21 @@ static const char *describe_scidd(struct attempt *attempt, size_t index)
 	return fmt_short_channel_id_dir(tmpctx, &scidd);
 }
 
+/* How much did previous successes deliver? */
+static struct amount_msat total_delivered(const struct payment *payment)
+{
+	struct amount_msat sum = AMOUNT_MSAT(0);
+	struct attempt *attempt;
+
+	list_for_each(&payment->past_attempts, attempt, list) {
+		if (!attempt->preimage)
+			continue;
+		if (!amount_msat_accumulate(&sum, attempt->delivers))
+			abort();
+	}
+	return sum;
+}
+
 static void update_knowledge_from_error(struct command *aux_cmd,
 					const char *buf,
 					const jsmntok_t *error,
@@ -531,7 +546,7 @@ static void update_knowledge_from_error(struct command *aux_cmd,
 	int index;
 	enum onion_wire failcode;
 	bool from_final;
-	const char *failcode_name, *errmsg;
+	const char *failcode_name, *errmsg, *description;
 	enum jsonrpc_errcode ecode;
 
 	tok = json_get_member(buf, error, "code");
@@ -574,6 +589,7 @@ static void update_knowledge_from_error(struct command *aux_cmd,
 	/* Garbled?  Blame random hop. */
 	if (!replymsg) {
 		index = pseudorand(tal_count(attempt->hops));
+		description = "Garbled error message";
 		add_result_summary(attempt, LOG_UNUSUAL,
 				   "We got a garbled error message, and chose to (randomly) to disable %s for this payment",
 				   describe_scidd(attempt, index));
@@ -609,13 +625,14 @@ static void update_knowledge_from_error(struct command *aux_cmd,
 	} else
 		errmsg = failcode_name;
 
-	attempt_debug(attempt,
-		      "Error %s for path %s, from %s",
-		      errmsg,
-		      fmt_path(tmpctx, attempt),
-		      from_final ? "destination"
-		      : index == 0 ? "local node"
-		      : fmt_pubkey(tmpctx, &attempt->hops[index-1].next_node));
+	description = tal_fmt(tmpctx,
+			      "Error %s for path %s, from %s",
+			      errmsg,
+			      fmt_path(tmpctx, attempt),
+			      from_final ? "destination"
+			      : index == 0 ? "local node"
+			      : fmt_pubkey(tmpctx, &attempt->hops[index-1].next_node));
+	attempt_debug(attempt, "%s", description);
 
 	/* Final node sent an error */
 	if (from_final) {
@@ -735,7 +752,7 @@ static void update_knowledge_from_error(struct command *aux_cmd,
 				      attempt->hops[index].scidd);
 	json_add_bool(req->js, "enabled", false);
 	send_payment_req(aux_cmd, attempt->payment, req);
-	return;
+	goto check_previous_success;
 
 channel_capacity:
 	req = payment_ignored_req(aux_cmd, attempt, "askrene-inform-channel");
@@ -747,6 +764,21 @@ static void update_knowledge_from_error(struct command *aux_cmd,
 	json_add_amount_msat(req->js, "amount_msat", attempt->hops[index].amount_out);
 	json_add_string(req->js, "inform", "constrained");
 	send_payment_req(aux_cmd, attempt->payment, req);
+
+check_previous_success:
+	/* If they give us the preimage but we didn't succeed in giving them
+	 * all the money, that's a win for us.  But either the destination is
+	 * buggy, or someone along the way lost money! */
+	if (any_attempts_succeeded(attempt->payment)) {
+		payment_log(attempt->payment, LOG_UNUSUAL,
+			    "Destination accepted partial payment,"
+			    " failed a part (%s), but accepted only %s of %s."
+			    "  Winning?!",
+			    description,
+			    fmt_amount_msat(tmpctx,
+					    total_delivered(attempt->payment)),
+			    fmt_amount_msat(tmpctx, attempt->payment->amount));
+	}
 }
 
 static struct command_result *unreserve_path(struct command *aux_cmd,

tests/test_xpay.py

@@ -8,6 +8,7 @@
 
 import os
 import pytest
+import re
 import subprocess
 import sys
 from hashlib import sha256
@@ -710,3 +711,58 @@ def test_xpay_slow_mode(node_factory, bitcoind):
                                 'amount_sent_msat': 500010002,
                                 'failed_parts': 0,
                                 'successful_parts': 2}
+
+
+@pytest.mark.parametrize("slow_mode", [False, True])
+def test_fail_after_success(node_factory, bitcoind, executor, slow_mode):
+    # l1 -> l2 -> l3 -> l5
+    #         \-> l4 -/^
+    l1, l2, l3, l4, l5 = node_factory.get_nodes(5, opts=[{'xpay-slow-mode': slow_mode},
+                                                         {},
+                                                         {},
+                                                         {'disconnect': ['-WIRE_UPDATE_FULFILL_HTLC']},
+                                                         {}])
+    node_factory.join_nodes([l2, l3, l5])
+    node_factory.join_nodes([l2, l4, l5])
+
+    # Make sure l1 can see all paths.
+    node_factory.join_nodes([l1, l2])
+    bitcoind.generate_block(5)
+    wait_for(lambda: len(l1.rpc.listchannels()['channels']) == 10)
+
+    inv = l5.rpc.invoice(500000000, 'test_xpay_slow_mode', 'test_xpay_slow_mode', preimage='00' * 32)['bolt11']
+    fut = executor.submit(l1.rpc.xpay, invstring=inv, retry_for=0)
+
+    # Part via l3 is fine.  Part via l4 is stuck, so we kill l4 and mine
+    # blocks to make l2 force close.
+    l4.daemon.wait_for_log('dev_disconnect: -WIRE_UPDATE_FULFILL_HTLC')
+    l4.stop()
+
+    # Normally, we return as soon as first part succeeds.
+    if slow_mode is False:
+        assert fut.result(TIMEOUT) == {'payment_preimage': '00' * 32,
+                                       'amount_msat': 500000000,
+                                       'amount_sent_msat': 500010002,
+                                       'failed_parts': 0,
+                                       'successful_parts': 2}
+
+    # Time it out, l2 will collect it.
+    bitcoind.generate_block(13)
+    l2.daemon.wait_for_log('Peer permanent failure in CHANNELD_NORMAL: Offered HTLC 0 SENT_ADD_ACK_REVOCATION cltv 124 hit deadline')
+    bitcoind.generate_block(3, wait_for_mempool=1)
+
+    l1.daemon.wait_for_log(r"UNUSUAL.*Destination accepted partial payment, failed a part \(Error permanent_channel_failure for path ->022d223620a359a47ff7f7ac447c85c46c923da53389221a0054c11c1e3ca31d59->0382ce59ebf18be7d84677c2e35f23294b9992ceca95491fcf8a56c6cb2d9de199->032cf15d1ad9c4a08d26eab1918f732d8ef8fdc6abb9640bf3db174372c491304e, from 022d223620a359a47ff7f7ac447c85c46c923da53389221a0054c11c1e3ca31d59\)")
+    # Could be either way around, check both
+    line = l1.daemon.is_in_log(r"UNUSUAL.*Destination accepted partial payment, failed a part")
+    assert re.search(r'but accepted only 32000msat of 500000000msat\.  Winning\?!', line) or re.search(r'but accepted only 499968000msat of 500000000msat\.  Winning\?!', line)
+
+    if slow_mode is True:
+        # Now it succeeds, but notes that it only sent one part!
+        res = fut.result(TIMEOUT)
+        # Some variation due to floating point.
+        assert res['amount_sent_msat'] < 500000000
+        assert res == {'payment_preimage': '00' * 32,
+                       'amount_msat': 500000000,
+                       'amount_sent_msat': res['amount_sent_msat'],
+                       'failed_parts': 1,
+                       'successful_parts': 1}