Skip to content

Commit 48c2d2e

Browse files
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) <noreply@anthropic.com> Signed-off-by: Joshua Richter <jrichter5781@gmail.com>
1 parent d706c33 commit 48c2d2e

3 files changed

Lines changed: 134 additions & 2 deletions

File tree

‎src/traces/traces.c‎

Lines changed: 42 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -6,6 +6,8 @@
66
#include "foundation/constants.h"
77

88
enum { TRACE_PATH_SLASHES = 3, TRACE_NOT_FOUND = -1 };
9+
#include <ctype.h>
10+
#include <errno.h>
911
#include <stdlib.h>
1012
#include <string.h>
1113
#include <stdio.h>
@@ -63,6 +65,38 @@ const char *cbm_extract_path_from_url(const char *url, char *buf, size_t buf_sz)
6365

6466
/* ── parseDuration ───────────────────────────────────────────────── */
6567

68+
/* Read one nanosecond timestamp. Answers false for text that does not read
69+
* cleanly from its first character to its last, the way src/main.c:1104 does
70+
* it: an end pointer says where the read stopped, errno catches a number too
71+
* large, and *end == '\0' catches anything left over. A leading blank is
72+
* refused too, because strtoll would otherwise step over it. */
73+
static bool trace_read_nano(const char *text, int64_t *out) {
74+
if (!text || !text[0] || isspace((unsigned char)text[0])) {
75+
return false;
76+
}
77+
char *end = NULL;
78+
errno = 0;
79+
long long value = strtoll(text, &end, CBM_DECIMAL_BASE);
80+
if (errno != 0 || !end || end == text || *end != '\0') {
81+
return false;
82+
}
83+
*out = (int64_t)value;
84+
return true;
85+
}
86+
87+
int64_t cbm_parse_duration_checked(const char *start_nano, const char *end_nano, bool *ok) {
88+
int64_t start = 0;
89+
int64_t end = 0;
90+
bool read_both = trace_read_nano(start_nano, &start) && trace_read_nano(end_nano, &end);
91+
if (ok) {
92+
*ok = read_both;
93+
}
94+
if (!read_both) {
95+
return 0;
96+
}
97+
return (end > start) ? (end - start) : 0;
98+
}
99+
66100
int64_t cbm_parse_duration(const char *start_nano, const char *end_nano) {
67101
if (!start_nano || !end_nano) {
68102
return 0;
@@ -115,7 +149,14 @@ bool cbm_extract_http_info(const cbm_trace_span_t *span, const char *service_nam
115149
return false;
116150
}
117151

118-
out->duration_ns = cbm_parse_duration(span->start_time, span->end_time);
152+
/* A timestamp nobody can read is not a measurement. It used to read as 0,
153+
* so an unreadable START time reported the whole end time as the duration
154+
* -- a made-up number that looks like a real one. The HTTP method and path
155+
* on this span are still good, so the span is still returned and only the
156+
* duration says it is missing. */
157+
bool timed = false;
158+
int64_t duration = cbm_parse_duration_checked(span->start_time, span->end_time, &timed);
159+
out->duration_ns = timed ? duration : CBM_DURATION_UNKNOWN;
119160
return true;
120161
}
121162

‎src/traces/traces.h‎

Lines changed: 14 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -43,6 +43,8 @@ typedef struct {
4343
const char *path;
4444
const char *status_code;
4545
int span_kind;
46+
/* Nanoseconds, or CBM_DURATION_UNKNOWN when the span's timestamps could
47+
* not be read. A duration of 0 means the span really took no time. */
4648
int64_t duration_ns;
4749
} cbm_http_span_info_t;
4850

@@ -62,9 +64,20 @@ bool cbm_extract_http_info(const cbm_trace_span_t *span, const char *service_nam
6264
* Writes to buf (up to buf_sz). Returns buf, or "" if not a valid URL. */
6365
const char *cbm_extract_path_from_url(const char *url, char *buf, size_t buf_sz);
6466

65-
/* Parse nanosecond timestamp strings and return duration. */
67+
/* A duration nobody could measure. Kept apart from 0, which is a real span
68+
* that took no time. */
69+
#define CBM_DURATION_UNKNOWN (-1)
70+
71+
/* Parse nanosecond timestamp strings and return duration. Text that cannot be
72+
* read counts as 0, so an unreadable timestamp and a span that took no time
73+
* give the same answer. Use cbm_parse_duration_checked when that matters. */
6674
int64_t cbm_parse_duration(const char *start_nano, const char *end_nano);
6775

76+
/* Same, and also says whether both timestamps could be read. *ok is false for
77+
* a NULL argument and for any text that does not read cleanly end to end, so
78+
* a caller can tell "took no time" from "nobody could measure this". */
79+
int64_t cbm_parse_duration_checked(const char *start_nano, const char *end_nano, bool *ok);
80+
6881
/* Calculate P99 from an array of int64_t values.
6982
* Sorts values in-place. Returns 0 for empty array. */
7083
int64_t cbm_calculate_p99(int64_t *values, int count);

‎tests/test_traces.c‎

Lines changed: 78 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -265,6 +265,82 @@ TEST(traces_parse_duration_large_values) {
265265
PASS();
266266
}
267267

268+
/* A timestamp the code cannot read is not a measurement of no time.
269+
*
270+
* strtoll answers 0 for text it cannot read, and the subtraction guard turns
271+
* that into a duration of 0 ns. A span that genuinely took no time and a span
272+
* whose timestamps were garbage then look the same, and no later query can
273+
* tell them apart. cbm_parse_duration_checked reports which one it read. */
274+
TEST(traces_parse_duration_checked_reports_unreadable_timestamps) {
275+
bool ok = false;
276+
277+
/* Positive control: a good pair still reads, and still answers the same
278+
* number cbm_parse_duration answers. */
279+
int64_t d = cbm_parse_duration_checked("1000000000", "1050000000", &ok);
280+
ASSERT(ok);
281+
ASSERT_EQ(d, 50000000);
282+
283+
/* A real measurement of no time reads fine. Zero is an answer here. */
284+
ok = false;
285+
d = cbm_parse_duration_checked("5000000000", "5000000000", &ok);
286+
ASSERT(ok);
287+
ASSERT_EQ(d, 0);
288+
289+
/* End before start reads fine too. The clamp to 0 is the caller's rule,
290+
* not a reading failure. */
291+
ok = false;
292+
d = cbm_parse_duration_checked("1000", "500", &ok);
293+
ASSERT(ok);
294+
ASSERT_EQ(d, 0);
295+
296+
/* The claim: text that does not read is reported, not folded into 0. */
297+
const char *unreadable[] = {"abc", "", " 100", "100ns", "1e9"};
298+
for (size_t i = 0; i < sizeof(unreadable) / sizeof(unreadable[0]); i++) {
299+
ok = true;
300+
(void)cbm_parse_duration_checked(unreadable[i], "1050000000", &ok);
301+
ASSERT(!ok);
302+
ok = true;
303+
(void)cbm_parse_duration_checked("1000000000", unreadable[i], &ok);
304+
ASSERT(!ok);
305+
}
306+
307+
/* A NULL argument was never a measurement either. */
308+
ok = true;
309+
(void)cbm_parse_duration_checked(NULL, "1000", &ok);
310+
ASSERT(!ok);
311+
ok = true;
312+
(void)cbm_parse_duration_checked("1000", NULL, &ok);
313+
ASSERT(!ok);
314+
PASS();
315+
}
316+
317+
/* A span whose timestamps cannot be read keeps its method and path, and says
318+
* the duration was not recorded rather than claiming it was zero. */
319+
TEST(traces_extract_http_info_marks_unreadable_duration) {
320+
cbm_trace_attr_t attrs[] = {
321+
{.key = "http.method", .string_value = "GET"},
322+
{.key = "http.route", .string_value = "/api/orders"},
323+
{.key = "http.status_code", .string_value = "200"},
324+
};
325+
cbm_trace_span_t span = {
326+
.kind = 2,
327+
.attributes = attrs,
328+
.attr_count = 3,
329+
.start_time = "not-a-timestamp",
330+
.end_time = "1050000000",
331+
};
332+
333+
cbm_http_span_info_t info;
334+
bool ok = cbm_extract_http_info(&span, "svc", &info);
335+
/* The HTTP part of the span is still good data, so it is still returned. */
336+
ASSERT(ok);
337+
ASSERT_STR_EQ(info.method, "GET");
338+
ASSERT_STR_EQ(info.path, "/api/orders");
339+
/* The claim: not recorded, rather than a duration of zero. */
340+
ASSERT_EQ(info.duration_ns, CBM_DURATION_UNKNOWN);
341+
PASS();
342+
}
343+
268344
/* ── TestCalculateP99 — edge cases ────────────────────────────────── */
269345

270346
TEST(traces_calculate_p99_100_values) {
@@ -341,4 +417,6 @@ SUITE(traces) {
341417
RUN_TEST(traces_parse_duration_both_null);
342418
RUN_TEST(traces_parse_duration_equal);
343419
RUN_TEST(traces_parse_duration_large_values);
420+
RUN_TEST(traces_parse_duration_checked_reports_unreadable_timestamps);
421+
RUN_TEST(traces_extract_http_info_marks_unreadable_duration);
344422
}

0 commit comments

Comments
 (0)