Databricks Community

holyone2 · 2 weeks ago

Hi all,

We're seeing cases where traces go missing in an experiment-backed MLflow trace store (not Unity Catalog). The client gets a successful response for both trace writes, and the server echoes back the same trace id, but the trace is never stored. `GetTrace` returns `NOT_FOUND` indefinitely, and the trace never appears in `search_traces` for the experiment or its run.

**Setup**
- MLflow Python client 3.15.1, databricks-sdk 0.102.0, Python 3.13
- Tracking URI `databricks`, traces stored in a regular MLflow experiment (about 2.8k traces total, well under the 100k cap)
- AWS workspace, ap-northeast-1. Client machine in a different region (UK).
- pytest with pytest-xdist: 8 worker processes, each writing one trace every 1–2 minutes, all attached to one shared run. That's far below the documented 50 trace creations/sec limit.
- Each trace is about 300 KB to a few MB (one root span plus N child spans)
- Tried with both async (default) and synchronous export (`MLFLOW_ENABLE_ASYNC_TRACE_LOGGING=false`); the problem happens with both

**What happens**

Roughly 1 in 37 traces per run disappears, on a different test each time. We wrapped `TracingClient.start_trace` and `TracingClient._upload_trace_data` to log every call. For a lost trace, we see:

```
16:00:51 UTC start_trace tr-0eb74c3a913e0f24188d56595ee45ca6 (experiment <id>) returned tr-0eb74c3a913e0f24188d56595ee45ca6 (experiment <id>) in 1.5s
16:00:54 UTC upload_trace_data tr-0eb74c3a913e0f24188d56595ee45ca6 done in 3.0s
16:01:56 UTC mlflow.get_trace(...) still None after 10 attempts (~60s, exponential backoff)
```

Hours later, `mlflow.get_trace("tr-0eb74c3a913e0f24188d56595ee45ca6")` still returns `NOT_FOUND`, and the trace isn't in a timestamp-window search of the experiment. Every other trace written by the same process in the same window is present and readable.

The MLflow exporter raised no error or warning, and the local trace was exported normally: it wasn't deferred and wasn't left in the in-memory buffer. As far as the client can tell, the write succeeded.

Other examples: `tr-1d335ca4b3ebd64db0b31c6d8025b297` (about 15:27:29 UTC), `tr-aed91304847d49e1674d7fa9eaf632c4` and `tr-f9ef235585cdaa7dafc2796bed560239`, all on 2026-09-30.

**Questions**
1. Is it known that `StartTraceV3` can return success without the trace being persisted for experiment-backed trace storage? Is there an ingestion pipeline behind it that can drop records?
2. Is there any server-side log or system table where we could see what happened to a specific trace id? `system.access.audit` doesn't seem to cover trace API calls.
3. Would migrating traces to Unity Catalog storage avoid this, or does it share the same ingestion path?
4. Which response header carries a request id, so we can capture it for support?

For now our workaround is to keep a copy of each trace client-side, re-send it if `get_trace` still misses after about a minute, and then check again. We'd much rather understand the root cause.

Thanks!

holyone2 · a week ago

I have since discovered a useful observation:

1. StartTraceV3 succeeds;

2. later GetTrace and SearchTraces return NOT_FOUND;

3. a retried StartTraceV3 with the same id returns 'already exists'!

anuj_lathi · Thursday

Short version: your new observation rules out a client-side drop. If a retried StartTraceV3 with the same id returns "already exists" while GetTrace and SearchTraces return NOT_FOUND, the server accepted and recorded something for that id, but the read path can't see it. That points to a server-side persistence or visibility inconsistency, and it needs a support ticket with server-side investigation. I'm not aware of a public known issue matching this, and this isn't behavior Databricks guarantees.

What the evidence says

The request reached the backend and was acknowledged, and the id is now reserved or recorded somewhere.
The same id is invisible to both point lookups and search, for hours. That rules out ordinary eventual-consistency lag.
Your retry workaround will not work for these traces. Re-sending the same id gets "already exists", so you'd need to regenerate the trace id (or treat the trace as lost) instead of resending.

Plausible server-side shapes, which only Databricks can tell apart: an id or idempotency record written but the main record never committed or later rolled back, a record written but not indexed or visible to reads, or a record written and then removed. I can't say which from the outside.

Your questions

1. Known behavior / ingestion pipeline? Experiment-backed traces live under the experiment [1], and success from StartTraceV3 should mean the trace info is durably stored. A success followed by permanent NOT_FOUND is a defect, not expected behavior. Whether there's an async stage behind the endpoint is internal, and I wouldn't guess at it. Support can answer that.

2. Server-side visibility? There's nothing customer-facing I'd point you to for per-trace ingestion status. As you found, system.access.audit isn't the place. Support or engineering can search service-side logs if you give them a request id, workspace id, experiment id, trace id and a UTC timestamp. You already have all of those except the request id.

3. Would Unity Catalog storage avoid it? I wouldn't assume so, and I wouldn't migrate on that hope. It's a different storage backend, so it may behave differently, but I can't tell you whether it shares the failing component. If you want to test it, run a parallel experiment with UC-backed traces under the same load and compare loss rates. Ask support the same question about the ingestion path.

4. Request id? Databricks REST responses carry an x-request-id header. Capture it on every StartTraceV3 call, and log it next to the trace id. One way is to wrap the MLflow REST helper, which returns a requests.Response:

import logging
from mlflow.utils import rest_utils

log = logging.getLogger("trace-audit")
_orig = rest_utils.http_request

def _wrapped(*args, **kwargs):
    resp = _orig(*args, **kwargs)
    log.info(
        "endpoint=%s status=%s x-request-id=%s",
        kwargs.get("endpoint") or (args if len(args) > 2 else None),
        resp.status_code,
        resp.headers.get("x-request-id"),
    )
    return resp

rest_utils.http_request = _wrapped

The patch point may differ slightly between client versions, since modules import http_request by name. If it doesn't take effect, patch the reference where the tracing REST store imports it, or enable DEBUG logging for urllib3 and capture headers there.

What I'd collect before opening the ticket

For each lost trace: the trace id, x-request-id from the StartTraceV3 response, UTC timestamps, the experiment id, the workspace id and the run id.
The x-request-id from the retried call that returned "already exists", plus the exact error body. It's strong evidence that the record exists server-side.
The size of the StartTraceV3 payload for lost versus good traces. Check the trace info fields (tags, metadata, previews), not the span data. Your 300 KB to few MB traces are mostly span data going through the upload path, so a size correlation would be informative either way.
An isolation test:
- Give each xdist worker its own run, or don't link traces to a run at all.
- Run a single worker.
If the loss rate drops, the shared-run write contention across 8 processes is a strong lead. If it doesn't, that's useful to tell support too.
Whether the lost traces' ids ever show up through a direct trace-info fetch, as opposed to search_traces and get_trace, which would help separate "metadata missing" from "data missing".

Interim approach

Until there's a root cause, make your writes safe against this failure. Verify each trace with get_trace after a delay. On a miss, don't resend under the same id. Re-emit the trace under a new id, with the lost id recorded as a tag so you can reconcile later. Keep logging the lost ids and request ids, since each one is another data point for support.