diff --git a/plugins/libplugin-pay.c b/plugins/libplugin-pay.c index 5e4608117..30f4b0f7b 100644 --- a/plugins/libplugin-pay.c +++ b/plugins/libplugin-pay.c @@ -13,6 +13,9 @@ struct payment *payment_new(tal_t *ctx, struct command *cmd, struct payment_modifier **mods) { struct payment *p = tal(ctx, struct payment); + + static u64 next_id = 0; + p->children = tal_arr(p, struct payment *, 0); p->parent = parent; p->modifiers = mods; @@ -46,6 +49,7 @@ struct payment *payment_new(tal_t *ctx, struct command *cmd, p->deadline = parent->deadline; p->invoice = parent->invoice; + p->id = parent->id; } else { assert(cmd != NULL); p->partid = 0; @@ -53,6 +57,7 @@ struct payment *payment_new(tal_t *ctx, struct command *cmd, p->plugin = cmd->plugin; p->channel_hints = tal_arr(p, struct channel_hint, 0); p->excluded_nodes = tal_arr(p, struct node_id, 0); + p->id = next_id++; } /* Initialize all modifier data so we can point to the fields when @@ -79,6 +84,59 @@ struct payment *payment_root(struct payment *p) return payment_root(p->parent); } +static void +paymod_log_header(struct payment *p, const char **type, u64 *id) +{ + struct payment *root = payment_root(p); + /* We prefer to show the command ID here since it is also known + * by `lightningd`, so in theory it can be used to correlate + * debugging logs between the main `lightningd` and whatever + * plugin is using the paymod system. + * We only fall back to a unique id per root payment if there + * is no command with an id associated with this payment. + */ + if (root->cmd && root->cmd->id) { + *type = "cmd"; + *id = *root->cmd->id; + } else { + *type = "id"; + *id = root->id; + } +} + +static void +paymod_log(struct payment *p, enum log_level l, const char *fmt, ...) +{ + const char *type; + u64 id; + char *txt; + va_list ap; + + va_start(ap, fmt); + txt = tal_vfmt(tmpctx, fmt, ap); + va_end(ap); + + paymod_log_header(p, &type, &id); + plugin_log(p->plugin, l, "%s %"PRIu64" partid %"PRIu32": %s", + type, id, p->partid, txt); +} +static void +paymod_err(struct payment *p, const char *fmt, ...) +{ + const char *type; + u64 id; + char *txt; + va_list ap; + + va_start(ap, fmt); + txt = tal_vfmt(tmpctx, fmt, ap); + va_end(ap); + + paymod_log_header(p, &type, &id); + plugin_err(p->plugin, "%s %"PRIu64" partid %"PRIu32": %s", + type, id, p->partid, txt); +} + /* Generic handler for RPC failures that should end up failing the payment. */ static struct command_result *payment_rpc_failure(struct command *cmd, const char *buffer, @@ -119,8 +177,8 @@ struct payment_tree_result payment_collect_result(struct payment *p) /* Some of our subpayments have succeeded, aggregate how much * we sent in total. */ if (!amount_msat_add(&res.sent, res.sent, cres.sent)) - plugin_err( - p->plugin, + paymod_err( + p, "Number overflow summing partial payments: %s + %s", type_to_string(tmpctx, struct amount_msat, &res.sent), @@ -228,8 +286,8 @@ static void channel_hints_update(struct payment *p, tal_arr_expand(&root->channel_hints, hint); - plugin_log( - root->plugin, LOG_DBG, + paymod_log( + p, LOG_DBG, "Added a channel hint for %s: enabled %s, estimated capacity %s", type_to_string(tmpctx, struct short_channel_id_dir, &hint.scid), hint.enabled ? "true" : "false", @@ -244,7 +302,7 @@ static void payment_exclude_most_expensive(struct payment *p) for (size_t i = 0; i < tal_count(p->route)-1; i++) { if (!amount_msat_sub(&fee, p->route[i].amount, p->route[i+1].amount)) - plugin_err(p->plugin, "Negative fee in a route."); + paymod_err(p, "Negative fee in a route."); if (amount_msat_greater_eq(fee, worst)) { e = &p->route[i]; @@ -275,8 +333,8 @@ static struct amount_msat payment_route_fee(struct payment *p) { struct amount_msat fee; if (!amount_msat_sub(&fee, p->route[0].amount, p->amount)) { - plugin_log( - p->plugin, + paymod_log( + p, LOG_BROKEN, "gossipd returned a route with a negative fee: sending %s " "to deliver %s", @@ -353,8 +411,8 @@ static void payment_chanhints_apply_route(struct payment *p, bool remove) * concurrent getroute calls using the * same channel_hints, no biggy, it's * an estimation anyway. */ - plugin_log( - p->plugin, LOG_UNUSUAL, + paymod_log( + p, LOG_UNUSUAL, "Could not update the channel hint " "for %s. Could be a concurrent " "`getroute` call.", @@ -405,7 +463,7 @@ static struct command_result *payment_getroute_result(struct command *cmd, /* Now update the constraints in fee_budget and cltv_budget so * modifiers know what constraints they need to adhere to. */ if (!payment_constraints_update(&p->constraints, fee, p->route[0].delay)) { - plugin_log(p->plugin, LOG_BROKEN, + paymod_log(p, LOG_BROKEN, "Could not update constraints."); abort(); } @@ -704,13 +762,13 @@ static void report_tampering(struct payment *p, const struct node_id *id = &p->route[report_pos].nodeid; if (report_pos == 0) { - plugin_log(p->plugin, LOG_UNUSUAL, + paymod_log(p, LOG_UNUSUAL, "Node #%zu (%s) claimed we sent them invalid %s", report_pos + 1, type_to_string(tmpctx, struct node_id, id), style); } else { - plugin_log(p->plugin, LOG_UNUSUAL, + paymod_log(p, LOG_UNUSUAL, "Node #%zu (%s) claimed #%zu (%s) sent them invalid %s", report_pos + 1, type_to_string(tmpctx, struct node_id, id), @@ -760,7 +818,7 @@ handle_final_failure(struct command *cmd, * otherwise we would set the abort flag too eagerly. */ if (failure_is_blockheight_disagreement(p, &unused)) { - plugin_log(p->plugin, LOG_DBG, + paymod_log(p, LOG_DBG, "Blockheight disagreement, not aborting."); goto nonerror; } @@ -834,7 +892,7 @@ handle_final_failure(struct command *cmd, } strange_error: - plugin_log(p->plugin, LOG_UNUSUAL, + paymod_log(p, LOG_UNUSUAL, "Final node %s reported strange error code %u", type_to_string(tmpctx, struct node_id, final_id), failcode); @@ -924,7 +982,7 @@ handle_intermediate_failure(struct command *cmd, } strange_error: - plugin_log(p->plugin, LOG_UNUSUAL, + paymod_log(p, LOG_UNUSUAL, "Intermediate node %s reported strange error code %u", type_to_string(tmpctx, struct node_id, errnode), failcode); @@ -988,7 +1046,7 @@ payment_waitsendpay_finished(struct command *cmd, const char *buffer, p->result = tal_sendpay_result_from_json(p, buffer, toks); if (p->result == NULL) { - plugin_log(p->plugin, LOG_UNUSUAL, + paymod_log(p, LOG_UNUSUAL, "Unable to parse `waitsendpay` result: %.*s", json_tok_full_len(toks), json_tok_full(buffer, toks)); @@ -1008,7 +1066,7 @@ payment_waitsendpay_finished(struct command *cmd, const char *buffer, payment_chanhints_apply_route(p, true); if (!assign_blame(p, &errnode, &errchan)) { - plugin_log(p->plugin, LOG_UNUSUAL, + paymod_log(p, LOG_UNUSUAL, "No erring_index set in `waitsendpay` result: %.*s", json_tok_full_len(toks), json_tok_full(buffer, toks)); @@ -1525,7 +1583,7 @@ void payment_fail(struct payment *p, const char *fmt, ...) p->failreason = tal_vfmt(p, fmt, ap); va_end(ap); - plugin_log(p->plugin, LOG_INFORM, "%s", p->failreason); + paymod_log(p, LOG_INFORM, "%s", p->failreason); payment_continue(p); } @@ -1633,8 +1691,8 @@ static inline void retry_step_cb(struct retry_mod_data *rd, return payment_continue(p); if (time_after(now, p->deadline)) { - plugin_log( - p->plugin, LOG_INFORM, + paymod_log( + p, LOG_INFORM, "Payment deadline expired, not retrying (partial-)payment " "%s/%d", type_to_string(tmpctx, struct sha256, p->payment_hash), @@ -1663,8 +1721,8 @@ static inline void retry_step_cb(struct retry_mod_data *rd, subpayment->why = tal_fmt(subpayment, "Still have %d attempts left", rdata->retries - 1); - plugin_log( - p->plugin, LOG_DBG, + paymod_log( + p, LOG_DBG, "Retrying %s/%d (%s), new partid %d. %d attempts left\n", type_to_string(tmpctx, struct sha256, p->payment_hash), p->partid, @@ -1990,8 +2048,8 @@ static void routehint_pre_getroute(struct routehints_data *d, struct payment *p) p->getroute->cltv = route_cltv(p->getroute->cltv, d->current_routehint, tal_count(d->current_routehint)); - plugin_log( - p->plugin, LOG_DBG, "Using routehint %s (%s) cltv_delta=%d", + paymod_log( + p, LOG_DBG, "Using routehint %s (%s) cltv_delta=%d", type_to_string(tmpctx, struct node_id, &d->current_routehint->pubkey), type_to_string(tmpctx, struct short_channel_id, @@ -2002,7 +2060,7 @@ static void routehint_pre_getroute(struct routehints_data *d, struct payment *p) * going through the destination to the entrypoint. */ p->temp_exclusion = routehint_generate_exclusion_list(p, d->current_routehint, p); } else - plugin_log(p->plugin, LOG_DBG, "Not using a routehint"); + paymod_log(p, LOG_DBG, "Not using a routehint"); } static struct command_result *routehint_getroute_result(struct command *cmd, @@ -2023,7 +2081,7 @@ static struct command_result *routehint_getroute_result(struct command *cmd, routehint_pre_getroute(d, p); - plugin_log(p->plugin, LOG_DBG, + paymod_log(p, LOG_DBG, "The destination is%s directly reachable %s attempts " "without routehints", d->destination_reachable ? "" : " not", @@ -2051,7 +2109,7 @@ static void routehint_check_reachable(struct payment *p) json_add_num(req->js, "maxhops", 20); json_add_num(req->js, "riskfactor", 10); send_outreq(p->plugin, req); - plugin_log(p->plugin, LOG_DBG, + paymod_log(p, LOG_DBG, "Asking gossipd whether %s is reachable " "without routehints.", type_to_string(tmpctx, struct node_id, p->destination)); @@ -2073,7 +2131,7 @@ static void routehint_step_cb(struct routehints_data *d, struct payment *p) d->routehints = filter_routehints(d, p->local_id, p->invoice->routes); - plugin_log(p->plugin, LOG_DBG, + paymod_log(p, LOG_DBG, "After filtering routehints we're left with " "%zu usable hints", tal_count(d->routehints)); @@ -2176,8 +2234,8 @@ static void exemptfee_cb(struct exemptfee_data *d, struct payment *p) return payment_continue(p); if (amount_msat_greater_eq(d->amount, p->constraints.fee_budget)) { - plugin_log( - p->plugin, LOG_INFORM, + paymod_log( + p, LOG_INFORM, "Payment fee constraint %s is below exemption threshold, " "allowing a maximum fee of %s", type_to_string(tmpctx, struct amount_msat, &p->constraints.fee_budget), @@ -2343,8 +2401,8 @@ static struct command_result *shadow_route_listchannels(struct command *cmd, } /* Now we can be sure that adding the shadow route will succeed */ - plugin_log( - p->plugin, LOG_DBG, + paymod_log( + p, LOG_DBG, "Adding shadow_route hop over channel %s: adding %s " "in fees and %d CLTV delta", type_to_string(tmpctx, struct short_channel_id, @@ -2368,7 +2426,7 @@ static struct command_result *shadow_route_listchannels(struct command *cmd, d->constraints.fee_budget, best_fee) || !amount_msat_sub(&p->constraints.fee_budget, p->constraints.fee_budget, best_fee)) - plugin_err(p->plugin, + paymod_err(p, "Could not update fee constraints " "for shadow route extension. " "payment fee budget %s, modifier " @@ -2455,7 +2513,7 @@ static void direct_pay_override(struct payment *p) { p->route[0].direction = hint->scid.dir; p->route[0].nodeid = *p->destination; p->route[0].style = ROUTE_HOP_TLV; - plugin_log(p->plugin, LOG_DBG, + paymod_log(p, LOG_DBG, "Found a direct channel (%s) with sufficient " "capacity, skipping route computation.", type_to_string(tmpctx, struct short_channel_id_dir, @@ -2565,7 +2623,7 @@ static void waitblockheight_cb(void *d, struct payment *p) if (!failure_is_blockheight_disagreement(p, &blockheight)) return payment_continue(p); - plugin_log(p->plugin, LOG_INFORM, + paymod_log(p, LOG_INFORM, "Remote node appears to be on a longer chain, which causes " "CLTV timeouts to be incorrect. Waiting up to %" PRIu64 " seconds to catch up to block %d before retrying.", @@ -2742,8 +2800,8 @@ static void presplit_cb(struct presplit_mod_data *d, struct payment *p) c->amount = fuzzed_near(target, amt); if (!amount_msat_sub(&amt, amt, c->amount)) - plugin_err( - p->plugin, + paymod_err( + p, "Cannot subtract %s from %s in splitter", type_to_string(tmpctx, struct amount_msat, &c->amount), @@ -2769,7 +2827,7 @@ static void presplit_cb(struct presplit_mod_data *d, struct payment *p) count, type_to_string(tmpctx, struct amount_msat, &root->amount), type_to_string(tmpctx, struct amount_msat, &target)); - plugin_log(p->plugin, LOG_INFORM, "%s", p->why); + paymod_log(p, LOG_INFORM, "%s", p->why); } payment_continue(p); } @@ -2900,7 +2958,7 @@ static void adaptive_splitter_cb(struct adaptive_split_mod_data *d, struct payme * may end up using an HTLC. */ root_data->htlc_budget--; } else { - plugin_log(p->plugin, LOG_INFORM, + paymod_log(p, LOG_INFORM, "Lower limit of adaptive splitter reached " "(%s < %s), not splitting further.", type_to_string(tmpctx, struct amount_msat, diff --git a/plugins/libplugin-pay.h b/plugins/libplugin-pay.h index a8a2ebef6..d6f844760 100644 --- a/plugins/libplugin-pay.h +++ b/plugins/libplugin-pay.h @@ -262,6 +262,9 @@ struct payment { * if we switch any of the parameters such as destination or * amount. */ bool failroute_retry; + + /* A unique id for the root of this payment. */ + u64 id; }; struct payment_modifier {