From 57ef0a6d8662e9854dc5711922f801c3da381071 Mon Sep 17 00:00:00 2001 From: Joshua Richter Date: Fri, 28 Aug 2026 11:34:47 -0400 Subject: [PATCH] fix(traces): stop an unreadable span timestamp from becoming a real duration strtoll answers 0 for text it cannot read, and cbm_parse_duration handed that 0 straight into its subtraction. The report of this said the result was a false duration of zero. It is worse than that. An unreadable START time reads as 0, so the span reports the whole END time as its duration: FAIL tests/test_traces.c:340: info.duration_ns == 1050000000, expected CBM_DURATION_UNKNOWN == -1 That is 1.05 seconds of measured time for a span whose start was never read. Nothing downstream can tell that number from a real one. The fix keeps cbm_parse_duration exactly as it is. It is public, it is declared in traces.h, and eight tests pin its answers -- 0 for a NULL argument, 0 for an end at or before the start. None of that moves. A companion carries the extra answer instead: int64_t cbm_parse_duration_checked(const char *start, const char *end, bool *ok); Both reads go through one small reader that follows src/main.c:1104 -- an end pointer, errno, and a check that nothing was left over -- plus a refusal of a leading blank, which strtoll would otherwise step over. cbm_extract_http_info now uses the companion and writes CBM_DURATION_UNKNOWN (-1) when the timestamps do not read. It still returns true, because the method and path on that span are still good data and dropping them would punish them for a fault they had no part in. -1 as "not recorded" is the sentinel this codebase already uses for the same question, in CBM_EDGE_CONF_ABSENT. The duration_ns field comment in traces.h now says so, so a reader who meets -1 has something to read. Scope note: cbm_extract_http_info has no production caller on this tree. rg finds it only in src/traces/traces.c, src/traces/traces.h and tests, and handle_ingest_traces in src/mcp/mcp.c never touches a timestamp. So this is a defect in a public, tested function rather than one putting bad rows in a graph today. Two tests come with the change. The one that pins the behaviour was seen failing first -- the FAIL line above is from that run. After the fix, TEST_SUITES="traces" reports 32 passed, 0 failed, exit 0. The full suite reports 7633 passed, 2 failed. Both failures are in tests/test_cli.c (lines 1749 and 6725), print "error: one or more agent cleanup operations failed", and reproduce on a clean tree without this change. make -f Makefile.cbm lint-ci passes. Co-Authored-By: Claude Opus 5 (1M context) Signed-off-by: Joshua Richter --- src/traces/traces.c | 43 ++++++++++++++++++++++++- src/traces/traces.h | 15 ++++++++- tests/test_traces.c | 78 +++++++++++++++++++++++++++++++++++++++++++++ 3 files changed, 134 insertions(+), 2 deletions(-) diff --git a/src/traces/traces.c b/src/traces/traces.c index f10eae249..0919d3b77 100644 --- a/src/traces/traces.c +++ b/src/traces/traces.c @@ -6,6 +6,8 @@ #include "foundation/constants.h" enum { TRACE_PATH_SLASHES = 3, TRACE_NOT_FOUND = -1 }; +#include +#include #include #include #include @@ -63,6 +65,38 @@ const char *cbm_extract_path_from_url(const char *url, char *buf, size_t buf_sz) /* ── parseDuration ───────────────────────────────────────────────── */ +/* Read one nanosecond timestamp. Answers false for text that does not read + * cleanly from its first character to its last, the way src/main.c:1104 does + * it: an end pointer says where the read stopped, errno catches a number too + * large, and *end == '\0' catches anything left over. A leading blank is + * refused too, because strtoll would otherwise step over it. */ +static bool trace_read_nano(const char *text, int64_t *out) { + if (!text || !text[0] || isspace((unsigned char)text[0])) { + return false; + } + char *end = NULL; + errno = 0; + long long value = strtoll(text, &end, CBM_DECIMAL_BASE); + if (errno != 0 || !end || end == text || *end != '\0') { + return false; + } + *out = (int64_t)value; + return true; +} + +int64_t cbm_parse_duration_checked(const char *start_nano, const char *end_nano, bool *ok) { + int64_t start = 0; + int64_t end = 0; + bool read_both = trace_read_nano(start_nano, &start) && trace_read_nano(end_nano, &end); + if (ok) { + *ok = read_both; + } + if (!read_both) { + return 0; + } + return (end > start) ? (end - start) : 0; +} + int64_t cbm_parse_duration(const char *start_nano, const char *end_nano) { if (!start_nano || !end_nano) { return 0; @@ -115,7 +149,14 @@ bool cbm_extract_http_info(const cbm_trace_span_t *span, const char *service_nam return false; } - out->duration_ns = cbm_parse_duration(span->start_time, span->end_time); + /* A timestamp nobody can read is not a measurement. It used to read as 0, + * so an unreadable START time reported the whole end time as the duration + * -- a made-up number that looks like a real one. The HTTP method and path + * on this span are still good, so the span is still returned and only the + * duration says it is missing. */ + bool timed = false; + int64_t duration = cbm_parse_duration_checked(span->start_time, span->end_time, &timed); + out->duration_ns = timed ? duration : CBM_DURATION_UNKNOWN; return true; } diff --git a/src/traces/traces.h b/src/traces/traces.h index ff628e44d..3f18e37ea 100644 --- a/src/traces/traces.h +++ b/src/traces/traces.h @@ -43,6 +43,8 @@ typedef struct { const char *path; const char *status_code; int span_kind; + /* Nanoseconds, or CBM_DURATION_UNKNOWN when the span's timestamps could + * not be read. A duration of 0 means the span really took no time. */ int64_t duration_ns; } cbm_http_span_info_t; @@ -62,9 +64,20 @@ bool cbm_extract_http_info(const cbm_trace_span_t *span, const char *service_nam * Writes to buf (up to buf_sz). Returns buf, or "" if not a valid URL. */ const char *cbm_extract_path_from_url(const char *url, char *buf, size_t buf_sz); -/* Parse nanosecond timestamp strings and return duration. */ +/* A duration nobody could measure. Kept apart from 0, which is a real span + * that took no time. */ +#define CBM_DURATION_UNKNOWN (-1) + +/* Parse nanosecond timestamp strings and return duration. Text that cannot be + * read counts as 0, so an unreadable timestamp and a span that took no time + * give the same answer. Use cbm_parse_duration_checked when that matters. */ int64_t cbm_parse_duration(const char *start_nano, const char *end_nano); +/* Same, and also says whether both timestamps could be read. *ok is false for + * a NULL argument and for any text that does not read cleanly end to end, so + * a caller can tell "took no time" from "nobody could measure this". */ +int64_t cbm_parse_duration_checked(const char *start_nano, const char *end_nano, bool *ok); + /* Calculate P99 from an array of int64_t values. * Sorts values in-place. Returns 0 for empty array. */ int64_t cbm_calculate_p99(int64_t *values, int count); diff --git a/tests/test_traces.c b/tests/test_traces.c index 18d02a90d..efae8918f 100644 --- a/tests/test_traces.c +++ b/tests/test_traces.c @@ -265,6 +265,82 @@ TEST(traces_parse_duration_large_values) { PASS(); } +/* A timestamp the code cannot read is not a measurement of no time. + * + * strtoll answers 0 for text it cannot read, and the subtraction guard turns + * that into a duration of 0 ns. A span that genuinely took no time and a span + * whose timestamps were garbage then look the same, and no later query can + * tell them apart. cbm_parse_duration_checked reports which one it read. */ +TEST(traces_parse_duration_checked_reports_unreadable_timestamps) { + bool ok = false; + + /* Positive control: a good pair still reads, and still answers the same + * number cbm_parse_duration answers. */ + int64_t d = cbm_parse_duration_checked("1000000000", "1050000000", &ok); + ASSERT(ok); + ASSERT_EQ(d, 50000000); + + /* A real measurement of no time reads fine. Zero is an answer here. */ + ok = false; + d = cbm_parse_duration_checked("5000000000", "5000000000", &ok); + ASSERT(ok); + ASSERT_EQ(d, 0); + + /* End before start reads fine too. The clamp to 0 is the caller's rule, + * not a reading failure. */ + ok = false; + d = cbm_parse_duration_checked("1000", "500", &ok); + ASSERT(ok); + ASSERT_EQ(d, 0); + + /* The claim: text that does not read is reported, not folded into 0. */ + const char *unreadable[] = {"abc", "", " 100", "100ns", "1e9"}; + for (size_t i = 0; i < sizeof(unreadable) / sizeof(unreadable[0]); i++) { + ok = true; + (void)cbm_parse_duration_checked(unreadable[i], "1050000000", &ok); + ASSERT(!ok); + ok = true; + (void)cbm_parse_duration_checked("1000000000", unreadable[i], &ok); + ASSERT(!ok); + } + + /* A NULL argument was never a measurement either. */ + ok = true; + (void)cbm_parse_duration_checked(NULL, "1000", &ok); + ASSERT(!ok); + ok = true; + (void)cbm_parse_duration_checked("1000", NULL, &ok); + ASSERT(!ok); + PASS(); +} + +/* A span whose timestamps cannot be read keeps its method and path, and says + * the duration was not recorded rather than claiming it was zero. */ +TEST(traces_extract_http_info_marks_unreadable_duration) { + cbm_trace_attr_t attrs[] = { + {.key = "http.method", .string_value = "GET"}, + {.key = "http.route", .string_value = "/api/orders"}, + {.key = "http.status_code", .string_value = "200"}, + }; + cbm_trace_span_t span = { + .kind = 2, + .attributes = attrs, + .attr_count = 3, + .start_time = "not-a-timestamp", + .end_time = "1050000000", + }; + + cbm_http_span_info_t info; + bool ok = cbm_extract_http_info(&span, "svc", &info); + /* The HTTP part of the span is still good data, so it is still returned. */ + ASSERT(ok); + ASSERT_STR_EQ(info.method, "GET"); + ASSERT_STR_EQ(info.path, "/api/orders"); + /* The claim: not recorded, rather than a duration of zero. */ + ASSERT_EQ(info.duration_ns, CBM_DURATION_UNKNOWN); + PASS(); +} + /* ── TestCalculateP99 — edge cases ────────────────────────────────── */ TEST(traces_calculate_p99_100_values) { @@ -341,4 +417,6 @@ SUITE(traces) { RUN_TEST(traces_parse_duration_both_null); RUN_TEST(traces_parse_duration_equal); RUN_TEST(traces_parse_duration_large_values); + RUN_TEST(traces_parse_duration_checked_reports_unreadable_timestamps); + RUN_TEST(traces_extract_http_info_marks_unreadable_duration); }