mirrors/core-lightning
1
0
Fork 0
mirror of https://github.com/ElementsProject/lightning.git synced 2025-03-26 20:30:59 +01:00
Code Issues Projects Releases Wiki Activity

askrene: give notifications back to caller as we go.

Browse source 
And unify logging for better debugging.

Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>
Changelog-EXPERIMENTAL: `askrene` now has better logging, gives notifications of progress.
This commit is contained in:
Rusty Russell 2024-10-11 21:30:26 +10:30
parent ca023f2b5e
commit 1230f1b832
4 changed files with 124 additions and 59 deletions
Show stats Download patch file Download diff file Expand all files Collapse all files

73
plugins/askrene/askrene.c
View file

@ -225,6 +225,50 @@ struct amount_msat get_additional_per_htlc_cost(const struct route_query *rq,
return AMOUNT_MSAT(0);
}
const char *rq_log(const tal_t *ctx,
const struct route_query *rq,
enum log_level level,
const char *fmt,
...)
{
va_list args;
const char *msg;
va_start(args, fmt);
msg = tal_vfmt(ctx, fmt, args);
va_end(args);
plugin_notify_message(rq->cmd, level, "%s", msg);
/* Notifications already get logged at debug. Otherwise reduce
* severity. */
if (level != LOG_DBG)
plugin_log(rq->plugin,
level == LOG_BROKEN ? level : level - 1,
"%s: %s", rq->cmd->id, msg);
return msg;
}
static const char *fmt_route(const tal_t *ctx,
const struct route *route,
struct amount_msat delivers,
u32 final_cltv)
{
char *str = tal_strdup(ctx, "");
for (size_t i = 0; i < tal_count(route->hops); i++) {
struct short_channel_id_dir scidd;
scidd.scid = route->hops[i].scid;
scidd.dir = route->hops[i].direction;
tal_append_fmt(&str, "%s/%u %s -> ",
fmt_amount_msat(tmpctx, route->hops[i].amount),
route->hops[i].delay,
fmt_short_channel_id_dir(tmpctx, &scidd));
}
tal_append_fmt(&str, "%s/%u",
fmt_amount_msat(tmpctx, delivers), final_cltv);
return str;
}
/* Returns an error message, or sets *routes */
static const char *get_routes(const tal_t *ctx,
@ -300,13 +344,17 @@ static const char *get_routes(const tal_t *ctx,
srcnode = gossmap_find_node(askrene->gossmap, source);
if (!srcnode) {
ret = tal_fmt(ctx, "Unknown source node %s", fmt_node_id(tmpctx, source));
ret = rq_log(ctx, rq, LOG_INFORM,
"Unknown source node %s",
fmt_node_id(tmpctx, source));
goto fail;
}
dstnode = gossmap_find_node(askrene->gossmap, dest);
if (!dstnode) {
ret = tal_fmt(ctx, "Unknown destination node %s", fmt_node_id(tmpctx, dest));
ret = rq_log(ctx, rq, LOG_INFORM,
"Unknown destination node %s",
fmt_node_id(tmpctx, dest));
goto fail;
}
@ -344,10 +392,14 @@ static const char *get_routes(const tal_t *ctx,
/* FIXME: Typo in spec for CLTV in descripton! But it breaks our spelling check, so we omit it above */
while (finalcltv + flows_worst_delay(flows) > 2016) {
delay_feefactor *= 2;
rq_log(tmpctx, rq, LOG_UNUSUAL,
"The worst flow delay is %"PRIu64" (> %i), retrying with delay_feefactor %f...",
flows_worst_delay(flows), 2016 - finalcltv, delay_feefactor);
flows = minflow(rq, rq, srcnode, dstnode, amount,
mu, delay_feefactor, base_fee_penalty, prob_cost_factor);
if (!flows || delay_feefactor > 10) {
ret = tal_fmt(ctx, "Could not find route without excessive delays");
ret = rq_log(ctx, rq, LOG_UNUSUAL,
"Could not find route without excessive delays");
goto fail;
}
}
@ -355,16 +407,23 @@ static const char *get_routes(const tal_t *ctx,
/* Too expensive? */
while (amount_msat_greater(flowset_fee(rq->plugin, flows), maxfee)) {
mu += 10;
rq_log(tmpctx, rq, LOG_UNUSUAL,
"The flows had a fee of %s, greater than max of %s, retrying with mu of %u%%...",
fmt_amount_msat(tmpctx, flowset_fee(rq->plugin, flows)),
fmt_amount_msat(tmpctx, maxfee),
mu);
flows = minflow(rq, rq, srcnode, dstnode, amount,
mu, delay_feefactor, base_fee_penalty, prob_cost_factor);
if (!flows || mu == 100) {
ret = tal_fmt(ctx, "Could not find route without excessive cost");
ret = rq_log(ctx, rq, LOG_UNUSUAL,
"Could not find route without excessive cost");
goto fail;
}
}
if (finalcltv + flows_worst_delay(flows) > 2016) {
ret = tal_fmt(ctx, "Could not find route without excessive cost or delays");
ret = rq_log(ctx, rq, LOG_UNUSUAL,
"Could not find route without excessive cost or delays");
goto fail;
}
@ -409,10 +468,14 @@ static const char *get_routes(const tal_t *ctx,
rh->delay = delay;
}
(*amounts)[i] = flows[i]->delivers;
rq_log(tmpctx, rq, LOG_INFORM, "Flow %zu/%zu: %s",
i, tal_count(flows),
fmt_route(tmpctx, r, (*amounts)[i], finalcltv));
}
*probability = flowset_probability(flows, rq);
gossmap_remove_localmods(askrene->gossmap, localmods);
return NULL;
/* Explicit failure path keeps the compiler (gcc version 12.3.0 -O3) from

8
plugins/askrene/askrene.h
View file

@ -64,6 +64,14 @@ void get_constraints(const struct route_query *rq,
struct amount_msat *min,
struct amount_msat *max);
/* Say something about this route_query */
const char *rq_log(const tal_t *ctx,
const struct route_query *rq,
enum log_level level,
const char *fmt,
...)
PRINTF_FMT(4, 5);
/* Is there a known additional per-htlc cost for this channel? */
struct amount_msat get_additional_per_htlc_cost(const struct route_query *rq,
const struct short_channel_id_dir *scidd);

17
plugins/askrene/explain_failure.c
View file

@ -236,7 +236,8 @@ const char *explain_failure(const tal_t *ctx,
hops = route_from_dijkstra(tmpctx, rq->gossmap, dij, srcnode,
AMOUNT_MSAT(0), 0);
if (!hops)
return tal_fmt(ctx, "There is no connection between source and destination at all");
return rq_log(ctx, rq, LOG_INFORM,
"There is no connection between source and destination at all");
/* Description of shortest path */
path = tal_strdup(tmpctx, "");
@ -276,15 +277,15 @@ const char *explain_failure(const tal_t *ctx,
else
continue;
return tal_fmt(ctx,
NO_USABLE_PATHS_STRING
" The shortest path is %s, but %s %s",
path,
fmt_short_channel_id_dir(tmpctx, &scidd),
explanation);
return rq_log(ctx, rq, LOG_INFORM,
NO_USABLE_PATHS_STRING
" The shortest path is %s, but %s %s",
path,
fmt_short_channel_id_dir(tmpctx, &scidd),
explanation);
}
return tal_fmt(ctx,
return rq_log(ctx, rq, LOG_BROKEN,
"Actually, I'm not sure why we didn't find the"
" obvious route %s: perhaps this is a bug?",
path);

85
plugins/askrene/refine.c
View file

@ -103,12 +103,12 @@ static const char *constrain_flow(const tal_t *ctx,
/* If amount is > max, we decrease and add note it in
* case something goes wrong later. */
if (amount_msat_greater(msat, max)) {
plugin_log(rq->plugin, LOG_DBG,
"Decreased %s to %s%s across %s",
fmt_amount_msat(tmpctx, msat),
max_cause,
fmt_amount_msat(tmpctx, max),
fmt_flows_step_scid(tmpctx, rq, flow, i));
rq_log(tmpctx, rq, LOG_INFORM,
"Had to decreased amount %s to %s%s across %s",
fmt_amount_msat(tmpctx, msat),
max_cause,
fmt_amount_msat(tmpctx, max),
fmt_flows_step_scid(tmpctx, rq, flow, i));
msat = max;
decreased = i;
why_decreased = max_cause;
@ -139,28 +139,31 @@ static const char *constrain_flow(const tal_t *ctx,
/* These failures are incredibly unlikely, but possible */
if (amount_msat_is_zero(next)) {
return tal_fmt(ctx, "Amount %s cannot pay its own fees across %s",
fmt_amount_msat(tmpctx, msat),
fmt_flows_step_scid(tmpctx, rq, flow, i));
return rq_log(ctx, rq, LOG_UNUSUAL,
"Amount %s cannot pay its own fees across %s",
fmt_amount_msat(tmpctx, msat),
fmt_flows_step_scid(tmpctx, rq, flow, i));
}
/* Does happen if we try to pay 1 msat, and all paths have 1000msat min */
if (amount_msat_less(next, min)) {
return tal_fmt(ctx, "Amount %s below minimum across %s",
fmt_amount_msat(tmpctx, next),
fmt_flows_step_scid(tmpctx, rq, flow, i));
return rq_log(ctx, rq, LOG_UNUSUAL,
"Amount %s below minimum across %s",
fmt_amount_msat(tmpctx, next),
fmt_flows_step_scid(tmpctx, rq, flow, i));
}
msat = next;
}
if (!amount_msat_eq(flow->delivers, msat)) {
plugin_log(rq->plugin, LOG_DBG, "Flow changed to deliver %s not %s, because max constrained by %s%s",
fmt_amount_msat(tmpctx, msat),
fmt_amount_msat(tmpctx, flow->delivers),
why_decreased ? why_decreased : NULL,
decreased == -1 ? "none"
: fmt_flows_step_scid(tmpctx, rq, flow, decreased));
rq_log(tmpctx, rq, LOG_INFORM,
"Flow changed to deliver %s not %s, because max constrained by %s%s",
fmt_amount_msat(tmpctx, msat),
fmt_amount_msat(tmpctx, flow->delivers),
why_decreased ? why_decreased : NULL,
decreased == -1 ? "none"
: fmt_flows_step_scid(tmpctx, rq, flow, decreased));
flow->delivers = msat;
}
@ -244,7 +247,6 @@ static struct flow *pick_most_likely_flow(struct route_query *rq,
continue;
best_prob = prob;
best_flow = flows[i];
plugin_log(rq->plugin, LOG_DBG, "Best flow is #%zu!", i);
}
return best_flow;
@ -260,15 +262,14 @@ static const char *flow_violates_min(const tal_t *ctx,
const struct half_chan *h = flow_edge(flow, i);
struct amount_msat min = amount_msat(fp16_to_u64(h->htlc_min));
plugin_log(rq->plugin, LOG_DBG, "flow_violates_min: %u/%zu amt=%s, min=%s",
i, tal_count(flow->path), fmt_amount_msat(tmpctx, msat), fmt_amount_msat(tmpctx, min));
if (amount_msat_less(msat, min)) {
struct short_channel_id_dir scidd;
get_scidd(rq->gossmap, flow, i, &scidd);
return tal_fmt(ctx, "Sending %s across %s would violate htlc_min (~%s)",
fmt_amount_msat(tmpctx, msat),
fmt_short_channel_id_dir(tmpctx, &scidd),
fmt_amount_msat(tmpctx, min));
return rq_log(ctx, rq, LOG_UNUSUAL,
"Sending %s across %s would violate htlc_min (~%s)",
fmt_amount_msat(tmpctx, msat),
fmt_short_channel_id_dir(tmpctx, &scidd),
fmt_amount_msat(tmpctx, min));
}
if (!amount_msat_add_fee(&msat, h->base_fee, h->proportional_fee))
plugin_err(rq->plugin, "Adding fee to amount");
@ -290,24 +291,14 @@ refine_with_fees_and_limits(const tal_t *ctx,
for (size_t i = 0; i < tal_count(*flows);) {
struct flow *flow = (*flows)[i];
plugin_log(rq->plugin, LOG_DBG, "Constraining flow %zu: %s",
i, fmt_amount_msat(tmpctx, flow->delivers));
for (size_t j = 0; j < tal_count(flow->path); j++) {
struct amount_msat min, max;
get_constraints(rq, flow->path[j], flow->dirs[j], &min, &max);
plugin_log(rq->plugin, LOG_DBG, "->%s(max %s)",
fmt_flows_step_scid(tmpctx, rq, flow, j),
fmt_amount_msat(tmpctx, max));
}
flow_constraint_error = constrain_flow(tmpctx, rq, flow, &reservations);
if (!flow_constraint_error) {
i++;
continue;
}
plugin_log(rq->plugin, LOG_DBG, "Flow was too constrained: %s",
flow_constraint_error);
rq_log(tmpctx, rq, LOG_UNUSUAL, "Flow %zu/%zu was too constrained (%s) so removing it",
i, tal_count(*flows), flow_constraint_error);
/* This flow was reduced to 0 / impossible, remove */
tal_arr_remove(flows, i);
}
@ -324,10 +315,10 @@ refine_with_fees_and_limits(const tal_t *ctx,
for (size_t i = 0; i < tal_count(*flows); i++) {
if (amount_msat_sub(&(*flows)[i]->delivers, (*flows)[i]->delivers, excess)) {
const char *err;
plugin_log(rq->plugin, LOG_DBG,
"Flows delivered %s extra, trimming %zu/%zu",
fmt_amount_msat(tmpctx, excess),
i, tal_count(*flows));
rq_log(tmpctx, rq, LOG_DBG,
"Flow %zu/%zu delivered %s extra, trimming",
i, tal_count(*flows),
fmt_amount_msat(tmpctx, excess));
/* In theory, this can violate min_htlc! Thanks @Lagrang3! */
err = flow_violates_min(tmpctx, rq, (*flows)[i]);
if (err) {
@ -346,15 +337,16 @@ refine_with_fees_and_limits(const tal_t *ctx,
* was deleted instead for being below minimum */
if (!amount_msat_sub(&more_to_deliver, deliver,
flowset_delivers(rq->plugin, *flows))) {
ret = tal_fmt(ctx,
ret = rq_log(ctx, rq, LOG_UNUSUAL,
"Flowset delivers %s instead of %s, can't shed excess?",
fmt_amount_msat(tmpctx, flowset_delivers(rq->plugin, *flows)),
fmt_amount_msat(tmpctx, deliver));
goto out;
}
plugin_log(rq->plugin, LOG_DBG, "After dealing with excess, more_to_deliver=%s",
fmt_amount_msat(tmpctx, more_to_deliver));
rq_log(tmpctx, rq, LOG_DBG,
"After dealing with excess, more_to_deliver=%s",
fmt_amount_msat(tmpctx, more_to_deliver));
}
/* The residual is minimal. In theory we could add one msat at a time
@ -375,8 +367,9 @@ refine_with_fees_and_limits(const tal_t *ctx,
* could try MCF again for the remainder. */
f = pick_most_likely_flow(rq, *flows, extra);
if (!f) {
ret = tal_fmt(ctx, "We couldn't quite afford it, we need to send %s more for fees: please submit a bug report!",
fmt_amount_msat(tmpctx, more_to_deliver));
ret = rq_log(ctx, rq, LOG_BROKEN,
"We couldn't quite afford it, we need to send %s more for fees: please submit a bug report!",
fmt_amount_msat(tmpctx, more_to_deliver));
goto out;
}