plugins/renepay: neaten the command notifications.

rustyrussell · rustyrussell · commit 00e9af57f563 · 2023-08-23T10:47:28.000+09:30
It now looks like (for test_hardmpp): ``` # we have computed a set of 1 flows with probability 0.328, fees 0msat and delay 23 # Flow 1: amount=1800000000msat prob=0.328 fees=0msat delay=12 path=-103x2x0/1(min=max=4294967295msat)->-103x5x0/0->-103x3x0/1-> # Flow 1: Failed at node #1 (WIRE_TEMPORARY_CHANNEL_FAILURE): failed: WIRE_TEMPORARY_CHANNEL_FAILURE (reply from remote) # Flow 1: Failure of 1800000000msat for 103x5x0/0 capacity [0msat,3000000000msat] -> [0msat,1799999999msat] # we have computed a set of 2 flows with probability 0.115, fees 0msat and delay 23 # Flow 2: amount=500000000msat prob=0.475 fees=0msat delay=12 path=-103x6x0/0(min=max=4294967295msat)->-103x1x0/1->-103x4x0/1-> # Flow 3: amount=1300000000msat prob=0.242 fees=0msat delay=12 path=-103x2x0/1(min=max=4294967295msat)->-103x5x0/0(max=1799999999msat)->-103x3x0/1-> # Flow 3: Failed at node #1 (WIRE_TEMPORARY_CHANNEL_FAILURE): failed: WIRE_TEMPORARY_CHANNEL_FAILURE (reply from remote) # Flow 3: Failure of 1300000000msat for 103x5x0/0 capacity [0msat,1799999999msat] -> [0msat,1299999999msat] # we have computed a set of 2 flows with probability 0.084, fees 0msat and delay 23 # Flow 4: amount=260000000msat prob=0.467 fees=0msat delay=12 path=-103x6x0/0(500000000msat in 1 htlcs,min=max=4294967295msat)->-103x1x0/1(500000000msat in 1 htlcs)->-103x4x0/1(500000000msat in 1 htlcs)-> # Flow 5: amount=1040000000msat prob=0.179 fees=0msat delay=12 path=-103x2x0/1(min=max=4294967295msat)->-103x5x0/0(max=1299999999msat)->-103x3x0/1-> # Flow 5: Failed at node #1 (WIRE_TEMPORARY_CHANNEL_FAILURE): failed: WIRE_TEMPORARY_CHANNEL_FAILURE (reply from remote) # Flow 5: Failure of 1040000000msat for 103x5x0/0 capacity [0msat,1299999999msat] -> [0msat,1039999999msat] # we have computed a set of 2 flows with probability 0.052, fees 0msat and delay 23 # Flow 6: amount=120000000msat prob=0.494 fees=0msat delay=12 path=-103x6x0/0(760000000msat in 2 htlcs,min=max=4294967295msat)->-103x1x0/1(760000000msat in 2 htlcs)->-103x4x0/1(760000000msat in 2 htlcs)-> # Flow 7: amount=920000000msat prob=0.105 fees=0msat delay=12 path=-103x2x0/1(min=max=4294967295msat)->-103x5x0/0(max=1039999999msat)->-103x3x0/1-> # Flow 7: Success ``` Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>
diff --git 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
@@ -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
@@ -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
@@ -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
diff --git a/plugins/renepay/uncertainty_network.c b/plugins/renepay/uncertainty_network.c
