Three Different RAG Bugs Produce the Same Wrong Answer. Without a Trace You Cannot Tell Them Apart

A user reports that your RAG system gave a wrong answer. You have exactly one string to work from. Here are three things that could have happened, and they are indistinguishable from the outside:

1. Retrieval never saw the right chunk. The embedder put the query somewhere unhelpful, or the chunker split the passage down the middle, so the evidence was never a candidate.
2. The right chunk was retrieved and then thrown away. It made the shortlist, and the context budget truncated it out before the prompt was built. Retrieval did its job perfectly and the model never saw the result.
3. Everything arrived intact and the model ignored it. The correct passage was sitting in the prompt, cited-and-all, and the answer went somewhere else.

Three different bugs. Three different fixes — re-ingest with a different embedder, raise max_context_chars, rewrite the system prompt. And one identical symptom.

Guessing between them is how a team spends a fortnight tuning a prompt when the chunker was at fault. That is the entire reason evaluation and observability is level 1 of this stack rather than a nice-to-have you add later: you cannot debug levels 3 through 8 without it, because every one of them fails into the same wrong string.

👉 Live, everything computed in your browser: https://dev48.infy.uk/arcrector/level1-observability.html

I built the instrument that ends the guessing as part of Arc Rector, a nine-level agentic RAG stack where every layer is a swappable adapter and every default runs with zero vendor bills and no API keys. The default here is Langfuse (MIT, self-hosted) plus Ragas.

A span is a stopwatch with a name and a parent

That is genuinely the whole primitive. Four fields:

name  ·  start  ·  end  ·  parent

Everything a tracing UI does is arithmetic on top of those four. The nesting is what makes it useful: retrieve is the parent of embed_query, vector.search and rerank, so when retrieval is slow you descend rather than guess.

Arc Rector expresses it as a context manager, which is the right shape for two reasons — a with block cannot leak an unclosed span even when the body raises, and the nesting is the Python call stack rather than a parallel structure you maintain by hand.

class Tracer(ABC):
    """L1 -- observability. Records nested spans for every step of a run."""
    name: str = "tracer"

    @abstractmethod
    @contextmanager
    def span(self, name: str, **attrs) -> Iterator["SpanHandle"]:
        """Open a span; yields a handle whose `.update(output=...)` records results."""

    def flush(self) -> None: ...
    def trace_url(self) -> str: return ""
    def last_trace_id(self) -> str: return ""

Note that it yields a SpanHandle rather than the backend's own object. No caller ever touches a Langfuse or OpenTelemetry type, which is exactly what makes swapping the backend a one-word change instead of a refactor.

Write the no-op tracer first

Build the null implementation before the real one and observability stops being a dependency. The pipeline keeps its with tracer.span(...) structure whether or not a backend exists, the test suite runs with no containers, and "no tracing" is a supported low-RAM configuration rather than an outage.

The record=True flag is the part worth stealing:

class NoopTracer(Tracer):
    name = "none"
    def __init__(self, *, record: bool = False, **_):
        self.record = record
        self.spans: list[str] = []

    @contextmanager
    def span(self, name: str, **attrs):
        if self.record:
            self.spans.append(name)
        yield _NullSpan()

# the test that keeps every framework adapter honest
def test_langgraph_opens_every_span():
    tracer = NoopTracer(record=True)
    LangGraphAgent().run("what is the default vector store?", deps(tracer))
    assert "retrieve" in tracer.spans and "generate" in tracer.spans

The null tracer became a test instrument: it proves every agent-framework adapter really instruments every step, which is otherwise the sort of thing that silently rots.

Self-time is where the time actually went

"Retrieval took 38 ms" is not a finding, because retrieval contains three other things. What you want is a span's duration minus the sum of its direct children's durations:

self_time = duration - sum(child.duration for child in direct_children)

That is the difference between "retrieve took 38 ms" and "retrieve itself took 0.4 ms and spent 37.6 of it inside vector.search".

Two properties are worth stating because they are also the invariants worth asserting in tests. Self-time is never negative — children open and close inside their parent's with block, so their durations cannot exceed it; a negative self-time in a real system means your clock is wrong or a span escaped its parent, and both are bugs. And a child's start and end must lie inside its parent's, which is what lets a UI draw nested bars with real offsets instead of a flat list.

The attributes are the value, not the timings

Duration tells you where. Attributes tell you what. This is the section that actually answers the three-identical-bugs problem:

with tracer.span("arc-rector.turn", framework=self.name, question=question) as turn:

    with tracer.span("guardrails.input", text=question) as sp:
        guard_in = deps.guardrails.check_input(question)
        sp.update(output={"allowed": guard_in.allowed, "reason": guard_in.reason})

    with tracer.span("memory.recall", user_id=deps.user_id) as sp:
        memories = rag_core.recall(deps, question)
        sp.update(output=[m.text for m in memories])

    with tracer.span("retrieve", top_k=deps.top_k, fetch_k=deps.fetch_k) as sp:
        hits = rag_core.retrieve(deps, question)
        sp.update(output=[{"chunk_id": h.chunk.chunk_id,
                           "score": round(h.score, 4),
                           "title": h.chunk.title} for h in hits])

    with tracer.span("generate", as_type="generation",
                     model=getattr(deps.inference, "model", ""), input=prompt) as sp:
        raw = deps.inference.complete(prompt, system=rag_core.SYSTEM_PROMPT)
        sp.update(output=raw)

    turn.update(output={"answer": answer.text, "citations": len(answer.citations)})

That turns a trace from a performance tool into a correctness tool. With the chunk ids and scores on retrieve and the full prompt on generate, the three failure modes from the opening separate instantly:

• the right chunk id is not in retrieve's output → retrieval bug, go and look at chunk size, the embedder, top_k
• the chunk id is in retrieve but not in generate's input → the budget truncated it, go and look at max_context_chars
• it is in generate's input and the answer contradicts it → generation bug, go and look at the system prompt

That is the difference between "retrieve was slow" and "retrieve returned chunk 7 at 0.61 when chunk 12 was the right one".

Two cautions. Marking the generation span as_type="generation" is not decoration — both Langfuse and Phoenix render generations differently from plain spans, prompt and completion side by side, with token accounting where the backend can compute it. And whatever you attach is stored: putting a full prompt on every span is how a trace backend's disk fills up, which is what retention policy and sampling exist for.

The bug that cost an evening, and it looks completely reasonable

Telemetry must not break the request it observes. Every update() is wrapped in a bare try/except: pass, and an unreachable backend degrades to a dead span whose methods do nothing, so a Langfuse outage costs you visibility and not availability. That part is obvious.

This part is not, and it is the best thing in the whole level:

# WRONG - looks equivalent to entering and exiting by hand. It is not.
@contextmanager
def span(self, name, **attrs):
    try:
        with self._open(name, **attrs) as raw:
            yield _LangfuseSpan(raw)
    except Exception:
        yield _DeadSpan()          # second yield -> RuntimeError, traceback lost

When the caller's block raises — an Ollama read timeout, say — contextlib throws that exception in at the yield. Your except catches it, you yield a second time, and contextlib raises RuntimeError: generator didn't stop after throw() with the original traceback gone.

The user's real error message became a contextlib internal. Losing the receipt is annoying; losing the explanation is a day.

# RIGHT - drive __enter__ and __exit__ yourself
try:
    raw_span = ctx.__enter__()
except Exception:
    yield _DeadSpan(); return
try:
    yield _LangfuseSpan(raw_span)
finally:
    try:
        ctx.__exit__(*sys.exc_info())   # pass the real exception through
    except Exception:
        pass

There is a regression test pinning it. Tracing must not break the request it observes, and it must not hide why the request broke.

flush() — the spans you never see

Every serious tracing SDK buffers spans and ships them on a background thread, because a synchronous HTTP call per span would make tracing more expensive than the thing it traces.

The consequence is specific and bites exactly once per project: a CLI run that finishes and exits can terminate the exporter before it has sent anything. Clean run, empty trace list. It feels like a configuration problem and it is a lifecycle problem — a web server hides it entirely, because the process lives long enough for the batch to go out on its own, which is why it reliably surfaces the first time you run the same code from a script.

answer.trace_id = tracer.last_trace_id()   # hang it on the answer
deps.tracer.flush()                        # a CLI exits; batched spans do not survive that

There is a nastier second-order version: a process that crashes loses its buffer too, so the traces you most want — from the run that fell over — are the ones most likely to be missing.

Capture the trace id off the raw span as it opens and hang it on the answer, and every answer in the UI carries a link straight to its own receipt. That single link is what turns "it gave a bad answer" into a bug report with evidence attached.

The mean lies

Latency distributions in a RAG system are not symmetric. They are a tight body plus a long right tail, produced by a cache miss, a cold model, a retry, a GC pause, or one question whose prompt is twice as long as the others.

A mean averages the tail away by construction. A p95 is an observation that actually happened to somebody.

Percentiles are also the only honest way to talk about a change. "The mean went from 380 ms to 372 ms" is noise; "p95 went from 2.1 s to 900 ms" is a fix. Compute them by nearest rank — sort, take element ceil(p/100 × n) — and know the rule that catches people out in aggregation:

Percentiles do not average. The p95 of two services is not the mean of their p95s. Aggregate raw samples or a histogram, never pre-computed percentiles.

The live panel makes the asymmetry visible: turn the slow path on for 1 run in 20 and the mean drifts by a few per cent while p95 moves to a different part of the chart — because 5% of runs are now the slow path and p95 is looking exactly there.

Sampling is cheap storage paid for in accuracy

Eventually somebody suggests keeping one trace in ten. That is fine, and it is not free.

Head-based sampling hashes the trace id and keeps 1-in-N, deciding before the work starts. It is cheap, stateless, and every service in a distributed trace reaches the same decision from the same id. It is also blind by construction: it cannot preferentially keep the slow traces, because at decision time nothing knows the trace will be slow.

Tail-based sampling buffers a whole trace and decides after it completes — keep everything with an error, everything over 2 s, and 1% of the rest. That is what you actually want, and it needs a collector holding spans in memory.

The number nobody puts on a dashboard is the error that sampling puts on the percentile you are reading. At 1-in-2 it is usually small. At 1-in-64 over a few hundred runs, your p95 is being estimated from a handful of observations and can be wildly wrong in either direction — and it will still render as a confident number with two decimal places. Langfuse exposes LANGFUSE_SAMPLE_RATE; Phoenix inherits OpenTelemetry's TraceIdRatioBased sampler. Neither shows you the error bar, which is why the page computes it.

The other half: four metrics, two jobs

A trace tells you what happened on one turn. It cannot tell you whether the change you just made helped. For that you need a marked exam — and the design decision that matters is scoring retrieval and generation separately.

Ragas' four metrics split cleanly:

metric	scores	question it answers
context precision	retrieval	was what you fetched on-topic and well-ranked?
context recall	retrieval	did it contain what the reference answer needed?
faithfulness	generation	is every claim supported by the retrieved context?
answer relevancy	generation	does the answer address the question asked?

And the diagnostic rule falls straight out of the split:

• recall low, faithfulness high → the model faithfully used context that did not contain the answer. A retrieval bug. Go and look at chunk size, the embedder, the prefixes, top_k.
• recall high, faithfulness low → the evidence was right there and the answer went elsewhere. A generation bug. Go and look at the system prompt, the model, the context ordering.

Merge the four into one headline score and you have thrown that diagnosis away. That is the whole argument for keeping the halves apart, and the live panel makes it provable rather than assertable: force top_k to 1 and the retrieval metrics drop while faithfulness holds; generate the answer from a different question and the retrieval metrics are untouched while faithfulness and relevancy collapse.

Eight pairs is a regression check, not a benchmark

The gold set here is eight hand-written question/reference pairs, with every reference written from the demo corpus so the harness measures the system and not the corpus.

Eight pairs will not tell you your RAG is good, and the repo says so plainly. It will tell you whether the chunk_size you just changed made things better or worse — a question no amount of eyeballing one answer can settle, because a single answer varies with the question you happened to pick.

Two disciplines make it work. Change one knob at a time, or you learn nothing about which knob did it. And treat absolute numbers as directional: a small local judge grades differently from a frontier one, and a proxy metric grades differently again, so the delta between runs on the same setup is the signal and the absolute value is decoration.

When you outgrow eight pairs, the next step is not a public benchmark. It is fifty pairs drawn from questions your users actually asked and got wrong.

The judge is the slowest thing you own

Ragas' metrics are LLM-judged, and that is the point of them: a judge can tell that a correct paraphrase is correct, and token overlap never will. It is also the cost, in two ways people hit in order.

First, it bills you by default. Ragas reaches for OpenAI for both its judge model and its embeddings, so an out-of-the-box run is a vendor bill you did not ask for. Pointing both at the same local Ollama the rest of the stack uses makes it genuinely zero-key:

chat     = ChatOllama(model="llama3.2:3b", base_url=OLLAMA, temperature=0.0)
embedder = OllamaEmbeddings(model="nomic-embed-text", base_url=OLLAMA)
llm, embeddings = LangchainLLMWrapper(chat), LangchainEmbeddingsWrapper(embedder)

for metric in metrics:            # metrics carry their OWN handles --
    metric.llm = llm              # setting these is what keeps the judge
    metric.embeddings = embeddings  # local instead of reaching for OpenAI

run_config = RunConfig(timeout=1800,     # default 180s: fine hosted, fatal local
                       max_workers=1,    # Ollama serialises; parallel just queues
                       max_retries=1)

Then the arithmetic bites. A 3B model on a CPU-only box needs 45–60 s per generation, each metric makes several calls per sample, and Ragas' default per-job timeout is 180 seconds — designed for a hosted judge and far too short for a local one. Every metric times out and every score comes back n/a.

Honest outcome on my development machine, and I would rather print it than round it off: the path runs, the judge really receives calls, one metric took 12 minutes 22 seconds, and the numbers actually reported came from the deterministic fallback. On a GPU box the defaults are fine. Say which one you are on.

Always ship an evaluator that cannot fail

fallback_to_builtin: true is one line of config and it is the difference between an eval harness and an eval aspiration.

def evaluate(self, samples):
    try:
        return self._evaluate_with_ragas(samples)
    except Exception as exc:
        if not self.fallback_to_builtin: raise
        result = BuiltinEvaluator().evaluate(samples)     # deterministic proxies
        result["backend"] = "builtin (ragas unavailable)"
        result["ragas_error"] = str(exc)[:300]            # say WHY, in the output
        return result

The builtin computes four things from token overlap and citation structure — context_recall, answer_correctness as token F1, faithfulness_proxy and citation_rate — with no model, no network and no judge. So make eval always produces numbers, and the harness itself is unit-testable.

The repo calls them proxies in the module docstring and never upgrades that word. faithfulness_proxy cannot tell a correct paraphrase from an invented claim that happens to reuse context vocabulary, and pretending otherwise would be worse than having no metric at all.

Note what the fallback also does: it writes backend: "builtin (ragas unavailable)" and a truncated ragas_error into the result, so the output says which evaluator produced it and why. A fallback that hides the fact that it fired is a lie with a nice interface.

Two boot bugs neither of which is findable by reading

Self-hosting Langfuse is five containers, not one — the Next.js web app, Postgres for metadata, ClickHouse for span data, Redis for queueing, MinIO for large payloads — with LANGFUSE_INIT_* seeding an organisation, a project and an API key pair so first boot needs no account and no clicking.

Both of these cost an evening of actually running it:

# MUST be quoted. This particular 64-char hex key happens to be all digits,
# and unquoted, YAML parses it as the integer 0 -- which Langfuse rejects
# with a Zod error about the key not being 256 bits.
ENCRYPTION_KEY: "0f1e2d3c4b5a69788796a5b4c3d2e1f00f1e2d3c4b5a69788796a5b4c3d2e1f0"

And then ClickHouse restart-looped because the tuning file mounted into it had a -- inside an XML comment. That is illegal in XML, so the config never parsed, so ClickHouse never started, so Langfuse's whole dependency chain sat waiting on a healthcheck that would never go green.

Neither is in any documentation. Both are the reason I keep saying "found by running it".

Verification

The trace really came back. Reading it out of the self-hosted Langfuse through its own API returned trace 5fd2af30… with 7 nested spans — arc-rector.turn wrapping guardrails.input, memory.recall, retrieve, generate, guardrails.output and memory.write — as part of a 5-of-5 verified local run against 21 real 768-dimensional vectors in Qdrant. The repo carries 216 pytest cases that need no Docker, no Ollama, no network and no model.

The level page ships four panels that genuinely compute in your browser: a real nested span recorder with real performance.now() timings and real self-time arithmetic, a real pipeline scored on six gold pairs, real nearest-rank percentiles over really-run samples, and a real hash-based sampler whose estimation error is measured rather than asserted.

What that page is not: there is no OTLP exporter, no collector and no server, so flush() has nothing to flush there. One process means parent/child is a stack, where a real trace crosses process boundaries by carrying a trace id and a span id in a header. There is no LLM judge on the page — the four metrics are clearly-labelled overlap and cosine proxies, and the milliseconds are JavaScript arithmetic, so the shape is real and the absolute numbers mean nothing outside the tab.

And the framing for the project, stated rather than left to be inferred: this is a complete, correct, zero-cost starting point — not a production system. No auth, no multi-tenancy, no rate limiting, no retention policy on trace storage. PRODUCTION.md lists the gap rather than hiding it.

If you take one thing from this: score retrieval and generation separately. One blended number tells you something broke. Two numbers tell you which half to go and fix, and that is the entire difference between having an instrument and having an opinion.

Live page: https://dev48.infy.uk/arcrector/level1-observability.html
Repo: https://github.com/dev48v/arc-rector