libplugin: Instrument the JSON-RPC calls with tracing

plugins/Makefile

@@ -23,8 +23,8 @@ PLUGIN_COMMANDO_OBJS := $(PLUGIN_COMMANDO_SRC:.c=.o)
 PLUGIN_KEYSEND_SRC := plugins/keysend.c
 PLUGIN_KEYSEND_OBJS := $(PLUGIN_KEYSEND_SRC:.c=.o)
 
-PLUGIN_LIB_SRC := plugins/libplugin.c
-PLUGIN_LIB_HEADER := plugins/libplugin.h
+PLUGIN_LIB_SRC := plugins/libplugin.c common/trace.c
+PLUGIN_LIB_HEADER := plugins/libplugin.h common/trace.h
 PLUGIN_LIB_OBJS := $(PLUGIN_LIB_SRC:.c=.o)
 
 PLUGIN_PAY_LIB_SRC := plugins/libplugin-pay.c

plugins/bkpr/test/run-bkpr_db.c

@@ -253,6 +253,21 @@ void towire_u8_array(u8 **pptr UNNEEDED, const u8 *arr UNNEEDED, size_t num UNNE
 /* Generated stub for towire_wirestring */
 void towire_wirestring(u8 **pptr UNNEEDED, const char *str UNNEEDED)
 { fprintf(stderr, "towire_wirestring called!\n"); abort(); }
+/* Generated stub for trace_span_end */
+void trace_span_end(const void *key UNNEEDED)
+{ fprintf(stderr, "trace_span_end called!\n"); abort(); }
+/* Generated stub for trace_span_resume */
+void trace_span_resume(const void *key UNNEEDED)
+{ fprintf(stderr, "trace_span_resume called!\n"); abort(); }
+/* Generated stub for trace_span_start */
+void trace_span_start(const char *name UNNEEDED, const void *key UNNEEDED)
+{ fprintf(stderr, "trace_span_start called!\n"); abort(); }
+/* Generated stub for trace_span_suspend */
+void trace_span_suspend(const void *key UNNEEDED)
+{ fprintf(stderr, "trace_span_suspend called!\n"); abort(); }
+/* Generated stub for trace_span_tag */
+void trace_span_tag(const void *key UNNEEDED, const char *name UNNEEDED, const char *value UNNEEDED)
+{ fprintf(stderr, "trace_span_tag called!\n"); abort(); }
 /* AUTOGENERATED MOCKS END */
 
 static char *tmp_dsn(const tal_t *ctx)

plugins/bkpr/test/run-recorder.c

@@ -259,6 +259,21 @@ void towire_u8_array(u8 **pptr UNNEEDED, const u8 *arr UNNEEDED, size_t num UNNE
 /* Generated stub for towire_wirestring */
 void towire_wirestring(u8 **pptr UNNEEDED, const char *str UNNEEDED)
 { fprintf(stderr, "towire_wirestring called!\n"); abort(); }
+/* Generated stub for trace_span_end */
+void trace_span_end(const void *key UNNEEDED)
+{ fprintf(stderr, "trace_span_end called!\n"); abort(); }
+/* Generated stub for trace_span_resume */
+void trace_span_resume(const void *key UNNEEDED)
+{ fprintf(stderr, "trace_span_resume called!\n"); abort(); }
+/* Generated stub for trace_span_start */
+void trace_span_start(const char *name UNNEEDED, const void *key UNNEEDED)
+{ fprintf(stderr, "trace_span_start called!\n"); abort(); }
+/* Generated stub for trace_span_suspend */
+void trace_span_suspend(const void *key UNNEEDED)
+{ fprintf(stderr, "trace_span_suspend called!\n"); abort(); }
+/* Generated stub for trace_span_tag */
+void trace_span_tag(const void *key UNNEEDED, const char *name UNNEEDED, const char *value UNNEEDED)
+{ fprintf(stderr, "trace_span_tag called!\n"); abort(); }
 /* AUTOGENERATED MOCKS END */
 
 static char *tmp_dsn(const tal_t *ctx)

plugins/libplugin-pay.c

@@ -10,9 +10,11 @@
 #include <common/memleak.h>
 #include <common/pseudorand.h>
 #include <common/random_select.h>
+#include <common/trace.h>
 #include <errno.h>
 #include <math.h>
 #include <plugins/libplugin-pay.h>
+#include <stdio.h>
 #include <sys/types.h>
 #include <wire/peer_wire.h>
 
@@ -2409,6 +2411,18 @@ static void payment_finished(struct payment *p)
 	}
 }
 
+const char * const payment_step_str[] =
+{
+    [PAYMENT_STEP_INITIALIZED] = "PAYMENT_STEP_INITIALIZED",
+    [PAYMENT_STEP_GOT_ROUTE] = "PAYMENT_STEP_GOT_ROUTE",
+    [PAYMENT_STEP_RETRY_GETROUTE]  = "PAYMENT_STEP_RETRY_GETROUTE",
+    [PAYMENT_STEP_ONION_PAYLOAD]  = "PAYMENT_STEP_ONION_PAYLOAD",
+    [PAYMENT_STEP_SPLIT] = "PAYMENT_STEP_SPLIT",
+    [PAYMENT_STEP_RETRY] = "PAYMENT_STEP_RETRY",
+    [PAYMENT_STEP_FAILED]  = "PAYMENT_STEP_FAILED",
+    [PAYMENT_STEP_SUCCESS]  = "PAYMENT_STEP_SUCCESS",
+};
+
 void payment_set_step(struct payment *p, enum payment_step newstep)
 {
 	p->current_modifier = -1;
@@ -2423,19 +2437,26 @@ void payment_continue(struct payment *p)
 {
 	struct payment_modifier *mod;
 	void *moddata;
+
+	trace_span_start("payment_continue", p);
 	/* If we are in the middle of calling the modifiers, continue calling
 	 * them, otherwise we can continue with the payment state-machine. */
 	p->current_modifier++;
 	mod = p->modifiers[p->current_modifier];
 
 	if (mod != NULL) {
+		char *str = tal_fmt(tmpctx, "%d", p->current_modifier);
+		trace_span_tag(p, "modifier", str);
+		trace_span_end(p);
 		/* There is another modifier, so call it. */
 		moddata = p->modifier_data[p->current_modifier];
 		return mod->post_step_cb(moddata, p);
 	} else {
 		/* There are no more modifiers, so reset the call chain and
 		 * proceed to the next state. */
 		p->current_modifier = -1;
+		trace_span_tag(p, "step", payment_step_str[p->step]);
+		trace_span_end(p);
 		switch (p->step) {
 		case PAYMENT_STEP_INITIALIZED:
 		case PAYMENT_STEP_RETRY_GETROUTE:
@@ -2462,6 +2483,7 @@ void payment_continue(struct payment *p)
 			return;
 		}
 	}
+	trace_span_end(p);
 	/* We should never get here, it'd mean one of the state machine called
 	 * `payment_continue` after the final state. */
 	abort();
@@ -2663,7 +2685,6 @@ local_channel_hints_listpeerchannels(struct command *cmd, const char *buffer,
 				     const jsmntok_t *toks, struct payment *p)
 {
 	struct listpeers_channel **chans;
-
 	chans = json_to_listpeers_channels(tmpctx, buffer, toks);
 
 	for (size_t i = 0; i < tal_count(chans); i++) {
@@ -2713,6 +2734,7 @@ local_channel_hints_listpeerchannels(struct command *cmd, const char *buffer,
 		}
 	}
 
+	trace_span_end(p);
 	payment_continue(p);
 	return command_still_pending(cmd);
 }
@@ -2728,6 +2750,7 @@ static void local_channel_hints_cb(void *d UNUSED, struct payment *p)
 	if (p->parent != NULL || p->step != PAYMENT_STEP_INITIALIZED)
 		return payment_continue(p);
 
+	trace_span_start("local_channel_hints_cb", p);
 	req = jsonrpc_request_start(p->plugin, NULL, "listpeerchannels",
 				    local_channel_hints_listpeerchannels,
 				    local_channel_hints_listpeerchannels, p);
@@ -3281,6 +3304,7 @@ static void exemptfee_cb(struct exemptfee_data *d, struct payment *p)
 	if (p->step != PAYMENT_STEP_INITIALIZED || p->parent != NULL)
 		return payment_continue(p);
 
+	trace_span_start("exemptfee_cb", p);
 	if (amount_msat_greater_eq(d->amount, p->constraints.fee_budget)) {
 		paymod_log(
 		    p, LOG_INFORM,
@@ -3291,6 +3315,8 @@ static void exemptfee_cb(struct exemptfee_data *d, struct payment *p)
 		p->constraints.fee_budget = d->amount;
 		p->start_constraints->fee_budget = d->amount;
 	}
+
+	trace_span_end(p);
 	return payment_continue(p);
 }
 
@@ -3507,8 +3533,12 @@ static void shadow_route_cb(struct shadow_route_data *d,
 		= amount_msat_div(p->constraints.fee_budget, 4);
 
 	if (pseudorand(2) == 0) {
+		trace_span_tag(p, "shadow_route_cb", "pseudorand(2) == 0");
+		trace_span_end(p);
 		return payment_continue(p);
 	} else {
+		trace_span_tag(p, "shadow_route_cb", "pseudorand(2) != 0");
+		trace_span_end(p);
 		shadow_route_extend(d, p);
 	}
 }
@@ -3527,8 +3557,11 @@ static void direct_pay_override(struct payment *p) {
 	 * anything. */
 	d = payment_mod_directpay_get_data(root);
 
-	if (d->chan == NULL)
+	if (d->chan == NULL) {
+		trace_span_tag(p, "direct_pay_override", "d->chan == NULL");
+		trace_span_end(p);
 		return payment_continue(p);
+	}
 
 	/* If we have a channel we need to make sure that it still has
 	 * sufficient capacity. Look it up in the channel_hints. */
@@ -3558,7 +3591,7 @@ static void direct_pay_override(struct payment *p) {
 		payment_set_step(p, PAYMENT_STEP_GOT_ROUTE);
 	}
 
-
+	trace_span_end(p);
 	payment_continue(p);
 }
 
@@ -3620,7 +3653,7 @@ static void direct_pay_cb(struct direct_pay_data *d, struct payment *p)
 		return payment_continue(p);
 
 
-
+	trace_span_start("direct_pay_cb", p);
 	req = jsonrpc_request_start(p->plugin, NULL, "listpeerchannels",
 				    direct_pay_listpeerchannels,
 				    direct_pay_listpeerchannels,
@@ -3876,7 +3909,7 @@ payee_incoming_limit_count(struct command *cmd,
 {
 	const jsmntok_t *channelstok;
 	size_t num_channels = 0;
-
+	trace_span_start("payee_incoming_limit_count", p);
 	channelstok = json_get_member(buf, result, "channels");
 	assert(channelstok);
 
@@ -3909,6 +3942,7 @@ payee_incoming_limit_count(struct command *cmd,
 		payment_lower_max_htlcs(p, lim, why);
 	}
 
+	trace_span_end(p);
 	payment_continue(p);
 	return command_still_pending(cmd);
 }
@@ -3922,8 +3956,10 @@ static void payee_incoming_limit_step_cb(void *d UNUSED, struct payment *p)
 	 || !payment_supports_mpp(p))
 		return payment_continue(p);
 
+	trace_span_start("payee_incoming_limit_step_cb", p);
 	/* Get information on the destination.  */
 	struct out_req *req;
+	trace_span_end(p);
 	req = jsonrpc_request_start(p->plugin, NULL, "listchannels",
 				    &payee_incoming_limit_count,
 				    &payment_rpc_failure, p);
@@ -3952,6 +3988,8 @@ static void route_exclusions_step_cb(struct route_exclusions_data *d,
 {
 	if (p->parent)
 		return payment_continue(p);
+
+	trace_span_start("route_exclusions_step_cb", p);
 	struct route_exclusion **exclusions = d->exclusions;
 	for (size_t i = 0; i < tal_count(exclusions); i++) {
 		struct route_exclusion *e = exclusions[i];
@@ -3970,6 +4008,7 @@ static void route_exclusions_step_cb(struct route_exclusions_data *d,
 			tal_arr_expand(&p->excluded_nodes, e->u.node_id);
 		}
 	}
+	trace_span_end(p);
 	payment_continue(p);
 }
 

plugins/libplugin.c

@@ -15,6 +15,7 @@
 #include <common/memleak.h>
 #include <common/plugin.h>
 #include <common/route.h>
+#include <common/trace.h>
 #include <errno.h>
 #include <plugins/libplugin.h>
 #include <stdio.h>
@@ -996,10 +997,18 @@ static void handle_rpc_reply(struct plugin *plugin, const jsmntok_t *toks)
 	if (out->cmd)
 		tal_del_destructor2(out->cmd, disable_request_cb, out);
 
+	trace_span_resume(out);
+
 	/* We want to free this if callback doesn't. */
 	tal_steal(tmpctx, out);
 
 	contenttok = json_get_member(buf, toks, "error");
+
+	/* Annotate the JSON-RPC span whether it succeeded or failed,
+	 * and then emit it. */
+	trace_span_tag(out, "error", contenttok == NULL ? "true" : "false");
+	trace_span_end(out);
+
 	if (contenttok) {
 		if (out->errcb)
 			res = out->errcb(out->cmd, buf, contenttok, out->arg);
@@ -1030,6 +1039,13 @@ send_outreq(struct plugin *plugin, const struct out_req *req)
 	json_object_end(req->js);
 	json_stream_close(req->js, req->cmd);
 
+	/* We are about to hand control over to the RPC, so suspend
+	 * the current span. It'll be resumed as soon as we have a
+	 * result to pass to either the error or the success
+	 * callback. */
+	trace_span_start("jsonrpc", req);
+	trace_span_tag(req, "id", req->id);
+	trace_span_suspend(req);
 	ld_rpc_send(plugin, req->js);
 
 	if (req->cmd != NULL)

plugins/renepay/mods.c

@@ -4,6 +4,7 @@
 #include <common/bolt11.h>
 #include <common/gossmods_listpeerchannels.h>
 #include <common/json_stream.h>
+#include <common/trace.h>
 #include <plugins/renepay/json.h>
 #include <plugins/renepay/mcf.h>
 #include <plugins/renepay/mods.h>
@@ -569,6 +570,7 @@ static struct command_result *routehints_done(struct command *cmd UNUSED,
 	assert(payment);
 	assert(payment->local_gossmods);
 
+	trace_span_start("routehints_done", payment);
 	const struct node_id *destination = &payment->payment_info.destination;
 	const struct route_info **routehints = payment->payment_info.routehints;
 	assert(routehints);
@@ -599,13 +601,16 @@ static struct command_result *routehints_done(struct command *cmd UNUSED,
 			   "been ignored.",
 			   __func__, skipped_count);
 
+	trace_span_end(payment);
 	return payment_continue(payment);
 }
 
 static struct command_result *routehints_cb(struct payment *payment)
 {
+	trace_span_start("routehints_cb", payment);
 	struct command *cmd = payment_command(payment);
 	assert(cmd);
+	trace_span_end(payment);
 	struct out_req *req = jsonrpc_request_start(
 	    cmd->plugin, cmd, "waitblockheight", routehints_done,
 	    payment_rpc_failure, payment);

plugins/test/run-route-calc.c

@@ -295,6 +295,15 @@ void towire_bigsize(u8 **pptr UNNEEDED, const bigsize_t val UNNEEDED)
 /* Generated stub for towire_channel_id */
 void towire_channel_id(u8 **pptr UNNEEDED, const struct channel_id *channel_id UNNEEDED)
 { fprintf(stderr, "towire_channel_id called!\n"); abort(); }
+/* Generated stub for trace_span_end */
+void trace_span_end(const void *key UNNEEDED)
+{ fprintf(stderr, "trace_span_end called!\n"); abort(); }
+/* Generated stub for trace_span_start */
+void trace_span_start(const char *name UNNEEDED, const void *key UNNEEDED)
+{ fprintf(stderr, "trace_span_start called!\n"); abort(); }
+/* Generated stub for trace_span_tag */
+void trace_span_tag(const void *key UNNEEDED, const char *name UNNEEDED, const char *value UNNEEDED)
+{ fprintf(stderr, "trace_span_tag called!\n"); abort(); }
 /* AUTOGENERATED MOCKS END */
 
 #ifndef SUPERVERBOSE

plugins/test/run-route-overlong.c

@@ -292,6 +292,15 @@ void towire_bigsize(u8 **pptr UNNEEDED, const bigsize_t val UNNEEDED)
 /* Generated stub for towire_channel_id */
 void towire_channel_id(u8 **pptr UNNEEDED, const struct channel_id *channel_id UNNEEDED)
 { fprintf(stderr, "towire_channel_id called!\n"); abort(); }
+/* Generated stub for trace_span_end */
+void trace_span_end(const void *key UNNEEDED)
+{ fprintf(stderr, "trace_span_end called!\n"); abort(); }
+/* Generated stub for trace_span_start */
+void trace_span_start(const char *name UNNEEDED, const void *key UNNEEDED)
+{ fprintf(stderr, "trace_span_start called!\n"); abort(); }
+/* Generated stub for trace_span_tag */
+void trace_span_tag(const void *key UNNEEDED, const char *name UNNEEDED, const char *value UNNEEDED)
+{ fprintf(stderr, "trace_span_tag called!\n"); abort(); }
 /* AUTOGENERATED MOCKS END */
 
 #ifndef SUPERVERBOSE

wallet/test/run-wallet.c

@@ -1002,7 +1002,7 @@ void topology_add_sync_waiter_(const tal_t *ctx UNNEEDED,
 u8 *towire_announcement_signatures(const tal_t *ctx UNNEEDED, const struct channel_id *channel_id UNNEEDED, struct short_channel_id short_channel_id UNNEEDED, const secp256k1_ecdsa_signature *node_signature UNNEEDED, const secp256k1_ecdsa_signature *bitcoin_signature UNNEEDED)
 { fprintf(stderr, "towire_announcement_signatures called!\n"); abort(); }
 /* Generated stub for towire_channel_reestablish */
-u8 *towire_channel_reestablish(const tal_t *ctx UNNEEDED, const struct channel_id *channel_id UNNEEDED, u64 next_commitment_number UNNEEDED, u64 next_revocation_number UNNEEDED, const struct secret *your_last_per_commitment_secret UNNEEDED, const struct pubkey *my_current_per_commitment_point UNNEEDED, const struct tlv_channel_reestablish_tlvs *tlvs UNNEEDED)
+u8 *towire_channel_reestablish(const tal_t *ctx UNNEEDED, const struct channel_id *channel_id UNNEEDED, u64 next_commitment_number UNNEEDED, u64 next_revocation_number UNNEEDED, const struct secret *your_last_per_commitment_secret UNNEEDED, const struct pubkey *my_current_per_commitment_point UNNEEDED, const struct tlv_channel_reestablish_tlvs *channel_reestablish UNNEEDED)
 { fprintf(stderr, "towire_channel_reestablish called!\n"); abort(); }
 /* Generated stub for towire_channeld_dev_memleak */
 u8 *towire_channeld_dev_memleak(const tal_t *ctx UNNEEDED)