diff --git a/common/test/Makefile b/common/test/Makefile index 444803342f99..75331d62e6dc 100644 --- a/common/test/Makefile +++ b/common/test/Makefile @@ -118,6 +118,7 @@ common/test/run-splice_script: \ common/test/run-trace: \ common/amount.o \ common/memleak.o \ + common/pseudorand.o \ common/trace.o \ wire/fromwire.o \ wire/towire.o diff --git a/common/test/run-trace.c b/common/test/run-trace.c index 99fd94b69484..7811f68c91dd 100644 --- a/common/test/run-trace.c +++ b/common/test/run-trace.c @@ -13,16 +13,20 @@ int main(int argx, char *argv[]) common_setup(argv[0]); /* Create a bunch of nested spans to emit. */ - for(int i=0; i<25000; i++) { + for(int i=0; i<2500000; i++) { trace_span_start("a", &a); + trace_span_tag(&a, "method", "getrawblockbyheight"); trace_span_start("b", &b); + trace_span_tag(&b, "method", "getrawblockbyheight"); trace_span_start("c", &c); + trace_span_tag(&c, "method", "getrawblockbyheight"); trace_span_end(&c); trace_span_end(&b); trace_span_start("d", &d); + trace_span_tag(&d, "method", "getrawblockbyheight"); trace_span_end(&d); trace_span_end(&a); diff --git a/common/trace.c b/common/trace.c index 5bd5fa5647fa..c65d7f374fec 100644 --- a/common/trace.c +++ b/common/trace.c @@ -1,25 +1,22 @@ #include "config.h" #include -#include +#include +#include #include #include #include #include #include #include +#include #include -#include +#include #include #include #if HAVE_USDT #include -#define MAX_ACTIVE_SPANS 128 - -#define HEX_SPAN_ID_SIZE (2*SPAN_ID_SIZE+1) -#define HEX_TRACE_ID_SIZE (2 * TRACE_ID_SIZE + 1) - /* The traceperent format is defined in W3C Trace Context RFC[1]. * Its format is defined as * @@ -42,20 +39,22 @@ const char *trace_service_name = "lightningd"; static bool disable_trace = false; +static FILE *trace_to_file = NULL; + +#define SPAN_MAX_TAGS 2 struct span_tag { - char *name, *value; + const char *name; + const char *valuestr; + int valuelen; }; struct span { /* Our own id */ - u8 id[SPAN_ID_SIZE]; - - /* 0 if we have no parent. */ - u8 parent_id[SPAN_ID_SIZE]; + u64 id; /* The trace_id for this span and all its children. */ - u8 trace_id[TRACE_ID_SIZE]; + u64 trace_id_hi, trace_id_lo; u64 start_time; u64 end_time; @@ -64,20 +63,45 @@ struct span { * spans. */ size_t key; struct span *parent; - struct span_tag *tags; - char *name; - - /* Indicate whether this is a remote span, i.e., it was - inherited by some other process, which is in charge of - emitting the span. This just means that we don't emit this - span ourselves, but we want to add child spans to the remote - span. */ - bool remote; + struct span_tag tags[SPAN_MAX_TAGS]; + const char *name; + + bool suspended; }; static struct span *active_spans = NULL; static struct span *current; +static void init_span(struct span *s, + size_t key, + const char *name, + struct span *parent) +{ + struct timeabs now = time_now(); + + s->key = key; + s->id = pseudorand_u64(); + s->start_time = (now.ts.tv_sec * 1000000) + now.ts.tv_nsec / 1000; + s->parent = parent; + s->name = name; + s->suspended = false; + + /* If this is a new root span we also need to associate a new + * trace_id with it. */ + if (!s->parent) { + s->trace_id_hi = pseudorand_u64(); + s->trace_id_lo = pseudorand_u64(); + } else { + s->trace_id_hi = current->trace_id_hi; + s->trace_id_lo = current->trace_id_lo; + } +} + +/* FIXME: forward decls for minimal patch size */ +static struct span *trace_span_slot(void); +static size_t trace_key(const void *key); +static void trace_span_clear(struct span *s); + /* If the `CLN_TRACEPARENT` envvar is set, we inject that as the * parent for the startup. This allows us to integrate the startup * tracing with whatever tooling we build around it. This only has an @@ -85,22 +109,31 @@ static struct span *current; * own parent. */ static void trace_inject_traceparent(void) { - char *traceparent; + const char *traceparent; + be64 trace_hi, trace_lo, span; + traceparent = getenv("CLN_TRACEPARENT"); if (!traceparent) return; assert(strlen(traceparent) == TRACEPARENT_LEN); - trace_span_start("", active_spans); - current->remote = true; + current = trace_span_slot(); + assert(current); + + init_span(current, trace_key(&active_spans), "", NULL); assert(current && !current->parent); - if (!hex_decode(traceparent + 3, 2*TRACE_ID_SIZE, current->trace_id, - TRACE_ID_SIZE) || - !hex_decode(traceparent + 36, 2*SPAN_ID_SIZE, current->id, - SPAN_ID_SIZE)) { + + if (!hex_decode(traceparent + 3, 16, &trace_hi, sizeof(trace_hi)) + || !hex_decode(traceparent + 3 + 16, 16, &trace_lo, sizeof(trace_lo)) + || !hex_decode(traceparent + 3 + 16 + 16 + 1, 16, &span, sizeof(span))) { /* We failed to parse the traceparent, abandon. */ fprintf(stderr, "Failed!"); - trace_span_end(active_spans); + trace_span_clear(current); + current = NULL; + } else { + current->trace_id_hi = be64_to_cpu(trace_hi); + current->trace_id_lo = be64_to_cpu(trace_lo); + current->id = be64_to_cpu(span); } } @@ -109,7 +142,7 @@ static void trace_inject_traceparent(void) /** Quickly print out the entries in the `active_spans`. */ static void trace_spans_print(void) { - for (size_t j = 0; j < MAX_ACTIVE_SPANS; j++) { + for (size_t j = 0; j < tal_count(active_spans); j++) { struct span *s = &active_spans[j], *parent = s->parent; TRACE_DBG(" > %zu: %s (key=%zu, parent=%s, " "parent_key=%zu)\n", @@ -120,17 +153,17 @@ static void trace_spans_print(void) /** Small helper to check for consistency in the linking. The idea is * that we should be able to reach the root (a span without a - * `parent`) in less than `MAX_ACTIVE_SPANS` steps. */ + * `parent`) in less than the number of spans. */ static void trace_check_tree(void) { /* `current` is either NULL or a valid entry. */ /* Walk the tree structure from leaves to their roots. It - * should not take more than `MAX_ACTIVE_SPANS`. */ + * should not take more than the number of spans. */ struct span *c; - for (size_t i = 0; i < MAX_ACTIVE_SPANS; i++) { + for (size_t i = 0; i < tal_count(active_spans); i++) { c = &active_spans[i]; - for (int j = 0; j < MAX_ACTIVE_SPANS; j++) + for (int j = 0; j < tal_count(active_spans); j++) if (c->parent == NULL) break; else @@ -150,11 +183,21 @@ static inline void trace_check_tree(void) {} static void trace_init(void) { + const char *dev_trace_file; if (active_spans) return; - active_spans = calloc(MAX_ACTIVE_SPANS, sizeof(struct span)); + + active_spans = notleak(tal_arrz(NULL, struct span, 1)); current = NULL; + dev_trace_file = getenv("CLN_DEV_TRACE_FILE"); + if (dev_trace_file) { + const char *fname = tal_fmt(tmpctx, "%s.%u", + dev_trace_file, (unsigned)getpid()); + trace_to_file = fopen(fname, "a+"); + if (!trace_to_file) + err(1, "Opening CLN_DEV_TRACE_FILE %s", fname); + } trace_inject_traceparent(); } @@ -168,7 +211,7 @@ static size_t trace_key(const void *key) static struct span *trace_span_find(size_t key) { - for (size_t i = 0; i < MAX_ACTIVE_SPANS; i++) + for (size_t i = 0; i < tal_count(active_spans); i++) if (active_spans[i].key == key) return &active_spans[i]; @@ -178,9 +221,6 @@ static struct span *trace_span_find(size_t key) return NULL; } -/* FIXME: Forward declaration for minimal patch size */ -static void trace_span_clear(struct span *s); - /** * Find an empty slot for a new span. */ @@ -190,14 +230,12 @@ static struct span *trace_span_slot(void) * that, and we should get an empty slot. */ struct span *s = trace_span_find(0); - /* Might end up here if we have more than MAX_ACTIVE_SPANS - * concurrent spans. */ + /* In the unlikely case this fails, double it */ if (!s) { - fprintf(stderr, "%u: out of spans, disabling tracing\n", getpid()); - for (size_t i = 0; i < MAX_ACTIVE_SPANS; i++) - trace_span_clear(&active_spans[i]); - disable_trace = true; - return NULL; + TRACE_DBG("%u: out of %zu spans, doubling!\n", + getpid(), tal_count(active_spans)); + tal_resizez(&active_spans, tal_count(active_spans) * 2); + s = trace_span_find(0); } assert(s->parent == NULL); @@ -210,46 +248,57 @@ static struct span *trace_span_slot(void) return s; } +#define MAX_BUF_SIZE 2048 + static void trace_emit(struct span *s) { - char span_id[HEX_SPAN_ID_SIZE]; - char trace_id[HEX_TRACE_ID_SIZE]; - char parent_span_id[HEX_SPAN_ID_SIZE]; - - /* If this is a remote span it's not up to us to emit it. Make - * this a no-op. `trace_span_end` will take care of cleaning - * the in-memory span up. */ - if (s->remote) - return; - - hex_encode(s->id, SPAN_ID_SIZE, span_id, HEX_SPAN_ID_SIZE); - hex_encode(s->trace_id, TRACE_ID_SIZE, trace_id, HEX_TRACE_ID_SIZE); + char span_id[hex_str_size(sizeof(s->id))]; + char buffer[MAX_BUF_SIZE + 1]; + size_t len; - if (s->parent) - hex_encode(s->parent_id, SPAN_ID_SIZE, parent_span_id, HEX_SPAN_ID_SIZE); - - char *res = tal_fmt( - NULL, - "[{\"id\": \"%s\", \"name\": \"%s\", " - "\"timestamp\": %" PRIu64 ", \"duration\": %" PRIu64 ",", - span_id, s->name, s->start_time, s->end_time - s->start_time); - - tal_append_fmt(&res, "\"localEndpoint\": { \"serviceName\": \"%s\"}, ", - trace_service_name); + snprintf(span_id, sizeof(span_id), "%016"PRIx64, s->id); + len = snprintf(buffer, MAX_BUF_SIZE, + "[{\"id\":\"%s\",\"name\":\"%s\"," + "\"timestamp\":%"PRIu64",\"duration\":%"PRIu64"," + "\"localEndpoint\":{\"serviceName\":\"%s\"},", + span_id, s->name, s->start_time, s->end_time - s->start_time, trace_service_name); if (s->parent != NULL) { - tal_append_fmt(&res, "\"parentId\": \"%s\",", parent_span_id); + len += snprintf(buffer + len, MAX_BUF_SIZE - len, + "\"parentId\":\"%016"PRIx64"\",", + s->parent->id); + if (len > MAX_BUF_SIZE) + len = MAX_BUF_SIZE; } - tal_append_fmt(&res, "\"tags\": {"); - for (size_t i = 0; i < tal_count(s->tags); i++) { - tal_append_fmt(&res, "%s\"%s\": \"%s\"", i == 0 ? "" : ", ", - s->tags[i].name, s->tags[i].value); + len += snprintf(buffer + len, MAX_BUF_SIZE - len, + "\"tags\":{"); + if (len > MAX_BUF_SIZE) + len = MAX_BUF_SIZE; + for (size_t i = 0; i < SPAN_MAX_TAGS; i++) { + if (!s->tags[i].name) + continue; + len += snprintf(buffer + len, MAX_BUF_SIZE - len, + "%s\"%s\":\"%.*s\"", i == 0 ? "" : ", ", + s->tags[i].name, + s->tags[i].valuelen, + s->tags[i].valuestr); + if (len > MAX_BUF_SIZE) + len = MAX_BUF_SIZE; } - tal_append_fmt(&res, "}, \"traceId\": \"%s\"}]", trace_id); - DTRACE_PROBE2(lightningd, span_emit, span_id, res); - tal_free(res); + len += snprintf(buffer + len, MAX_BUF_SIZE - len, + "},\"traceId\":\"%016"PRIx64"%016"PRIx64"\"}]", + s->trace_id_hi, s->trace_id_lo); + if (len > MAX_BUF_SIZE) + len = MAX_BUF_SIZE; + buffer[len] = '\0'; + /* FIXME: span_id here is in hex, could be u64? */ + DTRACE_PROBE2(lightningd, span_emit, span_id, buffer); + if (trace_to_file) { + fprintf(trace_to_file, "span_emit %s %s\n", span_id, buffer); + fflush(trace_to_file); + } } /** @@ -257,19 +306,12 @@ static void trace_emit(struct span *s) */ static void trace_span_clear(struct span *s) { - s->key = 0; - memset(s->id, 0, SPAN_ID_SIZE); - memset(s->trace_id, 0, TRACE_ID_SIZE); - ; - s->parent = NULL; - s->name = tal_free(s->name); - s->tags = tal_free(s->tags); + memset(s, 0, sizeof(*s)); } -void trace_span_start(const char *name, const void *key) +void trace_span_start_(const char *name, const void *key) { size_t numkey = trace_key(key); - struct timeabs now = time_now(); if (disable_trace) return; @@ -280,28 +322,17 @@ void trace_span_start(const char *name, const void *key) struct span *s = trace_span_slot(); if (!s) return; - s->key = numkey; - randombytes_buf(s->id, SPAN_ID_SIZE); - s->start_time = (now.ts.tv_sec * 1000000) + now.ts.tv_nsec / 1000; - s->parent = current; - s->tags = notleak(tal_arr(NULL, struct span_tag, 0)); - s->name = notleak(tal_strdup(NULL, name)); - - /* If this is a new root span we also need to associate a new - * trace_id with it. */ - if (!current) { - randombytes_buf(s->trace_id, TRACE_ID_SIZE); - } else { - memcpy(s->parent_id, current->id, SPAN_ID_SIZE); - memcpy(s->trace_id, current->trace_id, TRACE_ID_SIZE); - } - + init_span(s, numkey, name, current); current = s; trace_check_tree(); DTRACE_PROBE1(lightningd, span_start, s->id); + if (trace_to_file) { + fprintf(trace_to_file, "span_start %016"PRIx64"\n", s->id); + fflush(trace_to_file); + } } -void trace_span_remote(u8 trace_id[TRACE_ID_SIZE], u8 span_id[SPAN_ID_SIZE]) +void trace_span_remote(u64 trace_id_hi, u64 trade_id_lo, u64 span_id) { abort(); } @@ -321,6 +352,10 @@ void trace_span_end(const void *key) struct timeabs now = time_now(); s->end_time = (now.ts.tv_sec * 1000000) + now.ts.tv_nsec / 1000; DTRACE_PROBE1(lightningd, span_end, s->id); + if (trace_to_file) { + fprintf(trace_to_file, "span_end %016"PRIx64"\n", s->id); + fflush(trace_to_file); + } trace_emit(s); /* Reset the context span we are in. */ @@ -328,14 +363,6 @@ void trace_span_end(const void *key) /* Now reset the span */ trace_span_clear(s); - - /* One last special case: if the parent is remote, it must be - * the root. And we should terminate that trace along with - * this one. */ - if (current && current->remote) { - assert(current->parent == NULL); - current = NULL; - } trace_check_tree(); } @@ -344,20 +371,27 @@ void trace_span_tag(const void *key, const char *name, const char *value) if (disable_trace) return; + assert(name); size_t numkey = trace_key(key); struct span *span = trace_span_find(numkey); assert(span); - 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); + for (size_t i = 0; i < SPAN_MAX_TAGS; i++) { + struct span_tag *t = &span->tags[i]; + if (!t->name) { + t->name = name; + t->valuestr = value; + t->valuelen = strlen(value); + if (t->valuestr[0] == '"' + && t->valuelen > 1 + && t->valuestr[t->valuelen-1] == '"') { + t->valuestr++; + t->valuelen -= 2; + } + return; + } } - span->tags[s].value = tal_strdup(span->tags, value); + abort(); } void trace_span_suspend_(const void *key, const char *lbl) @@ -369,8 +403,14 @@ void trace_span_suspend_(const void *key, const char *lbl) struct span *span = trace_span_find(numkey); TRACE_DBG("Suspending span %s (%zu)\n", current->name, current->key); assert(current == span); - current = NULL; + assert(!span->suspended); + span->suspended = true; + current = current->parent; DTRACE_PROBE1(lightningd, span_suspend, span->id); + if (trace_to_file) { + fprintf(trace_to_file, "span_suspend %016"PRIx64"\n", span->id); + fflush(trace_to_file); + } } static void destroy_trace_span(const void *key) @@ -383,6 +423,8 @@ static void destroy_trace_span(const void *key) return; /* Otherwise resume so we can terminate it */ + if (trace_to_file) + fprintf(trace_to_file, "destroying span\n"); trace_span_resume(key); trace_span_end(key); } @@ -402,19 +444,24 @@ void trace_span_resume_(const void *key, const char *lbl) size_t numkey = trace_key(key); current = trace_span_find(numkey); + assert(current->suspended); + current->suspended = false; TRACE_DBG("Resuming span %s (%zu)\n", current->name, current->key); DTRACE_PROBE1(lightningd, span_resume, current->id); + if (trace_to_file) { + fprintf(trace_to_file, "span_resume %016"PRIx64"\n", current->id); + fflush(trace_to_file); + } } void trace_cleanup(void) { - free(active_spans); - active_spans = NULL; + active_spans = tal_free(active_spans); } #else /* HAVE_USDT */ -void trace_span_start(const char *name, const void *key) {} +void trace_span_start_(const char *name, const void *key) {} void trace_span_end(const void *key) {} void trace_span_suspend_(const void *key, const char *lbl) {} void trace_span_suspend_may_free_(const void *key, const char *lbl) {} diff --git a/common/trace.h b/common/trace.h index d8996684b9d7..fe3649af58b5 100644 --- a/common/trace.h +++ b/common/trace.h @@ -3,15 +3,15 @@ #include "config.h" #include -#define SPAN_ID_SIZE 8 -#define TRACE_ID_SIZE 16 #undef TRACE_DEBUG -void trace_span_start(const char *name, const void *key); +/* name must be a string constant */ +#define trace_span_start(name, key) trace_span_start_(name "", (key)) +void trace_span_start_(const char *name, const void *key); void trace_span_end(const void *key); void trace_span_tag(const void *key, const char *name, const char *value); void trace_cleanup(void); -void trace_span_remote(u8 trace_id[TRACE_ID_SIZE], u8 span_id[SPAN_ID_SIZE]); +void trace_span_remote(u64 trace_id_hi, u64 trade_id_lo, u64 span_id); #define TRACE_LBL __FILE__ ":" stringify(__LINE__) void trace_span_suspend_(const void *key, const char *lbl); diff --git a/lightningd/lightningd.c b/lightningd/lightningd.c index a5d46e7f35ca..756cae072c23 100644 --- a/lightningd/lightningd.c +++ b/lightningd/lightningd.c @@ -1409,14 +1409,6 @@ int main(int argc, char *argv[]) /*~ Now handle sigchld, so we can clean up appropriately. */ sigchld_conn = notleak(io_new_conn(ld, sigchld_rfd, sigchld_rfd_in, ld)); - /* This span was started before handing control to `io_loop` - * which suspends active spans in-between processing - * events. Depending on how the `io_loop` was interrupted, the - * current context span may have been suspended. We need to - * manually resume it for this case. Notice that resuming is - * idempotent, and doing so repeatedly is safe. - */ - trace_span_resume(argv); trace_span_end(argv); /*~ Mark ourselves live. diff --git a/lightningd/test/run-find_my_abspath.c b/lightningd/test/run-find_my_abspath.c index 59b0b80f57a8..47e5553b0727 100644 --- a/lightningd/test/run-find_my_abspath.c +++ b/lightningd/test/run-find_my_abspath.c @@ -269,9 +269,9 @@ void trace_span_end(const void *key UNNEEDED) /* Generated stub for trace_span_resume_ */ void trace_span_resume_(const void *key UNNEEDED, const char *lbl 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_start_ */ +void trace_span_start_(const char *name UNNEEDED, const void *key UNNEEDED) +{ fprintf(stderr, "trace_span_start_ called!\n"); abort(); } /* Generated stub for txfilter_add_derkey */ void txfilter_add_derkey(struct txfilter *filter UNNEEDED, const u8 derkey[PUBKEY_CMPR_LEN]) diff --git a/lightningd/test/run-jsonrpc.c b/lightningd/test/run-jsonrpc.c index f337c24e35b4..cf064ca891a4 100644 --- a/lightningd/test/run-jsonrpc.c +++ b/lightningd/test/run-jsonrpc.c @@ -176,9 +176,9 @@ void towire_node_id(u8 **pptr UNNEEDED, const struct node_id *id UNNEEDED) /* 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_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(); } diff --git a/plugins/bkpr/test/run-bkpr_db.c b/plugins/bkpr/test/run-bkpr_db.c index 10ba59aea78f..ecf21f1772c7 100644 --- a/plugins/bkpr/test/run-bkpr_db.c +++ b/plugins/bkpr/test/run-bkpr_db.c @@ -219,6 +219,9 @@ bool param_check(struct command *cmd UNNEEDED, const char *buffer UNNEEDED, const jsmntok_t tokens[] UNNEEDED, ...) { fprintf(stderr, "param_check called!\n"); abort(); } +/* Generated stub for pseudorand_u64 */ +uint64_t pseudorand_u64(void) +{ fprintf(stderr, "pseudorand_u64 called!\n"); abort(); } /* Generated stub for toks_alloc */ jsmntok_t *toks_alloc(const tal_t *ctx UNNEEDED) { fprintf(stderr, "toks_alloc called!\n"); abort(); } diff --git a/plugins/bkpr/test/run-recorder.c b/plugins/bkpr/test/run-recorder.c index 16cd8e9b7877..8f46a7eee66f 100644 --- a/plugins/bkpr/test/run-recorder.c +++ b/plugins/bkpr/test/run-recorder.c @@ -225,6 +225,9 @@ bool param_check(struct command *cmd UNNEEDED, const char *buffer UNNEEDED, const jsmntok_t tokens[] UNNEEDED, ...) { fprintf(stderr, "param_check called!\n"); abort(); } +/* Generated stub for pseudorand_u64 */ +uint64_t pseudorand_u64(void) +{ fprintf(stderr, "pseudorand_u64 called!\n"); abort(); } /* Generated stub for toks_alloc */ jsmntok_t *toks_alloc(const tal_t *ctx UNNEEDED) { fprintf(stderr, "toks_alloc called!\n"); abort(); } diff --git a/plugins/test/run-route-calc.c b/plugins/test/run-route-calc.c index b9b575991c52..a0bdda823448 100644 --- a/plugins/test/run-route-calc.c +++ b/plugins/test/run-route-calc.c @@ -326,9 +326,9 @@ void towire_channel_id(u8 **pptr UNNEEDED, const struct channel_id *channel_id U /* 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_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(); } diff --git a/plugins/test/run-route-overlong.c b/plugins/test/run-route-overlong.c index d07c328c6f54..da6f0a607a03 100644 --- a/plugins/test/run-route-overlong.c +++ b/plugins/test/run-route-overlong.c @@ -323,9 +323,9 @@ void towire_channel_id(u8 **pptr UNNEEDED, const struct channel_id *channel_id U /* 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_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(); } diff --git a/tests/test_misc.py b/tests/test_misc.py index a8547e0c7ff6..bacaaab93252 100644 --- a/tests/test_misc.py +++ b/tests/test_misc.py @@ -13,6 +13,7 @@ ) import copy +import glob import json import os import pytest @@ -4697,3 +4698,80 @@ def test_bolt12_invoice_decode(node_factory): assert l1.rpc.decode(inv)['valid'] is True subprocess.run(["devtools/bolt12-cli", "decode", inv], check=True) + + +@unittest.skipIf(env('HAVE_USDT') != '1', "Test requires tracing compiled in") +def test_tracing(node_factory): + l1 = node_factory.get_node(start=False) + trace_fnamebase = os.path.join(l1.daemon.lightning_dir, TEST_NETWORK, "l1.trace") + l1.daemon.env["CLN_DEV_TRACE_FILE"] = trace_fnamebase + l1.start() + l1.stop() + + traces = set() + suspended = set() + for fname in glob.glob(f"{trace_fnamebase}.*"): + for linenum, l in enumerate(open(fname, "rt").readlines(), 1): + # In case an assertion fails + print(f"Parsing {fname}:{linenum}") + parts = l.split(maxsplit=2) + cmd = parts[0] + spanid = parts[1] + if cmd == 'span_emit': + assert spanid in traces + assert spanid not in suspended + # Should be valid JSON + res = json.loads(parts[2]) + + # This is an array for some reason + assert len(res) == 1 + res = res[0] + assert res['id'] == spanid + assert res['localEndpoint'] == {"serviceName": "lightningd"} + expected_keys = ['id', 'name', 'timestamp', 'duration', 'tags', 'traceId', 'localEndpoint'] + if 'parentId' in res: + assert res['parentId'] in traces + expected_keys.append('parentId') + assert set(res.keys()) == set(expected_keys) + traces.remove(spanid) + elif cmd == 'span_end': + assert spanid in traces + elif cmd == 'span_start': + assert spanid not in traces + traces.add(spanid) + elif cmd == 'span_suspend': + assert spanid in traces + assert spanid not in suspended + suspended.add(spanid) + elif cmd == 'span_resume': + assert spanid in traces + suspended.remove(spanid) + else: + assert False, "Unknown trace line" + + assert suspended == set() + assert traces == set() + + # Test parent trace + trace_fnamebase = os.path.join(l1.daemon.lightning_dir, TEST_NETWORK, "l1.parent.trace") + l1.daemon.env["CLN_DEV_TRACE_FILE"] = trace_fnamebase + l1.daemon.env["CLN_TRACEPARENT"] = "00-00112233445566778899aabbccddeeff-0123456789abcdef-00" + l1.start() + l1.stop() + + # The parent should set all the trace ids and span ids + for fname in glob.glob(f"{trace_fnamebase}.*"): + for linenum, l in enumerate(open(fname, "rt").readlines(), 1): + # In case an assertion fails + print(f"Parsing {fname}:{linenum}") + parts = l.split(maxsplit=2) + cmd = parts[0] + spanid = parts[1] + # This span doesn't actually appear anywhere + assert spanid != '0123456789abcdef' + if cmd == 'span_emit': + # Should be valid JSON + res = json.loads(parts[2]) + assert res[0]['traceId'] == '00112233445566778899aabbccddeeff' + # Everyone has a parent! + assert 'parentId' in res[0]