From 43e59a67742c993ee5fa2a471cf2d2b0dad26406 Mon Sep 17 00:00:00 2001 From: Rusty Russell Date: Fri, 21 Feb 2025 09:35:26 +1030 Subject: [PATCH] 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 --- plugins/xpay/xpay.c | 50 ++++++++++++++++++++++++++++++++-------- tests/test_xpay.py | 56 +++++++++++++++++++++++++++++++++++++++++++++ 2 files changed, 97 insertions(+), 9 deletions(-) diff --git a/plugins/xpay/xpay.c b/plugins/xpay/xpay.c index d15ddf6ad..17a118122 100644 --- a/plugins/xpay/xpay.c +++ b/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 @@ disable_channel: 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 @@ channel_capacity: 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, diff --git a/tests/test_xpay.py b/tests/test_xpay.py index 684c6d175..a26bfc6ee 100644 --- a/tests/test_xpay.py +++ b/tests/test_xpay.py @@ -8,6 +8,7 @@ from utils import ( 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}