diff --git a/plugins/renepay/flow.c b/plugins/renepay/flow.c index 90708844a964..a6c32545b72a 100644 --- a/plugins/renepay/flow.c +++ b/plugins/renepay/flow.c @@ -48,6 +48,52 @@ const char *fmt_chan_extra_map( return buff; } +const char *fmt_chan_extra_details(const tal_t *ctx, + struct chan_extra_map* chan_extra_map, + const struct short_channel_id_dir *scidd) +{ + const struct chan_extra *ce = chan_extra_map_get(chan_extra_map, + scidd->scid); + const struct chan_extra_half *ch; + char *str = tal_strdup(ctx, ""); + char sep = '('; + + if (!ce) + return str; + + ch = &ce->half[scidd->dir]; + if (ch->num_htlcs != 0) { + tal_append_fmt(&str, "%c%s in %zu htlcs", + sep, + fmt_amount_msat(tmpctx, ch->htlc_total), + ch->num_htlcs); + sep = ','; + } + /* Happens with local channels, where we're certain. */ + if (amount_msat_eq(ch->known_min, ch->known_max)) { + tal_append_fmt(&str, "%cmin=max=%s", + sep, + fmt_amount_msat(tmpctx, ch->known_min)); + sep = ','; + } else { + if (amount_msat_greater(ch->known_min, AMOUNT_MSAT(0))) { + tal_append_fmt(&str, "%cmin=%s", + sep, + fmt_amount_msat(tmpctx, ch->known_min)); + sep = ','; + } + if (!amount_msat_eq(ch->known_max, ce->capacity)) { + tal_append_fmt(&str, "%cmax=%s", + sep, + fmt_amount_msat(tmpctx, ch->known_max)); + sep = ','; + } + } + if (!streq(str, "")) + tal_append_fmt(&str, ")"); + return str; +} + struct chan_extra *new_chan_extra( struct chan_extra_map *chan_extra_map, const struct short_channel_id scid, @@ -145,12 +191,12 @@ void chan_extra_can_send( /* Update the knowledge that this (channel,direction) cannot send.*/ void chan_extra_cannot_send( - struct payment *p, + struct pay_flow *pf, struct chan_extra_map *chan_extra_map, const struct short_channel_id_dir *scidd, struct amount_msat sent) { - struct amount_msat x; + struct amount_msat oldmin, oldmax, x; struct chan_extra *ce = chan_extra_map_get(chan_extra_map, scidd->scid); if(!ce) @@ -170,20 +216,23 @@ void chan_extra_cannot_send( x = AMOUNT_MSAT(0); } + oldmin = ce->half[scidd->dir].known_min; + oldmax = ce->half[scidd->dir].known_max; + /* If we "knew" the capacity was at least this, we just showed we're wrong! */ - if (amount_msat_less(x, ce->half[scidd->dir].known_min)) { - debug_paynote(p, "Expected scid=%s min %s, but %s failed! Setting min to 0", - type_to_string(tmpctx,struct short_channel_id_dir,scidd), - type_to_string(tmpctx,struct amount_msat,&ce->half[scidd->dir].known_min), - type_to_string(tmpctx,struct amount_msat,&x)); + if (amount_msat_less(x, ce->half[scidd->dir].known_min)) ce->half[scidd->dir].known_min = AMOUNT_MSAT(0); - } + ce->half[scidd->dir].known_max = amount_msat_min(ce->half[scidd->dir].known_max,x); - debug_paynote(p,"Update chan knowledge scid=%s: [%s,%s]", - type_to_string(tmpctx,struct short_channel_id_dir,scidd), - type_to_string(tmpctx,struct amount_msat,&ce->half[scidd->dir].known_min), - type_to_string(tmpctx,struct amount_msat,&ce->half[scidd->dir].known_max)); + payflow_note(pf, LOG_INFORM, + "Failure of %s for %s capacity [%s,%s] -> [%s,%s]", + fmt_amount_msat(tmpctx, sent), + type_to_string(tmpctx,struct short_channel_id_dir,scidd), + fmt_amount_msat(tmpctx, oldmin), + fmt_amount_msat(tmpctx, oldmax), + fmt_amount_msat(tmpctx, ce->half[scidd->dir].known_min), + fmt_amount_msat(tmpctx, ce->half[scidd->dir].known_max)); chan_extra_adjust_half(ce,!scidd->dir); } @@ -223,11 +272,20 @@ void chan_extra_set_liquidity( chan_extra_set_liquidity_(ce,scidd->dir,x); } /* Update the knowledge that this (channel,direction) has sent x msat.*/ -static void chan_extra_sent_success_( - struct chan_extra *ce, - int dir, +void chan_extra_sent_success( + struct pay_flow *pf, + struct chan_extra_map *chan_extra_map, + const struct short_channel_id_dir *scidd, struct amount_msat x) { + struct chan_extra *ce = chan_extra_map_get(chan_extra_map, + scidd->scid); + if(!ce) + { + debug_err("%s unexpected chan_extra ce is NULL", + __PRETTY_FUNCTION__); + } + if(amount_msat_greater(x,ce->capacity)) { debug_err("%s unexpected capacity=%s is less than x=%s", @@ -240,29 +298,24 @@ static void chan_extra_sent_success_( struct amount_msat new_a, new_b; - if(!amount_msat_sub(&new_a,ce->half[dir].known_min,x)) + if(!amount_msat_sub(&new_a,ce->half[scidd->dir].known_min,x)) new_a = AMOUNT_MSAT(0); - if(!amount_msat_sub(&new_b,ce->half[dir].known_max,x)) + if(!amount_msat_sub(&new_b,ce->half[scidd->dir].known_max,x)) new_b = AMOUNT_MSAT(0); - ce->half[dir].known_min = new_a; - ce->half[dir].known_max = new_b; + payflow_note(pf, LOG_DBG, + "Success of %s for %s capacity [%s,%s] -> [%s,%s]", + fmt_amount_msat(tmpctx, x), + type_to_string(tmpctx,struct short_channel_id_dir,scidd), + fmt_amount_msat(tmpctx, ce->half[scidd->dir].known_min), + fmt_amount_msat(tmpctx, ce->half[scidd->dir].known_max), + fmt_amount_msat(tmpctx, new_a), + fmt_amount_msat(tmpctx, new_b)); - chan_extra_adjust_half(ce,!dir); -} -void chan_extra_sent_success( - struct chan_extra_map *chan_extra_map, - const struct short_channel_id_dir *scidd, - struct amount_msat x) -{ - struct chan_extra *ce = chan_extra_map_get(chan_extra_map, - scidd->scid); - if(!ce) - { - debug_err("%s unexpected chan_extra ce is NULL", - __PRETTY_FUNCTION__); - } - chan_extra_sent_success_(ce,scidd->dir,x); + ce->half[scidd->dir].known_min = new_a; + ce->half[scidd->dir].known_max = new_b; + + chan_extra_adjust_half(ce,!scidd->dir); } /* Forget a bit about this (channel,direction) state. */ static void chan_extra_relax_( diff --git a/plugins/renepay/flow.h b/plugins/renepay/flow.h index 378be7b26131..0ee448a30efd 100644 --- a/plugins/renepay/flow.h +++ b/plugins/renepay/flow.h @@ -118,6 +118,12 @@ const char *fmt_chan_extra_map( const tal_t *ctx, struct chan_extra_map* chan_extra_map); +/* Returns "" if nothing useful known about channel, otherwise + * "(details)" */ +const char *fmt_chan_extra_details(const tal_t *ctx, + struct chan_extra_map* chan_extra_map, + const struct short_channel_id_dir *scidd); + /* Creates a new chan_extra and adds it to the chan_extra_map. */ struct chan_extra *new_chan_extra( struct chan_extra_map *chan_extra_map, @@ -152,7 +158,7 @@ void chan_extra_can_send(struct chan_extra_map *chan_extra_map, struct amount_msat x); /* Update the knowledge that this (channel,direction) cannot send x msat.*/ -void chan_extra_cannot_send(struct payment* p, +void chan_extra_cannot_send(struct pay_flow* pf, struct chan_extra_map *chan_extra_map, const struct short_channel_id_dir *scidd, struct amount_msat x); @@ -163,7 +169,8 @@ void chan_extra_set_liquidity(struct chan_extra_map *chan_extra_map, struct amount_msat x); /* Update the knowledge that this (channel,direction) has sent x msat.*/ -void chan_extra_sent_success(struct chan_extra_map *chan_extra_map, +void chan_extra_sent_success(struct pay_flow *pf, + struct chan_extra_map *chan_extra_map, const struct short_channel_id_dir *scidd, struct amount_msat x); diff --git a/plugins/renepay/pay.c b/plugins/renepay/pay.c index 300644e51559..25aed947e523 100644 --- a/plugins/renepay/pay.c +++ b/plugins/renepay/pay.c @@ -121,12 +121,8 @@ static struct pf_result *handle_unhandleable_error(struct pay_flow *pf, size_t n = tal_count(pf); /* We got a mangled reply. We don't know who to penalize! */ - debug_paynote(pf->payment, "%s on route %s", what, flow_path_to_str(tmpctx, pf)); - - // TODO(eduardo): does LOG_BROKEN finish the plugin execution? - plugin_log(pay_plugin->plugin, LOG_BROKEN, - "%s on route %s", - what, flow_path_to_str(tmpctx, pf)); + payflow_note(pf, LOG_UNUSUAL, "%s on route %s", + what, flow_path_to_str(tmpctx, pf)); if (n == 1) { @@ -145,9 +141,9 @@ static struct pf_result *handle_unhandleable_error(struct pay_flow *pf, n = pseudorand(n-1); tal_arr_expand(&pf->payment->disabled, pf->path_scidds[n].scid); - debug_paynote(pf->payment, "... eliminated %s", - type_to_string(tmpctx, struct short_channel_id, - &pf->path_scidds[n].scid)); + payflow_note(pf, LOG_DBG, "... eliminated %s", + type_to_string(tmpctx, struct short_channel_id, + &pf->path_scidds[n].scid)); return pay_flow_failed(pf); } @@ -182,9 +178,10 @@ static struct command_result *addgossip_failure(struct command *cmd, struct payment * payment = adg->pf->payment; plugin_log(pay_plugin->plugin,LOG_DBG,"calling %s",__PRETTY_FUNCTION__); - debug_paynote(payment, "addgossip failed, removing channel %s (%.*s)", - type_to_string(tmpctx, struct short_channel_id, &adg->scid), - err->end - err->start, buf + err->start); + payflow_note(adg->pf, LOG_UNUSUAL, + "addgossip failed, removing channel %s (%.*s)", + type_to_string(tmpctx, struct short_channel_id, &adg->scid), + err->end - err->start, buf + err->start); tal_arr_expand(&payment->disabled, adg->scid); return addgossip_done(cmd, buf, err, adg); @@ -195,7 +192,6 @@ static struct pf_result *submit_update(struct pay_flow *pf, struct short_channel_id errscid) { plugin_log(pay_plugin->plugin,LOG_DBG,"calling %s",__PRETTY_FUNCTION__); - struct payment *payment = pf->payment; struct out_req *req; struct addgossip *adg = tal(pf, struct addgossip); @@ -204,8 +200,7 @@ static struct pf_result *submit_update(struct pay_flow *pf, adg->scid = errscid; adg->pf = pf; - debug_paynote(payment, "... extracted channel_update, telling gossipd"); - plugin_log(pay_plugin->plugin, LOG_DBG, "(update = %s)", tal_hex(tmpctx, update)); + payflow_note(pf, LOG_DBG, "... extracted channel_update %s, telling gossipd", tal_hex(tmpctx, update)); req = jsonrpc_request_start(pay_plugin->plugin, NULL, "addgossip", addgossip_done, @@ -312,8 +307,8 @@ static struct command_result *flow_sendpay_failed(struct command *cmd, plugin_err(cmd->plugin, "Strange error from sendpay: %.*s", json_tok_full_len(err), json_tok_full(buf, err)); - debug_paynote(payment, - "sendpay didn't like first hop, eliminated: %s", msg) + payflow_note(pf, LOG_INFORM, + "sendpay didn't like first hop, eliminated: %s", msg); /* There is no new knowledge from this kind of failure. * We just disable this scid. */ @@ -329,15 +324,11 @@ static void sendpay_new_flows(struct payment *p) struct pay_flow *pf; list_for_each(&p->flows, pf, list) { + struct out_req *req; + if (pf->state != PAY_FLOW_NOT_STARTED) continue; - debug_paynote(p, "sendpay flow groupid=%"PRIu64", partid=%"PRIu64", delivering=%s, probability=%.3lf", - pf->key.groupid, - pf->key.partid, - fmt_amount_msat(tmpctx, payflow_delivered(pf)), - pf->success_prob); - struct out_req *req; /* FIXME: We don't actually want cmd to own this sendpay, so we use NULL here, * but we should use a variant which allows us to set json id! */ req = jsonrpc_request_start(pay_plugin->plugin, NULL, "sendpay", @@ -1163,18 +1154,6 @@ static void handle_sendpay_failure_flow(struct pay_flow *pf, { debug_assert(pf); - struct payment * const p = pf->payment; - - plugin_log(pay_plugin->plugin, LOG_UNUSUAL, - "onion error %s from node #%u %s: " - "%s", - onion_wire_name(onionerr), - erridx, - erridx == tal_count(pf->path_scidds) - ? "final" - : type_to_string(tmpctx, struct short_channel_id_dir, &pf->path_scidds[erridx]), - msg); - /* we know that all channels before erridx where able to commit to this payment */ uncertainty_network_channel_can_send( pay_plugin->chan_extra_map, @@ -1185,10 +1164,7 @@ static void handle_sendpay_failure_flow(struct pay_flow *pf, if((enum onion_wire)onionerr == WIRE_TEMPORARY_CHANNEL_FAILURE && erridx < tal_count(pf->path_scidds)) { - plugin_log(pay_plugin->plugin,LOG_DBG, - "sendpay_failure says insufficient funds!"); - - chan_extra_cannot_send(p,pay_plugin->chan_extra_map, + chan_extra_cannot_send(pf,pay_plugin->chan_extra_map, &pf->path_scidds[erridx], pf->amounts[erridx]); } @@ -1244,6 +1220,8 @@ static struct command_result *notification_sendpay_success( json_tok_full(buf, params)); } + payflow_note(pf, LOG_INFORM, "Success"); + // 2. update information uncertainty_network_flow_success(pay_plugin->chan_extra_map, pf); @@ -1302,6 +1280,8 @@ static struct pf_result *sendpay_failure(struct pay_flow *pf, flow_path_to_str(tmpctx, pf)); } + payflow_note(pf, LOG_INFORM, "Failed at node #%u (%s): %s", + erridx, onion_wire_name(onionerr), msg); handle_sendpay_failure_flow(pf, msg, erridx, onionerr); return handle_sendpay_failure_payment(pf, msg, erridx, onionerr, raw); diff --git a/plugins/renepay/pay_flow.c b/plugins/renepay/pay_flow.c index 9d5db54181f2..7e7754dd762b 100644 --- a/plugins/renepay/pay_flow.c +++ b/plugins/renepay/pay_flow.c @@ -264,6 +264,23 @@ static void destroy_payment_flow(struct pay_flow *pf) list_del_from(&pf->payment->flows, &pf->list); } +/* Print out flow, and any information we already know */ +static const char *flow_path_annotated(const tal_t *ctx, + const struct pay_flow *flow) +{ + char *s = tal_strdup(ctx, ""); + for (size_t i = 0; i < tal_count(flow->path_scidds); i++) { + tal_append_fmt(&s, "-%s%s->", + type_to_string(tmpctx, + struct short_channel_id_dir, + &flow->path_scidds[i]), + fmt_chan_extra_details(tmpctx, + pay_plugin->chan_extra_map, + &flow->path_scidds[i])); + } + return s; +} + /* Calculates delays and converts to scids, and links to the payment. * Frees flows. */ static void convert_and_attach_flows(struct payment *payment, @@ -310,6 +327,15 @@ static void convert_and_attach_flows(struct payment *payment, /* Payment keeps a list of its flows. */ list_add(&payment->flows, &pf->list); + /* First time they see this: annotate important points */ + payflow_note(pf, LOG_INFORM, + "amount=%s prob=%.3lf fees=%s delay=%u path=%s", + fmt_amount_msat(tmpctx, payflow_delivered(pf)), + pf->success_prob, + fmt_amount_msat(tmpctx, payflow_fee(pf)), + pf->cltv_delays[0] - pf->cltv_delays[plen-1], + flow_path_annotated(tmpctx, pf)); + /* Increase totals for payment */ amount_msat_accumulate(&payment->total_sent, pf->amounts[0]); amount_msat_accumulate(&payment->total_delivering, @@ -551,6 +577,16 @@ struct amount_msat payflow_delivered(const struct pay_flow *flow) return flow->amounts[tal_count(flow->amounts)-1]; } +/* How much does this flow pay in fees? */ +struct amount_msat payflow_fee(const struct pay_flow *pf) +{ + struct amount_msat fee; + + if (!amount_msat_sub(&fee, pf->amounts[0], payflow_delivered(pf))) + abort(); + return fee; +} + static struct pf_result *pf_resolve(struct pay_flow *pf, enum pay_flow_state oldstate, enum pay_flow_state newstate, diff --git a/plugins/renepay/pay_flow.h b/plugins/renepay/pay_flow.h index 6d6d33be8ab9..4a62adb2dec5 100644 --- a/plugins/renepay/pay_flow.h +++ b/plugins/renepay/pay_flow.h @@ -136,4 +136,7 @@ const char *flow_path_to_str(const tal_t *ctx, const struct pay_flow *flow); /* How much does this flow deliver to destination? */ struct amount_msat payflow_delivered(const struct pay_flow *flow); +/* At what cost? */ +struct amount_msat payflow_fee(const struct pay_flow *flow); + #endif /* LIGHTNING_PLUGINS_RENEPAY_PAY_FLOW_H */ diff --git a/plugins/renepay/uncertainty_network.c b/plugins/renepay/uncertainty_network.c index 7e1ad702ed42..9d14d456b68c 100644 --- a/plugins/renepay/uncertainty_network.c +++ b/plugins/renepay/uncertainty_network.c @@ -191,7 +191,7 @@ void uncertainty_network_flow_success( for (size_t i = 0; i < tal_count(pf->path_scidds); i++) { chan_extra_sent_success( - chan_extra_map, + pf, chan_extra_map, &pf->path_scidds[i], pf->amounts[i]); }