diff --git a/bitcoin/test/run-psbt-from-tx.c b/bitcoin/test/run-psbt-from-tx.c index 85e2ca677100..d813fd4d3931 100644 --- a/bitcoin/test/run-psbt-from-tx.c +++ b/bitcoin/test/run-psbt-from-tx.c @@ -65,12 +65,12 @@ u8 *scriptpubkey_p2wsh(const tal_t *ctx UNNEEDED, const u8 *witnessscript UNNEED /* Generated stub for sha256_double */ void sha256_double(struct sha256_double *shadouble UNNEEDED, const void *p UNNEEDED, size_t len UNNEEDED) { fprintf(stderr, "sha256_double called!\n"); abort(); } +/* Generated stub for signature_from_der */ +bool signature_from_der(const u8 *der UNNEEDED, size_t len UNNEEDED, struct bitcoin_signature *sig UNNEEDED) +{ fprintf(stderr, "signature_from_der called!\n"); abort(); } /* Generated stub for signature_to_der */ size_t signature_to_der(u8 der[73] UNNEEDED, const struct bitcoin_signature *sig UNNEEDED) { fprintf(stderr, "signature_to_der called!\n"); abort(); } -/* Generated stub for signature_to_der */ -bool signature_from_der(const u8 *der UNNEEDED, size_t len UNNEEDED, struct bitcoin_signature *sig UNNEEDED) -{ fprintf(stderr, "signature_from_der called!\n"); abort(); } /* Generated stub for towire_sha256_double */ void towire_sha256_double(u8 **pptr UNNEEDED, const struct sha256_double *sha256d UNNEEDED) { fprintf(stderr, "towire_sha256_double called!\n"); abort(); } diff --git a/common/test/run-splice_script.c b/common/test/run-splice_script.c index 43bd579a3389..efabe4b293d0 100644 --- a/common/test/run-splice_script.c +++ b/common/test/run-splice_script.c @@ -35,6 +35,7 @@ void command_log(struct command *cmd UNNEEDED, enum log_level level UNNEEDED, const char *fmt UNNEEDED, ...) { fprintf(stderr, "command_log called!\n"); abort(); } +/* Generated stub for mvt_tag_str */ const char *mvt_tag_str(enum mvt_tag tag UNNEEDED) { fprintf(stderr, "mvt_tag_str called!\n"); abort(); } /* AUTOGENERATED MOCKS END */ diff --git a/common/trace.c b/common/trace.c index dd6df82b7063..bf62c7776ade 100644 --- a/common/trace.c +++ b/common/trace.c @@ -269,6 +269,12 @@ void trace_span_tag(const void *key, const char *name, const char *value) size_t s = tal_count(span->tags); tal_resize(&span->tags, s + 1); span->tags[s].name = tal_strdup(span->tags, name); + if (strstarts(value, "\"") + && strlen(value) > 1 + && strends(value, "\"")) { + value = tal_strndup(tmpctx, value + 1, + strlen(value) - 2); + } span->tags[s].value = tal_strdup(span->tags, value); } diff --git a/plugins/Makefile b/plugins/Makefile index efe64d379d58..b59df4b16d48 100644 --- a/plugins/Makefile +++ b/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 := \ diff --git a/plugins/bkpr/test/run-bkpr_db.c b/plugins/bkpr/test/run-bkpr_db.c index 308110548ec1..b2c555bca525 100644 --- a/plugins/bkpr/test/run-bkpr_db.c +++ b/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) diff --git a/plugins/bkpr/test/run-recorder.c b/plugins/bkpr/test/run-recorder.c index 85c901200fad..5f1b5cf80aeb 100644 --- a/plugins/bkpr/test/run-recorder.c +++ b/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) diff --git a/plugins/libplugin-pay.c b/plugins/libplugin-pay.c index ed78d76815d2..17254703ff07 100644 --- a/plugins/libplugin-pay.c +++ b/plugins/libplugin-pay.c @@ -11,9 +11,11 @@ #include #include #include +#include #include #include #include +#include #include #include @@ -2250,6 +2252,18 @@ static struct command_result *payment_finished(struct payment *p) return command_finished(cmd, ret); } +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; @@ -2264,12 +2278,17 @@ struct command_result *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); @@ -2277,6 +2296,8 @@ struct command_result *payment_continue(struct payment *p) /* 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: @@ -2299,6 +2320,7 @@ struct command_result *payment_continue(struct payment *p) return command_still_pending(payment_cmd(p)); } } + 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(); diff --git a/plugins/libplugin.c b/plugins/libplugin.c index e64c9b99b282..3a9148b572be 100644 --- a/plugins/libplugin.c +++ b/plugins/libplugin.c @@ -15,6 +15,7 @@ #include #include #include +#include #include #include #include @@ -1058,7 +1059,14 @@ static void handle_rpc_reply(struct plugin *plugin, const jsmntok_t *toks) cmd_freed = false; tal_add_destructor2(out->cmd, destroy_cmd_mark_freed, &cmd_freed); + trace_span_resume(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 ? "true" : "false"); + trace_span_end(out); + if (contenttok) { if (out->errcb) res = out->errcb(out->cmd, out->method, buf, contenttok, out->arg); @@ -1096,6 +1104,14 @@ send_outreq(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(req->cmd->plugin, req->js); notleak_with_children(req->cmd); return &pending; diff --git a/plugins/test/run-route-calc.c b/plugins/test/run-route-calc.c index 6cef7eeee5ed..98c3e61f3bcb 100644 --- a/plugins/test/run-route-calc.c +++ b/plugins/test/run-route-calc.c @@ -283,7 +283,7 @@ void memleak_scan_htable(struct htable *memtable UNNEEDED, const struct htable * void *notleak_(void *ptr UNNEEDED, bool plus_children UNNEEDED) { fprintf(stderr, "notleak_ called!\n"); abort(); } /* Generated stub for plugin_err */ -void plugin_err(struct plugin *p UNNEEDED, const char *fmt UNNEEDED, ...) +void plugin_err(struct plugin *p UNNEEDED, const char *fmt UNNEEDED, ...) { fprintf(stderr, "plugin_err called!\n"); abort(); } /* Generated stub for plugin_log */ void plugin_log(struct plugin *p UNNEEDED, enum log_level l UNNEEDED, const char *fmt UNNEEDED, ...) @@ -314,6 +314,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 diff --git a/plugins/test/run-route-overlong.c b/plugins/test/run-route-overlong.c index 3e7bacfc2622..5fc606f5e59d 100644 --- a/plugins/test/run-route-overlong.c +++ b/plugins/test/run-route-overlong.c @@ -280,7 +280,7 @@ void memleak_scan_htable(struct htable *memtable UNNEEDED, const struct htable * void *notleak_(void *ptr UNNEEDED, bool plus_children UNNEEDED) { fprintf(stderr, "notleak_ called!\n"); abort(); } /* Generated stub for plugin_err */ -void plugin_err(struct plugin *p UNNEEDED, const char *fmt UNNEEDED, ...) +void plugin_err(struct plugin *p UNNEEDED, const char *fmt UNNEEDED, ...) { fprintf(stderr, "plugin_err called!\n"); abort(); } /* Generated stub for plugin_log */ void plugin_log(struct plugin *p UNNEEDED, enum log_level l UNNEEDED, const char *fmt UNNEEDED, ...) @@ -311,6 +311,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