From d60b9e433a11afaa72fc81415d1f4297a06ddadb Mon Sep 17 00:00:00 2001 From: Rusty Russell Date: Mon, 20 Jul 2020 15:19:52 +0930 Subject: [PATCH] test_penalty_htlc_tx_timeout: debugging Somehow, we occasionally set the wrong amount field? Doesn't happen all the time, but when it does: b'2020-07-20T05:40:15.510Z DEBUG lightningd: Attept to pay 528691fdf7baf0043ef2305e504988a5ae510dcb6127b463b3103b40c2b82a87 with amount 10839569msat < 500000000msat' b'2020-07-20T05:40:15.510Z DEBUG lightningd: WIRE_INCORRECT_OR_UNKNOWN_PAYMENT_DETAILS: lightningd/htlc_set.c:113' b'2020-07-20T05:40:15.510Z DEBUG 035d2b1192dfba134e10e540875d366ebc8bc353d5aa766b80c090b39c3a5d885d-chan#1: HTLC in 5 RCVD_ADD_ACK_REVOCATION->SENT_REMOVE_HTLC' b'2020-07-20T05:40:15.513Z DEBUG 035d2b1192dfba134e10e540875d366ebc8bc353d5aa766b80c090b39c3a5d885d-channeld-chan#1: peer_in WIRE_UPDATE_ADD_HTLC' b'2020-07-20T05:40:15.514Z DEBUG lightningd: Attept to pay 528691fdf7baf0043ef2305e504988a5ae510dcb6127b463b3103b40c2b82a87 with amount 9710103msat < 500000000msat' b'2020-07-20T05:40:15.514Z DEBUG lightningd: WIRE_INCORRECT_OR_UNKNOWN_PAYMENT_DETAILS: lightningd/htlc_set.c:113' b'2020-07-20T05:40:15.514Z DEBUG 035d2b1192dfba134e10e540875d366ebc8bc353d5aa766b80c090b39c3a5d885d-chan#1: HTLC in 10 RCVD_ADD_ACK_REVOCATION->SENT_REMOVE_HTLC' b'2020-07-20T05:40:15.518Z DEBUG lightningd: Attept to pay 528691fdf7baf0043ef2305e504988a5ae510dcb6127b463b3103b40c2b82a87 with amount 10915092msat < 500000000msat' b'2020-07-20T05:40:15.518Z DEBUG lightningd: WIRE_INCORRECT_OR_UNKNOWN_PAYMENT_DETAILS: lightningd/htlc_set.c:113' b'2020-07-20T05:40:15.518Z DEBUG 035d2b1192dfba134e10e540875d366ebc8bc353d5aa766b80c090b39c3a5d885d-chan#1: HTLC in 0 RCVD_ADD_ACK_REVOCATION->SENT_REMOVE_HTLC' b'2020-07-20T05:40:15.521Z DEBUG lightningd: Attept to pay 528691fdf7baf0043ef2305e504988a5ae510dcb6127b463b3103b40c2b82a87 with amount 9143652msat < 500000000msat' b'2020-07-20T05:40:15.521Z DEBUG lightningd: WIRE_INCORRECT_OR_UNKNOWN_PAYMENT_DETAILS: lightningd/htlc_set.c:113' b'2020-07-20T05:40:15.521Z DEBUG 035d2b1192dfba134e10e540875d366ebc8bc353d5aa766b80c090b39c3a5d885d-chan#1: HTLC in 3 RCVD_ADD_ACK_REVOCATION->SENT_REMOVE_HTLC' b'2020-07-20T05:40:15.524Z DEBUG lightningd: Attept to pay 528691fdf7baf0043ef2305e504988a5ae510dcb6127b463b3103b40c2b82a87 with amount 9840417msat < 500000000msat' b'2020-07-20T05:40:15.524Z DEBUG lightningd: WIRE_INCORRECT_OR_UNKNOWN_PAYMENT_DETAILS: lightningd/htlc_set.c:113' b'2020-07-20T05:40:15.524Z DEBUG 035d2b1192dfba134e10e540875d366ebc8bc353d5aa766b80c090b39c3a5d885d-chan#1: HTLC in 6 RCVD_ADD_ACK_REVOCATION->SENT_REMOVE_HTLC' b'2020-07-20T05:40:15.527Z DEBUG lightningd: Attept to pay 528691fdf7baf0043ef2305e504988a5ae510dcb6127b463b3103b40c2b82a87 with amount 10524535msat < 500000000msat' b'2020-07-20T05:40:15.527Z DEBUG lightningd: WIRE_INCORRECT_OR_UNKNOWN_PAYMENT_DETAILS: lightningd/htlc_set.c:113' b'2020-07-20T05:40:15.527Z DEBUG 035d2b1192dfba134e10e540875d366ebc8bc353d5aa766b80c090b39c3a5d885d-chan#1: HTLC in 8 RCVD_ADD_ACK_REVOCATION->SENT_REMOVE_HTLC' b'2020-07-20T05:40:15.536Z DEBUG lightningd: Attept to pay 528691fdf7baf0043ef2305e504988a5ae510dcb6127b463b3103b40c2b82a87 with amount 9579583msat < 500000000msat' b'2020-07-20T05:40:15.536Z DEBUG lightningd: WIRE_INCORRECT_OR_UNKNOWN_PAYMENT_DETAILS: lightningd/htlc_set.c:113' b'2020-07-20T05:40:15.536Z DEBUG 035d2b1192dfba134e10e540875d366ebc8bc353d5aa766b80c090b39c3a5d885d-chan#1: HTLC in 1 RCVD_ADD_ACK_REVOCATION->SENT_REMOVE_HTLC' b'2020-07-20T05:40:15.541Z DEBUG lightningd: Attept to pay 528691fdf7baf0043ef2305e504988a5ae510dcb6127b463b3103b40c2b82a87 with amount 9048144msat < 500000000msat' b'2020-07-20T05:40:15.541Z DEBUG lightningd: WIRE_INCORRECT_OR_UNKNOWN_PAYMENT_DETAILS: lightningd/htlc_set.c:113' b'2020-07-20T05:40:15.541Z DEBUG 035d2b1192dfba134e10e540875d366ebc8bc353d5aa766b80c090b39c3a5d885d-chan#1: HTLC in 7 RCVD_ADD_ACK_REVOCATION->SENT_REMOVE_HTLC' b'2020-07-20T05:40:15.544Z DEBUG lightningd: Attept to pay 528691fdf7baf0043ef2305e504988a5ae510dcb6127b463b3103b40c2b82a87 with amount 10858167msat < 500000000msat' b'2020-07-20T05:40:15.544Z DEBUG lightningd: WIRE_INCORRECT_OR_UNKNOWN_PAYMENT_DETAILS: lightningd/htlc_set.c:113' b'2020-07-20T05:40:15.544Z DEBUG 035d2b1192dfba134e10e540875d366ebc8bc353d5aa766b80c090b39c3a5d885d-chan#1: HTLC in 9 RCVD_ADD_ACK_REVOCATION->SENT_REMOVE_HTLC' b'2020-07-20T05:40:15.548Z DEBUG lightningd: Attept to pay 528691fdf7baf0043ef2305e504988a5ae510dcb6127b463b3103b40c2b82a87 with amount 10137155msat < 500000000msat' b'2020-07-20T05:40:15.548Z DEBUG lightningd: WIRE_INCORRECT_OR_UNKNOWN_PAYMENT_DETAILS: lightningd/htlc_set.c:113' b'2020-07-20T05:40:15.548Z DEBUG 035d2b1192dfba134e10e540875d366ebc8bc353d5aa766b80c090b39c3a5d885d-chan#1: HTLC in 2 RCVD_ADD_ACK_REVOCATION->SENT_REMOVE_HTLC' b'2020-07-20T05:40:15.551Z DEBUG lightningd: Attept to pay 528691fdf7baf0043ef2305e504988a5ae510dcb6127b463b3103b40c2b82a87 with amount 10002298msat < 500000000msat' b'2020-07-20T05:40:15.551Z DEBUG lightningd: WIRE_INCORRECT_OR_UNKNOWN_PAYMENT_DETAILS: lightningd/htlc_set.c:113' b'2020-07-20T05:40:15.551Z DEBUG 035d2b1192dfba134e10e540875d366ebc8bc353d5aa766b80c090b39c3a5d885d-chan#1: HTLC in 4 RCVD_ADD_ACK_REVOCATION->SENT_REMOVE_HTLC' b'2020-07-20T05:40:15.554Z DEBUG 035d2b1192dfba134e10e540875d366ebc8bc353d5aa766b80c090b39c3a5d885d-channeld-chan#1: NEW:: HTLC REMOTE 14 = RCVD_ADD_HTLC/SENT_ADD_HTLC' b'2020-07-20T05:40:15.554Z DEBUG 035d2b1192dfba134e10e540875d366ebc8bc353d5aa766b80c090b39c3a5d885d-channeld-chan#1: peer_in WIRE_UPDATE_ADD_HTLC' b'2020-07-20T05:40:15.554Z DEBUG 035d2b1192dfba134e10e540875d366ebc8bc353d5aa766b80c090b39c3a5d885d-channeld-chan#1: NEW:: HTLC REMOTE 15 = RCVD_ADD_HTLC/SENT_ADD_HTLC' b'2020-07-20T05:40:15.554Z DEBUG 035d2b1192dfba134e10e540875d366ebc8bc353d5aa766b80c090b39c3a5d885d-channeld-chan#1: peer_in WIRE_UPDATE_ADD_HTLC' b'2020-07-20T05:40:15.554Z DEBUG 035d2b1192dfba134e10e540875d366ebc8bc353d5aa766b80c090b39c3a5d885d-channeld-chan#1: NEW:: HTLC REMOTE 16 = RCVD_ADD_HTLC/SENT_ADD_HTLC' --- lightningd/invoice.c | 22 +++++++++++++++++++-- lightningd/peer_htlcs.c | 9 ++++++--- lightningd/peer_htlcs.h | 10 +++++++--- lightningd/test/run-invoice-select-inchan.c | 11 ++++++----- 4 files changed, 39 insertions(+), 13 deletions(-) diff --git a/lightningd/invoice.c b/lightningd/invoice.c index 866f054f6..87ef0e31d 100644 --- a/lightningd/invoice.c +++ b/lightningd/invoice.c @@ -302,8 +302,15 @@ invoice_check_payment(const tal_t *ctx, * - MUST fail the HTLC. * - MUST return an `incorrect_or_unknown_payment_details` error. */ - if (!wallet_invoice_find_unpaid(ld->wallet, &invoice, payment_hash)) + if (!wallet_invoice_find_unpaid(ld->wallet, &invoice, payment_hash)) { + log_debug(ld->log, "Unknown paid invoice %s", + type_to_string(tmpctx, struct sha256, payment_hash)); + if (wallet_invoice_find_by_rhash(ld->wallet, &invoice, payment_hash)) { + log_debug(ld->log, "ALREADY paid invoice %s", + type_to_string(tmpctx, struct sha256, payment_hash)); + } return NULL; + } details = wallet_invoice_details(ctx, ld->wallet, invoice); @@ -342,11 +349,22 @@ invoice_check_payment(const tal_t *ctx, if (details->msat != NULL) { struct amount_msat twice; - if (amount_msat_less(msat, *details->msat)) + if (amount_msat_less(msat, *details->msat)) { + log_debug(ld->log, "Attept to pay %s with amount %s < %s", + type_to_string(tmpctx, struct sha256, + &details->rhash), + type_to_string(tmpctx, struct amount_msat, &msat), + type_to_string(tmpctx, struct amount_msat, details->msat)); return tal_free(details); + } if (amount_msat_add(&twice, *details->msat, *details->msat) && amount_msat_greater(msat, twice)) { + log_debug(ld->log, "Attept to pay %s with amount %s > %s", + type_to_string(tmpctx, struct sha256, + &details->rhash), + type_to_string(tmpctx, struct amount_msat, details->msat), + type_to_string(tmpctx, struct amount_msat, &twice)); /* BOLT #4: * * - if the amount paid is more than twice the amount diff --git a/lightningd/peer_htlcs.c b/lightningd/peer_htlcs.c index 641a325b2..3d6a0eead 100644 --- a/lightningd/peer_htlcs.c +++ b/lightningd/peer_htlcs.c @@ -283,10 +283,13 @@ void local_fail_in_htlc_needs_update(struct htlc_in *hin, } /* Helper to create (common) WIRE_INCORRECT_OR_UNKNOWN_PAYMENT_DETAILS */ -const u8 *failmsg_incorrect_or_unknown(const tal_t *ctx, - struct lightningd *ld, - const struct htlc_in *hin) +const u8 *failmsg_incorrect_or_unknown_(const tal_t *ctx, + struct lightningd *ld, + const struct htlc_in *hin, + const char *file, int line) { + log_debug(ld->log, "WIRE_INCORRECT_OR_UNKNOWN_PAYMENT_DETAILS: %s:%u", + file, line); return towire_incorrect_or_unknown_payment_details( ctx, hin->msat, get_block_height(ld->topology)); diff --git a/lightningd/peer_htlcs.h b/lightningd/peer_htlcs.h index c24f76555..6d786c510 100644 --- a/lightningd/peer_htlcs.h +++ b/lightningd/peer_htlcs.h @@ -81,7 +81,11 @@ void json_format_forwarding_object(struct json_stream *response, const char *fie const struct forwarding *cur); /* Helper to create (common) WIRE_INCORRECT_OR_UNKNOWN_PAYMENT_DETAILS */ -const u8 *failmsg_incorrect_or_unknown(const tal_t *ctx, - struct lightningd *ld, - const struct htlc_in *hin); +#define failmsg_incorrect_or_unknown(ctx, ld, hin) \ + failmsg_incorrect_or_unknown_((ctx), (ld), (hin), __FILE__, __LINE__) + +const u8 *failmsg_incorrect_or_unknown_(const tal_t *ctx, + struct lightningd *ld, + const struct htlc_in *hin, + const char *file, int line); #endif /* LIGHTNING_LIGHTNINGD_PEER_HTLCS_H */ diff --git a/lightningd/test/run-invoice-select-inchan.c b/lightningd/test/run-invoice-select-inchan.c index e7d426b0c..1d8e4ba9d 100644 --- a/lightningd/test/run-invoice-select-inchan.c +++ b/lightningd/test/run-invoice-select-inchan.c @@ -88,11 +88,12 @@ char *encode_scriptpubkey_to_addr(const tal_t *ctx UNNEEDED, const struct chainparams *chainparams UNNEEDED, const u8 *scriptPubkey UNNEEDED) { fprintf(stderr, "encode_scriptpubkey_to_addr called!\n"); abort(); } -/* Generated stub for failmsg_incorrect_or_unknown */ -const u8 *failmsg_incorrect_or_unknown(const tal_t *ctx UNNEEDED, - struct lightningd *ld UNNEEDED, - const struct htlc_in *hin UNNEEDED) -{ fprintf(stderr, "failmsg_incorrect_or_unknown called!\n"); abort(); } +/* Generated stub for failmsg_incorrect_or_unknown_ */ +const u8 *failmsg_incorrect_or_unknown_(const tal_t *ctx UNNEEDED, + struct lightningd *ld UNNEEDED, + const struct htlc_in *hin UNNEEDED, + const char *file UNNEEDED, int line UNNEEDED) +{ fprintf(stderr, "failmsg_incorrect_or_unknown_ called!\n"); abort(); } /* Generated stub for fatal */ void fatal(const char *fmt UNNEEDED, ...) { fprintf(stderr, "fatal called!\n"); abort(); }