fix(d2p): structural log + relax entrance condition for sync

E4 forensic (docs/E4_RESULTS_ZH.md): 272 admission rejections triggered
the fallback seeded_router path, but zero /_snapshot/* HTTP calls hit
the workers. Two root causes:

1. _attempt_d_to_p_sync gated on agentic-side `decode_session.opened`.
   By the time fallback runs, agentic has already flipped that flag
   to False in response to admission rejection. But D-side
   SessionAwareCache may still hold the session (release_session is
   not called automatically on admission rejection). Removing the
   gate; let D respond authoritatively with "session-not-resident"
   if it has actually evicted.

2. _attempt_d_to_p_sync logged decisions via logger.info, but
   agentic has no root logger handler so those events silently sank.
   Switching every branch (entry skip, prepare fail/not-ok, dump
   fail/not-ok, finalize fail/not-ok, ok) to write a structural-log
   line at outputs/<run>/structural/d-to-p-sync.jsonl. Each line
   carries stage, reason, durations, bytes pushed.

The result doc is updated to reflect the honest E4-1 outcome and
the P1 fix list.
This commit is contained in:
Claude Code Agent
2026-05-13 09:34:09 +08:00
parent 1d68ad66a7
commit e729d62ddf
2 changed files with 215 additions and 109 deletions

View File

@@ -2121,22 +2121,37 @@ async def _attempt_d_to_p_sync(
Returns a dict with status info on success/skip, or ``None`` on a
non-recoverable error. The caller falls back to normal re-prefill on
any failure.
any failure. Each path emits a structural-log line so we can forensic
why sync skipped vs succeeded vs failed.
"""
if not config.enable_d_to_p_sync:
return None
source_d_url = decode_session.server_url
sid = request.session_id
rid = request.request_id
if not source_d_url:
await _structural_emit(
"d-to-p-sync.jsonl",
{"event": "skipped", "stage": "entry", "sid": sid, "rid": rid,
"reason": "no-source-d"},
)
return {"status": "skipped-no-source-d"}
if not decode_session.opened:
return {"status": "skipped-d-closed"}
# Compose token list for radix insert: we don't have the actual token_ids
# on the agentic side in a stable form; use the request's prompt_token_ids
# via the residency bookkeeping. For now we use a length proxy.
# NB: do NOT gate on decode_session.opened. By the time we reach the
# fallback seeded_router, agentic has already flipped that flag to False
# in response to admission rejection. But the D-side scheduler's
# SessionAwareCache may STILL hold the session resident (release_session
# is only called explicitly, not from admission events). Let D be the
# source of truth via its own snapshot_dump response.
target_tokens = max(0, int(_estimate_session_resident_tokens(request)))
if target_tokens <= 0:
await _structural_emit(
"d-to-p-sync.jsonl",
{"event": "skipped", "stage": "entry", "sid": sid, "rid": rid,
"reason": "zero-target-tokens"},
)
return {"status": "skipped-zero-tokens"}
t_prep0 = time.perf_counter()
try:
prep_resp = await client.post(
f"{prefill_url}/_snapshot/prepare_receive",
@@ -2149,10 +2164,23 @@ async def _attempt_d_to_p_sync(
prep_resp.raise_for_status()
prep = prep_resp.json()
except Exception as exc:
await _structural_emit(
"d-to-p-sync.jsonl",
{"event": "failed", "stage": "prepare", "sid": sid, "rid": rid,
"error": repr(exc)[:200]},
)
return {"status": "prepare-failed", "error": repr(exc)}
t_prep1 = time.perf_counter()
if not prep.get("ok"):
await _structural_emit(
"d-to-p-sync.jsonl",
{"event": "skipped", "stage": "prepare", "sid": sid, "rid": rid,
"reason": prep.get("reason"),
"prepare_dur_ms": round((t_prep1 - t_prep0) * 1000, 2)},
)
return {"status": "prepare-not-ok", "reason": prep.get("reason")}
t_dump0 = time.perf_counter()
try:
dump_resp = await client.post(
f"{source_d_url}/_snapshot/dump",
@@ -2170,8 +2198,21 @@ async def _attempt_d_to_p_sync(
dump_resp.raise_for_status()
dump = dump_resp.json()
except Exception as exc:
await _structural_emit(
"d-to-p-sync.jsonl",
{"event": "failed", "stage": "dump", "sid": sid, "rid": rid,
"error": repr(exc)[:200]},
)
return {"status": "dump-failed", "error": repr(exc)}
t_dump1 = time.perf_counter()
if not dump.get("ok"):
await _structural_emit(
"d-to-p-sync.jsonl",
{"event": "skipped", "stage": "dump", "sid": sid, "rid": rid,
"reason": dump.get("reason"),
"dump_dur_ms": round((t_dump1 - t_dump0) * 1000, 2),
"kv_committed_len": int(dump.get("kv_committed_len", 0))},
)
return {"status": "dump-not-ok", "reason": dump.get("reason"),
"bytes_pushed": dump.get("bytes_pushed", 0)}
@@ -2193,9 +2234,16 @@ async def _attempt_d_to_p_sync(
)
except Exception:
pass
await _structural_emit(
"d-to-p-sync.jsonl",
{"event": "skipped", "stage": "post-dump", "sid": sid, "rid": rid,
"reason": "no-input-token-ids",
"bytes_pushed": int(dump.get("bytes_pushed", 0))},
)
return {"status": "no-tokens-discard", "bytes_pushed": dump.get("bytes_pushed", 0)}
n = min(len(tokens), len(prep["slot_indices"]))
t_fin0 = time.perf_counter()
try:
fin_resp = await client.post(
f"{prefill_url}/_snapshot/finalize_ingest",
@@ -2209,11 +2257,35 @@ async def _attempt_d_to_p_sync(
fin_resp.raise_for_status()
fin = fin_resp.json()
except Exception as exc:
await _structural_emit(
"d-to-p-sync.jsonl",
{"event": "failed", "stage": "finalize", "sid": sid, "rid": rid,
"error": repr(exc)[:200],
"bytes_pushed": int(dump.get("bytes_pushed", 0))},
)
return {"status": "finalize-failed", "error": repr(exc),
"bytes_pushed": dump.get("bytes_pushed", 0)}
t_fin1 = time.perf_counter()
if not fin.get("ok"):
await _structural_emit(
"d-to-p-sync.jsonl",
{"event": "skipped", "stage": "finalize", "sid": sid, "rid": rid,
"reason": fin.get("reason"),
"bytes_pushed": int(dump.get("bytes_pushed", 0))},
)
return {"status": "finalize-not-ok", "reason": fin.get("reason"),
"bytes_pushed": dump.get("bytes_pushed", 0)}
await _structural_emit(
"d-to-p-sync.jsonl",
{"event": "ok", "sid": sid, "rid": rid,
"bytes_pushed": int(dump.get("bytes_pushed", 0)),
"kv_committed_len": int(dump.get("kv_committed_len", 0)),
"inserted_prefix_len": int(fin.get("inserted_prefix_len", 0)),
"prepare_dur_ms": round((t_prep1 - t_prep0) * 1000, 2),
"dump_dur_ms": round((t_dump1 - t_dump0) * 1000, 2),
"finalize_dur_ms": round((t_fin1 - t_fin0) * 1000, 2),
"snapshot_session_id": prep.get("snapshot_session_id")},
)
return {
"status": "ok",
"bytes_pushed": int(dump.get("bytes_pushed", 0)),