xpay: add xpay_attempt_start and xpay_attempt_end notifications.

Requested-by: Michael at Boltz
Signed-off-by: Rusty Russell <[email protected]>
Changelog-Added: Plugins: `xpay` now publishes `xpay_attempt_start` and `xpay_attempt_end` notifications on every payment send attempt.

Author: rustyrussell

doc/developers-guide/plugin-development/event-notifications.md

@@ -567,3 +567,85 @@ Where:
 - `plugin_name`: The short name of the plugin.
 - `plugin_path`: The full file path to the plugin executable.
 - `methods`: An array of RPC method names that the plugin registered.
+
+
+### `xpay_attempt_start` (v25.09 onward) 
+
+Emitted by `xpay` when part of a payment begins.  `payment_hash` and
+`groupid` uniquely identify this xpay invocation, and `partid` then identifies
+this particular attempt to pay part of that.
+
+`total_payment_msat` is the total amount (usually the invoice amount),
+which will be the same across all parts, adn `attempt_msat` is the
+amount being delivered to the destination by this part.
+
+Each element in `hops` shows the amount going into the node (i.e. with
+fees, `channel_in_msat`) and the amount we're telling it to send
+to the other end (`channel_out_msat`).  The `channel_out_msat` will
+be equal to the next `channel_in_msat.  The final
+`channel_out_msat` will be equal to the `attempt_msat`.
+
+The example shows a payment from this node via 1x2x3 (direction 1) to 035d2b1192dfba134e10e540875d366ebc8bc353d5aa766b80c090b39c3a5d885d, then via 2x3x4 (direction 0) to 022d223620a359a47ff7f7ac447c85c46c923da53389221a0054c11c1e3ca31d59.
+
+```json
+{
+  "xpay_attempt_start": {
+    "payment_hash": "f5a6a059a25d1e329d9b094aeeec8c2191ca037d3f5b0662e21ae850debe8ea2",
+    "groupid": 1,
+    "partid": 1,
+    "total_payment_msat": 200000,
+    "attempt_msat": 100000,
+    "hops": [
+      {
+        "next_node": "035d2b1192dfba134e10e540875d366ebc8bc353d5aa766b80c090b39c3a5d885d",
+        "short_channel_id": "1x2x3",
+        "direction": 1,
+        "channel_in_msat": 100030,
+        "channel_out_msat": 100030
+      },
+      {
+        "next_node": "022d223620a359a47ff7f7ac447c85c46c923da53389221a0054c11c1e3ca31d59",
+        "short_channel_id": "2x3x4",
+        "direction": 0,
+        "channel_in_msat": 100030,
+        "channel_out_msat": 100000
+      }
+    ]
+  }
+}
+```
+
+### `xpay_attempt_end` (v25.09 onward) 
+
+Emitted by `xpay` when part of a payment ends.  `payment_hash`, `groupid` and `partid`
+will match a previous `xpay_attempt_start`.
+
+`status` will be "success" or "failure".  `duration` will be a number of seconds, with 9 decimal places.  This is the time between `xpay` telling lightningd to send the onion, to when `xpay` processes the response.
+
+If `status` is "failure", there will always be an `error_message`: the other fields below
+will be missing in the unusual case where the error onion is corrupted.
+
+`failed_node_id`: If it's a non-local error, the source of the error.
+`failed_short_channel_id`: if it's not the final node, the channel it's complaining about.
+`failed_direction`: if it's not the final node, the channel direction.
+`failed_msg`: the decrypted onion message, in hex, if it was valid.
+`error_code`: the error code returned (present unless onion was corrupted).
+`error_message`: always present: if `failed_node_id` is present it's just the name of the `error_code`, but otherwise it can be a more informative error from our own node.
+
+```json
+{
+  "xpay_attempt_end": {
+    "payment_hash": "f5a6a059a25d1e329d9b094aeeec8c2191ca037d3f5b0662e21ae850debe8ea2",
+    "groupid": 12345677890,
+    "partid": 1,
+    "duration": 1.123456789,
+    "status": "failure",
+    "failed_node_id": "035d2b1192dfba134e10e540875d366ebc8bc353d5aa766b80c090b39c3a5d885d",
+    "failed_msg": "1007008a01024eb43f5212a864e19c426ec0278fb1c506eb043a1cdfde88bd1747080f711dbb472ecce9b1c44f2df7dbbc501a78451fe3ac93b6b9a2aac1bddc9dbb86e81b1b06226e46111a0b59caaf126043eb5bbf28c34f3a5e332a1fc7b2b73cf188910f0000670000010000684e64ea010000060000000000000000000000010000000a000000003b023380",
+    "failed_short_channel_id": "1x2x3",
+    "failed_direction": 1,
+    "error_code": 4103,
+    "error_message": "temporary_channel_failure"
+  }
+}
+```

plugins/xpay/xpay.c

@@ -149,6 +149,7 @@ struct attempt {
 
 	struct payment *payment;
 	struct amount_msat delivers;
+	struct timemono start_time;
 
 	/* Path we tried, so we can unreserve, and tell askrene the results */
 	const struct hop *hops;
@@ -536,6 +537,73 @@ static struct amount_msat total_delivered(const struct payment *payment)
 	return sum;
 }
 
+/* We can notify others of what the details are, so they can do their own
+ * layer heuristics. */
+static void json_add_attempt_fields(struct json_stream *js,
+				    const struct attempt *attempt)
+{
+	/* These three uniquely identify this attempt */
+	json_add_sha256(js, "payment_hash", &attempt->payment->payment_hash);
+	json_add_u64(js, "groupid", attempt->payment->group_id);
+	json_add_u64(js, "partid", attempt->partid);
+}
+
+static void outgoing_notify_start(const struct attempt *attempt)
+{
+	struct json_stream *js = plugin_notification_start(NULL, "xpay_attempt_start");
+	json_add_attempt_fields(js, attempt);
+	json_add_amount_msat(js, "total_payment_msat", attempt->payment->amount);
+	json_add_amount_msat(js, "attempt_msat", attempt->delivers);
+	json_array_start(js, "hops");
+	for (size_t i = 0; i < tal_count(attempt->hops); i++) {
+		const struct hop *hop = &attempt->hops[i];
+		json_object_start(js, NULL);
+		json_add_pubkey(js, "next_node", &hop->next_node);
+		json_add_short_channel_id(js, "short_channel_id", hop->scidd.scid);
+		json_add_u32(js, "direction", hop->scidd.dir);
+		json_add_amount_msat(js, "channel_in_msat", hop->amount_in);
+		json_add_amount_msat(js, "channel_out_msat", hop->amount_out);
+		json_object_end(js);
+	}
+	json_array_end(js);
+	plugin_notification_end(attempt->payment->plugin, js);
+}
+
+static void outgoing_notify_success(const struct attempt *attempt)
+{
+	struct json_stream *js = plugin_notification_start(NULL, "xpay_attempt_end");
+	json_add_string(js, "status", "success");
+	json_add_timerel(js, "duration", timemono_between(time_mono(), attempt->start_time));
+	json_add_attempt_fields(js, attempt);
+	plugin_notification_end(attempt->payment->plugin, js);
+}
+
+static void outgoing_notify_failure(const struct attempt *attempt,
+				    int failindex, int errcode,
+				    const u8 *replymsg,
+				    const char *errstr)
+{
+	struct json_stream *js = plugin_notification_start(NULL, "xpay_attempt_end");
+	json_add_string(js, "status", "failure");
+	json_add_attempt_fields(js, attempt);
+	if (replymsg)
+		json_add_hex_talarr(js, "failed_msg", replymsg);
+	json_add_timerel(js, "duration", timemono_between(time_mono(), attempt->start_time));
+	if (failindex != -1) {
+		if (failindex != 0)
+			json_add_pubkey(js, "failed_node_id", &attempt->hops[failindex-1].next_node);
+		if (failindex != tal_count(attempt->hops)) {
+			const struct hop *hop = &attempt->hops[failindex];
+			json_add_short_channel_id(js, "failed_short_channel_id", hop->scidd.scid);
+			json_add_u32(js, "failed_direction", hop->scidd.dir);
+		}
+	}
+	if (errcode != -1)
+		json_add_u32(js, "error_code", errcode);
+	json_add_string(js, "error_message", errstr);
+	plugin_notification_end(attempt->payment->plugin, js);
+}
+
 static void update_knowledge_from_error(struct command *aux_cmd,
 					const char *buf,
 					const jsmntok_t *error,
@@ -590,6 +658,7 @@ static void update_knowledge_from_error(struct command *aux_cmd,
 
 	/* Garbled?  Blame random hop. */
 	if (!replymsg) {
+		outgoing_notify_failure(attempt, -1, -1, replymsg, "Garbled error message");
 		index = pseudorand(tal_count(attempt->hops));
 		description = "Garbled error message";
 		add_result_summary(attempt, LOG_UNUSUAL,
@@ -627,6 +696,7 @@ static void update_knowledge_from_error(struct command *aux_cmd,
 	} else
 		errmsg = failcode_name;
 
+	outgoing_notify_failure(attempt, index, failcode, replymsg, errmsg);
 	description = tal_fmt(tmpctx,
 			      "Error %s for path %s, from %s",
 			      errmsg,
@@ -881,6 +951,8 @@ static struct command_result *injectpaymentonion_succeeded(struct command *aux_c
 		plugin_err(aux_cmd->plugin, "Invalid injectpaymentonion result '%.*s'",
 			   json_tok_full_len(result), json_tok_full(buf, result));
 
+	outgoing_notify_success(attempt);
+
 	/* Move from current_attempts to past_attempts */
 	list_del_from(&payment->current_attempts, &attempt->list);
 	list_add(&payment->past_attempts, &attempt->list);
@@ -1008,6 +1080,9 @@ static struct command_result *do_inject(struct command *aux_cmd,
 		return command_still_pending(aux_cmd);
 	}
 
+	outgoing_notify_start(attempt);
+	attempt->start_time = time_mono();
+
 	req = jsonrpc_request_start(aux_cmd,
 				    "injectpaymentonion",
 				    injectpaymentonion_succeeded,
@@ -2118,6 +2193,12 @@ static const struct plugin_hook hooks[] = {
 	},
 };
 
+/* Notifications for each payment part we attempt */
+static const char *outgoing_notifications[] = {
+	"xpay_attempt_start",
+	"xpay_attempt_end",
+};
+
 int main(int argc, char *argv[])
 {
 	struct xpay *xpay;
@@ -2131,7 +2212,7 @@ int main(int argc, char *argv[])
 		    commands, ARRAY_SIZE(commands),
 		    notifications, ARRAY_SIZE(notifications),
 		    hooks, ARRAY_SIZE(hooks),
-	            NULL, 0,
+	            outgoing_notifications, ARRAY_SIZE(outgoing_notifications),
 		    plugin_option_dynamic("xpay-handle-pay", "bool",
 					  "Make xpay take over pay commands it can handle.",
 					  bool_option, bool_jsonfmt, &xpay->take_over_pay),