Skip to content

fix(traces): stop an unreadable span timestamp from becoming a real duration - #1881

Open
CaptainMittens wants to merge 1 commit into
DeusData:mainfrom
CaptainMittens:fix/span-duration-unreadable-timestamps
Open

fix(traces): stop an unreadable span timestamp from becoming a real duration#1881
CaptainMittens wants to merge 1 commit into
DeusData:mainfrom
CaptainMittens:fix/span-duration-unreadable-timestamps

Conversation

@CaptainMittens

@CaptainMittens CaptainMittens commented Aug 28, 2026

Copy link
Copy Markdown
Contributor

What this fixes

strtoll answers 0 for text it cannot read, and cbm_parse_duration hands
that 0 straight into its subtraction:

int64_t start = strtoll(start_nano, NULL, CBM_DECIMAL_BASE);
int64_t end = strtoll(end_nano, NULL, CBM_DECIMAL_BASE);
return (end > start) ? (end - start) : 0;

The obvious harm is a false duration of zero — a span that took no time and
a span whose timestamps were garbage become the same row.

It is worse than that. An unreadable start time reads as 0, so the span
reports the whole end time as its duration. The test that pins this failed
like so before the fix:

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

cbm_parse_duration does not move. It is public, it is declared in
traces.h:66, and eight tests pin its answers — 0 for a NULL argument, 0
for an end at or before the start. All of that stays exactly as it is.

A companion carries the extra answer instead:

/* Same, and also says whether both timestamps could be read. */
int64_t cbm_parse_duration_checked(const char *start_nano, const char *end_nano, bool *ok);

Both reads go through one small reader in the src/main.c:1104 shape — 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: 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 — CBM_EDGE_CONF_ABSENT in src/graph_buffer/graph_buffer.c, which is
what #1877 is about. 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/test_traces.c,
and handle_ingest_traces in src/mcp/mcp.c never touches a timestamp or a
duration. So this is a defect in a public, tested function rather than one
putting bad rows into a graph today. Worth stating plainly rather than
overselling the impact.

Tests

Two tests. The one that pins the behaviour was seen failing before the fix
the FAIL line above is from that run.

Test Covers
traces_parse_duration_checked_reports_unreadable_timestamps abc, empty, " 100", 100ns, 1e9, and NULL in either position; plus the positive controls that a good pair, an equal pair, and an end-before-start pair all read fine
traces_extract_http_info_marks_unreadable_duration the span keeps its method and path and reports CBM_DURATION_UNKNOWN

The eight existing cbm_parse_duration tests pass untouched.

Checks run

Command Result
make -f Makefile.cbm test-focused TEST_SUITES="traces" 32 passed, 0 failed — exit 0
make -f Makefile.cbm lint-ci === CI linters passed === — exit 0
make -f Makefile.cbm cbm exit 0
make -f Makefile.cbm test 7633 passed, 2 failed, 8 skipped

The two 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.

How this was found

By scanning for siblings of the parse bug fixed in #1875 — "a parse reports
success while the input stays unread". #1877 fixed the confidence pair and the
companion PR to this one fixes the environment-variable group.

Checklist

  • Signed off with git commit -s (DCO)
  • make -f Makefile.cbm test run
  • make -f Makefile.cbm lint-ci run
  • New behaviour covered by a test

Fixes #1982

@github-actions

Copy link
Copy Markdown

Thanks for opening this — it has been seen, and it is queued.

This note is automated, but it is not a brush-off: it exists so you know where your PR stands instead of having to guess from silence.

Current review status: working through a backlog. 0.9.1-rc.1 is out, so the release freeze that held reviews is over — but it left a large queue of open pull requests behind it, and we are reading through them oldest-first. The background is in discussion #1144.

What that means for this PR, concretely:

  • It will not be closed for inactivity. No stale bot touches pull requests here.
  • It may still sit a while before a human reads it. That is on us, not on you.
  • Older PRs are read first, so a recent one is not being skipped — it is behind a queue.

Things that will genuinely speed it up whenever review does happen:

  • Keep it rebased on main — the tree is moving quickly right now, and a conflicting branch cannot be reviewed as the diff you intended.
  • Get CI green, or say which failures you believe are pre-existing.
  • Keep the change to one claim. Bundled features and refactors get split before they get merged, which costs you a round trip.
  • Every commit needs a sign-off (git commit -s) — CI enforces DCO.

If this fixes a bug, a reproduction we can run is worth more than a description of the symptom.

Thanks for contributing, and sorry in advance for the wait.

…uration

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>
@CaptainMittens

Copy link
Copy Markdown
Contributor Author

Same shape as #1922: an input the code cannot read becomes a plausible value, and nothing downstream can tell it from a real one.

Here strtoll answers 0 for a timestamp it cannot read. The obvious harm is a false duration of zero. The real one is an unreadable start: it reads as 0, so the span reports the whole end time as its duration. The test that pins this measured 1.05 seconds for a span whose start was never read.

The scope note in the description is deliberate — cbm_extract_http_info has no production caller on this tree, so this is a defect in a public, tested function rather than one putting bad rows into a graph today.

The -1 it writes is the sentinel this codebase already uses for the same question, CBM_EDGE_CONF_ABSENT — which is what #1877 is about.

One of four from a single scan for siblings of #1875. Context for the set is on #1877.

@DeusData DeusData added bug Something isn't working parsing/quality Graph extraction bugs, false positives, missing edges priority/normal Standard review queue; useful PR with ordinary maintainer urgency. labels Sep 1, 2026
@DeusData

DeusData commented Sep 1, 2026

Copy link
Copy Markdown
Owner

Thank you for the careful sentinel analysis and for explicitly documenting that cbm_extract_http_info has no production caller on the current tree. This still changes a public trace helper and its duration semantics, so we need more time to review the API and downstream compatibility before making a decision. No additional information is requested from you at this stage.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

bug Something isn't working parsing/quality Graph extraction bugs, false positives, missing edges priority/normal Standard review queue; useful PR with ordinary maintainer urgency.

Projects

None yet

Development

Successfully merging this pull request may close these issues.

An unreadable span timestamp becomes a real-looking duration in ingest_traces

2 participants