diff --git a/common/json_stream.c b/common/json_stream.c index 60517b3fbc82..7d1cc92cbd9a 100644 --- a/common/json_stream.c +++ b/common/json_stream.c @@ -372,6 +372,14 @@ void json_add_timeabs(struct json_stream *result, const char *fieldname, (u64)t.ts.tv_sec, (u64)t.ts.tv_nsec); } +void json_add_timerel(struct json_stream *result, const char *fieldname, + struct timerel t) +{ + json_add_primitive_fmt(result, fieldname, + "%" PRIu64 ".%09" PRIu64, + (u64)t.ts.tv_sec, (u64)t.ts.tv_nsec); +} + void json_add_timestr(struct json_stream *result, const char *fieldname, struct timespec ts) { diff --git a/common/json_stream.h b/common/json_stream.h index 9cc539e29a52..bfbb5d0a78df 100644 --- a/common/json_stream.h +++ b/common/json_stream.h @@ -253,9 +253,14 @@ void json_add_hex_talarr(struct json_stream *result, const char *fieldname, const tal_t *data); +/* '"fieldname" : 1749785122.000000001 */ void json_add_timeabs(struct json_stream *result, const char *fieldname, struct timeabs t); +/* '"fieldname" : 1.000000001 */ +void json_add_timerel(struct json_stream *result, const char *fieldname, + struct timerel t); + /* used in log.c and notification.c*/ void json_add_timestr(struct json_stream *result, const char *fieldname, struct timespec ts); diff --git a/doc/developers-guide/plugin-development/event-notifications.md b/doc/developers-guide/plugin-development/event-notifications.md index ad6f2756011e..49d5742d5247 100644 --- a/doc/developers-guide/plugin-development/event-notifications.md +++ b/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" + } +} +``` diff --git a/plugins/libplugin.c b/plugins/libplugin.c index b70fe94d1f01..896564f70858 100644 --- a/plugins/libplugin.c +++ b/plugins/libplugin.c @@ -1859,10 +1859,10 @@ void plugin_gossmap_logcb(struct plugin *plugin, va_end(ap); } -struct json_stream *plugin_notification_start(struct plugin *plugin, +struct json_stream *plugin_notification_start(const tal_t *ctx, const char *method) { - struct json_stream *js = new_json_stream(plugin, NULL, NULL); + struct json_stream *js = new_json_stream(ctx, NULL, NULL); json_object_start(js, NULL); json_add_string(js, "jsonrpc", "2.0"); @@ -1873,7 +1873,7 @@ struct json_stream *plugin_notification_start(struct plugin *plugin, } void plugin_notification_end(struct plugin *plugin, - struct json_stream *stream) + struct json_stream *stream STEALS) { json_object_end(stream); jsonrpc_finish_and_send(plugin, stream); diff --git a/plugins/libplugin.h b/plugins/libplugin.h index 09a29a97f95b..54b4f883fc6b 100644 --- a/plugins/libplugin.h +++ b/plugins/libplugin.h @@ -534,10 +534,10 @@ void plugin_notify_end(struct command *cmd, struct json_stream *js); /* Send a notification for a custom notification topic. These are sent * to lightningd and distributed to subscribing plugins. */ -struct json_stream *plugin_notification_start(struct plugin *plugins, +struct json_stream *plugin_notification_start(const tal_t *ctx, const char *method); void plugin_notification_end(struct plugin *plugin, - struct json_stream *stream TAKES); + struct json_stream *stream STEALS); /* Convenience wrapper for notify "message" */ void plugin_notify_message(struct command *cmd, diff --git a/plugins/test/run-route-calc.c b/plugins/test/run-route-calc.c index a0bdda823448..3898c3f45955 100644 --- a/plugins/test/run-route-calc.c +++ b/plugins/test/run-route-calc.c @@ -299,10 +299,10 @@ void plugin_log(struct plugin *p UNNEEDED, enum log_level l UNNEEDED, const char { fprintf(stderr, "plugin_log called!\n"); abort(); } /* Generated stub for plugin_notification_end */ void plugin_notification_end(struct plugin *plugin UNNEEDED, - struct json_stream *stream TAKES UNNEEDED) + struct json_stream *stream STEALS UNNEEDED) { fprintf(stderr, "plugin_notification_end called!\n"); abort(); } /* Generated stub for plugin_notification_start */ -struct json_stream *plugin_notification_start(struct plugin *plugins UNNEEDED, +struct json_stream *plugin_notification_start(const tal_t *ctx UNNEEDED, const char *method UNNEEDED) { fprintf(stderr, "plugin_notification_start called!\n"); abort(); } /* Generated stub for plugin_notify_message */ diff --git a/plugins/test/run-route-overlong.c b/plugins/test/run-route-overlong.c index da6f0a607a03..3683c0dd0d6e 100644 --- a/plugins/test/run-route-overlong.c +++ b/plugins/test/run-route-overlong.c @@ -296,10 +296,10 @@ void plugin_log(struct plugin *p UNNEEDED, enum log_level l UNNEEDED, const char { fprintf(stderr, "plugin_log called!\n"); abort(); } /* Generated stub for plugin_notification_end */ void plugin_notification_end(struct plugin *plugin UNNEEDED, - struct json_stream *stream TAKES UNNEEDED) + struct json_stream *stream STEALS UNNEEDED) { fprintf(stderr, "plugin_notification_end called!\n"); abort(); } /* Generated stub for plugin_notification_start */ -struct json_stream *plugin_notification_start(struct plugin *plugins UNNEEDED, +struct json_stream *plugin_notification_start(const tal_t *ctx UNNEEDED, const char *method UNNEEDED) { fprintf(stderr, "plugin_notification_start called!\n"); abort(); } /* Generated stub for plugin_notify_message */ diff --git a/plugins/xpay/xpay.c b/plugins/xpay/xpay.c index 2bf1c787d96f..06cc660b96ab 100644 --- a/plugins/xpay/xpay.c +++ b/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), diff --git a/tests/plugins/custom_notifications.py b/tests/plugins/custom_notifications.py index a3fa9b9aa837..1211a30c733f 100755 --- a/tests/plugins/custom_notifications.py +++ b/tests/plugins/custom_notifications.py @@ -34,6 +34,16 @@ def on_pay_success(origin, payload, **kwargs): ) +@plugin.subscribe("xpay_attempt_start") +def on_xpay_attempt_start(origin, payload, **kwargs): + plugin.log("Got xpay_attempt_start: {}".format(payload)) + + +@plugin.subscribe("xpay_attempt_end") +def on_xpay_attempt_end(origin, payload, **kwargs): + plugin.log("Got xpay_attempt_end: {}".format(payload)) + + @plugin.subscribe("ididntannouncethis") def on_faulty_emit(origin, payload, **kwargs): """We should never receive this as it gets dropped. diff --git a/tests/test_xpay.py b/tests/test_xpay.py index ff7179c888dd..2516251ccf68 100644 --- a/tests/test_xpay.py +++ b/tests/test_xpay.py @@ -831,3 +831,53 @@ def test_xpay_twohop_bug(node_factory, bitcoind): # This doesn't! l1.rpc.xpay(inv) l1.daemon.wait_for_log(f'Adding HTLC 1 amount=15002msat cltv={110 + 1 + 100 + 200 + 400}') + + +def test_attempt_notifications(node_factory): + plugin_path = os.path.join(os.getcwd(), 'tests/plugins/custom_notifications.py') + l1, l2, l3 = node_factory.line_graph(3, wait_for_announce=True, + opts=[{"plugin": plugin_path}, {}, {}]) + + scid12 = only_one(l1.rpc.listpeerchannels(l2.info['id'])['channels'])['short_channel_id'] + scid12_dir = only_one(l1.rpc.listpeerchannels(l2.info['id'])['channels'])['direction'] + scid23 = only_one(l2.rpc.listpeerchannels(l3.info['id'])['channels'])['short_channel_id'] + scid23_dir = only_one(l2.rpc.listpeerchannels(l3.info['id'])['channels'])['direction'] + inv1 = l3.rpc.invoice(5000000, 'test_attempt_notifications1', 'test_attempt_notifications1') + l1.rpc.xpay(inv1['bolt11']) + + line = l1.daemon.wait_for_log("plugin-custom_notifications.py: Got xpay_attempt_start: ") + regex = r".*Got xpay_attempt_start: \{'payment_hash': '" + inv1['payment_hash'] + r"', 'groupid': [0-9]*, 'partid': 1, 'total_payment_msat': 5000000, 'attempt_msat': 5000000, 'hops': \[\{'next_node': '" + l2.info['id'] + r"', 'short_channel_id': '" + scid12 + r"', 'direction': " + str(scid12_dir) + r", 'channel_in_msat': 5000051, 'channel_out_msat': 5000051\}, \{'next_node': '" + l3.info['id'] + r"', 'short_channel_id': '" + scid23 + r"', 'direction': " + str(scid23_dir) + r", 'channel_in_msat': 5000051, 'channel_out_msat': 5000000\}\]\}" + assert re.match(regex, line) + + # Note, duration always has 9 decimals, EXCEPT that the python code interprets it, so if the last digit is a 0 it will only print 8. + line = l1.daemon.wait_for_log("plugin-custom_notifications.py: Got xpay_attempt_end: ") + regex = r".*Got xpay_attempt_end: \{'status': 'success', 'duration': [0-9]*\.[0-9]*, 'payment_hash': '" + inv1['payment_hash'] + r"', 'groupid': [0-9]*, 'partid': 1\}" + assert re.match(regex, line) + + inv2 = l3.rpc.invoice(10000000, 'test_attempt_notifications2', 'test_attempt_notifications2') + l3.rpc.delinvoice('test_attempt_notifications2', "unpaid") + + # Final node failure + with pytest.raises(RpcError, match=r"Destination said it doesn't know invoice: incorrect_or_unknown_payment_details"): + l1.rpc.xpay(inv2['bolt11']) + + line = l1.daemon.wait_for_log("plugin-custom_notifications.py: Got xpay_attempt_start: ") + regex = r".*Got xpay_attempt_start: \{'payment_hash': '" + inv2['payment_hash'] + r"', 'groupid': [0-9]*, 'partid': 1, 'total_payment_msat': 10000000, 'attempt_msat': 10000000, 'hops': \[\{'next_node': '" + l2.info['id'] + r"', 'short_channel_id': '" + scid12 + r"', 'direction': " + str(scid12_dir) + r", 'channel_in_msat': 10000101, 'channel_out_msat': 10000101\}, \{'next_node': '" + l3.info['id'] + r"', 'short_channel_id': '" + scid23 + r"', 'direction': " + str(scid23_dir) + r", 'channel_in_msat': 10000101, 'channel_out_msat': 10000000\}\]\}" + assert re.match(regex, line) + + line = l1.daemon.wait_for_log("plugin-custom_notifications.py: Got xpay_attempt_end: ") + regex = r".*Got xpay_attempt_end: \{'status': 'failure', 'payment_hash': '" + inv2['payment_hash'] + r"', 'groupid': [0-9]*, 'partid': 1, 'failed_msg': '400f00000000009896800000006c', 'duration': [0-9]*\.[0-9]*, 'failed_node_id': '" + l3.info['id'] + r"', 'error_code': 16399, 'error_message': 'incorrect_or_unknown_payment_details'\}" + assert re.match(regex, line) + + # Intermediary node failure + l3.stop() + with pytest.raises(RpcError, match=r"Failed after 1 attempts"): + l1.rpc.xpay(inv2['bolt11']) + + line = l1.daemon.wait_for_log("plugin-custom_notifications.py: Got xpay_attempt_start: ") + regex = r".*Got xpay_attempt_start: \{'payment_hash': '" + inv2['payment_hash'] + r"', 'groupid': [0-9]*, 'partid': 1, 'total_payment_msat': 10000000, 'attempt_msat': 10000000, 'hops': \[\{'next_node': '" + l2.info['id'] + r"', 'short_channel_id': '" + scid12 + r"', 'direction': " + str(scid12_dir) + r", 'channel_in_msat': 10000101, 'channel_out_msat': 10000101\}, \{'next_node': '" + l3.info['id'] + r"', 'short_channel_id': '" + scid23 + r"', 'direction': " + str(scid23_dir) + r", 'channel_in_msat': 10000101, 'channel_out_msat': 10000000\}\]\}" + assert re.match(regex, line) + + line = l1.daemon.wait_for_log("plugin-custom_notifications.py: Got xpay_attempt_end: ") + regex = r".*Got xpay_attempt_end: \{'status': 'failure', 'payment_hash': '" + inv2['payment_hash'] + r"', 'groupid': [0-9]*, 'partid': 1, 'failed_msg': '1007[a-f0-9]*', 'duration': [0-9]*\.[0-9]{9}, 'failed_node_id': '" + l2.info['id'] + r"', 'failed_short_channel_id': '" + scid23 + r"', 'failed_direction': " + str(scid23_dir) + r", 'error_code': 4103, 'error_message': 'temporary_channel_failure'\}" + assert re.match(regex, line)