From 924f28adcbe61bf8099f7df0fb0d26ad18ce5538 Mon Sep 17 00:00:00 2001 From: Rusty Russell Date: Wed, 23 Apr 2025 10:24:18 +0930 Subject: [PATCH] pytest: add test hooks so we can test tracing. Suggested-by: Christian Decker Signed-off-by: Rusty Russell --- common/trace.c | 42 ++++++++++++++++++++++++++++++++++++ tests/test_misc.py | 54 ++++++++++++++++++++++++++++++++++++++++++++++ 2 files changed, 96 insertions(+) diff --git a/common/trace.c b/common/trace.c index d85c61afb..c92a82dd4 100644 --- a/common/trace.c +++ b/common/trace.c @@ -1,5 +1,6 @@ #include "config.h" #include +#include #include #include #include @@ -8,6 +9,7 @@ #include #include #include +#include #include #include #include @@ -42,6 +44,7 @@ const char *trace_service_name = "lightningd"; static bool disable_trace = false; +static FILE *trace_to_file = NULL; struct span_tag { char *name, *value; @@ -151,11 +154,20 @@ 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)); 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(); } @@ -250,6 +262,10 @@ static void trace_emit(struct span *s) tal_append_fmt(&res, "}, \"traceId\": \"%s\"}]", trace_id); DTRACE_PROBE2(lightningd, span_emit, span_id, res); + if (trace_to_file) { + fprintf(trace_to_file, "span_emit %s %s\n", span_id, res); + fflush(trace_to_file); + } tal_free(res); } @@ -301,6 +317,12 @@ void trace_span_start(const char *name, const void *key) current = s; trace_check_tree(); DTRACE_PROBE1(lightningd, span_start, s->id); + if (trace_to_file) { + char span_id[HEX_SPAN_ID_SIZE]; + hex_encode(s->id, SPAN_ID_SIZE, span_id, HEX_SPAN_ID_SIZE); + fprintf(trace_to_file, "span_start %s\n", span_id); + fflush(trace_to_file); + } } void trace_span_remote(u8 trace_id[TRACE_ID_SIZE], u8 span_id[SPAN_ID_SIZE]) @@ -323,6 +345,12 @@ 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) { + char span_id[HEX_SPAN_ID_SIZE]; + hex_encode(s->id, SPAN_ID_SIZE, span_id, HEX_SPAN_ID_SIZE); + fprintf(trace_to_file, "span_end %s\n", span_id); + fflush(trace_to_file); + } trace_emit(s); /* Reset the context span we are in. */ @@ -375,6 +403,12 @@ void trace_span_suspend_(const void *key, const char *lbl) span->suspended = true; current = NULL; DTRACE_PROBE1(lightningd, span_suspend, span->id); + if (trace_to_file) { + char span_id[HEX_SPAN_ID_SIZE]; + hex_encode(span->id, SPAN_ID_SIZE, span_id, HEX_SPAN_ID_SIZE); + fprintf(trace_to_file, "span_suspend %s\n", span_id); + fflush(trace_to_file); + } } static void destroy_trace_span(const void *key) @@ -387,6 +421,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); } @@ -410,6 +446,12 @@ void trace_span_resume_(const void *key, const char *lbl) 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) { + char span_id[HEX_SPAN_ID_SIZE]; + hex_encode(current->id, SPAN_ID_SIZE, span_id, HEX_SPAN_ID_SIZE); + fprintf(trace_to_file, "span_resume %s\n", span_id); + fflush(trace_to_file); + } } void trace_cleanup(void) diff --git a/tests/test_misc.py b/tests/test_misc.py index a8547e0c7..3a5232f45 100644 --- a/tests/test_misc.py +++ b/tests/test_misc.py @@ -13,6 +13,7 @@ from utils import ( ) import copy +import glob import json import os import pytest @@ -4697,3 +4698,56 @@ 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()