fix(plugins): stop delivering telemetry events twice, and stop losing parked ones
Two defects, one cause: the spool protocol infers ownership instead of holding it, and never records progress. Duplicate delivery after a partial failure. flush() posts the claim in batches of 100 and returns on the first failure, keeping the whole file. The retry then posts every batch again, including the ones that already arrived — 150 recorded events were delivered 250 times. Progress is now written back to the claim after each successful batch, so a retry resumes where the send stopped and a crash repeats at most one batch. Duplicate delivery when two senders overlap. spool.replace(claim) is os.rename, which preserves mtime, so a claim created after a quiet minute inherited the spool's last-write time and looked abandoned the instant it existed. A second sender starting while the first was still posting took it over and sent it too — most likely at session end, when the MCP server's exit sender and the SessionEnd flush worker both drain. Claims are now touched at claim time, and the per-batch rewrite doubles as a lease heartbeat. _post makes one attempt with SEND_TIMEOUT and no retry, so a heartbeat lands well inside the 120s lease; a test asserts that margin so adding a retry loop to _post cannot silently break it. Parked batches starved. _claim_spool only looked at parked .sending files when no spool existed, and because sessions keep recording there usually was one — so a batch parked by a failed send waited until the 7-day expiry deleted it unsent, despite its own presence being what starts the sender in the first place. flush() now drains the live spool and then parked claims in the same run, oldest first, bounded. Expiry applies only after a genuine retry has failed, with the attempt count carried in the filename. A sender that gives up releases its lease rather than heartbeating on the way out, so the next run picks the batch up promptly instead of waiting a full stale window for a batch nobody is working on. A failing send stops the run, so one broken connection cannot burn every parked batch's attempt budget at once. Two existing tests asserted the old lifecycle and are updated in place, each with a comment saying what changed. Claude-Session: https://claude.ai/code/session_01C7tEmH86HAr7GoAAKCEHZb
This commit is contained in:
@@ -0,0 +1,164 @@
|
||||
"""Delivery semantics of the telemetry spool: no duplicates, no starvation.
|
||||
|
||||
These run against a built host's core in-process (not a subprocess) because they
|
||||
need to inject failures into ``_post``. The identity tests next door cover the
|
||||
uninitialised-process case that needs a real interpreter.
|
||||
"""
|
||||
|
||||
from __future__ import annotations
|
||||
|
||||
import importlib
|
||||
import json
|
||||
import os
|
||||
import sys
|
||||
import time
|
||||
from pathlib import Path
|
||||
|
||||
import pytest
|
||||
|
||||
CORE_ROOT = Path(__file__).resolve().parents[1]
|
||||
REPOSITORY_ROOT = CORE_ROOT.parents[1]
|
||||
HOST_CORE = REPOSITORY_ROOT / "integrations" / "claude-code-plugin" / "core"
|
||||
|
||||
pytestmark = pytest.mark.skipif(not HOST_CORE.exists(), reason="claude-code-plugin is not built")
|
||||
|
||||
|
||||
@pytest.fixture()
|
||||
def telemetry(tmp_path, monkeypatch):
|
||||
monkeypatch.setenv("MEM0_CODE_DATA_DIR", str(tmp_path / "data"))
|
||||
monkeypatch.syspath_prepend(str(HOST_CORE))
|
||||
for name in ("telemetry", "memory_core", "_harness_id"):
|
||||
sys.modules.pop(name, None)
|
||||
module = importlib.import_module("telemetry")
|
||||
monkeypatch.setattr(module, "resolve_distinct_id", lambda: ("tester@example.com", ""))
|
||||
yield module
|
||||
for name in ("telemetry", "memory_core", "_harness_id"):
|
||||
sys.modules.pop(name, None)
|
||||
|
||||
|
||||
def _delivered(payloads):
|
||||
return [event for payload in payloads if "batch" in payload for event in payload["batch"]]
|
||||
|
||||
|
||||
def test_a_partial_failure_does_not_redeliver_what_already_arrived(telemetry):
|
||||
"""Defect 2a: flush kept the whole claim on failure and retried from the top.
|
||||
|
||||
150 events across two batches, the second failing, previously delivered 250.
|
||||
"""
|
||||
for index in range(150):
|
||||
telemetry.record("search", index=index)
|
||||
|
||||
sent: list[dict] = []
|
||||
calls = {"n": 0}
|
||||
|
||||
def flaky(payload, url):
|
||||
calls["n"] += 1
|
||||
if calls["n"] == 2: # second batch fails
|
||||
return False
|
||||
sent.append(payload)
|
||||
return True
|
||||
|
||||
telemetry._post = flaky
|
||||
telemetry.flush()
|
||||
|
||||
telemetry._post = lambda payload, url: sent.append(payload) or True
|
||||
telemetry.flush()
|
||||
|
||||
events = _delivered(sent)
|
||||
assert len(events) == 150
|
||||
assert len({event["uuid"] for event in events}) == 150
|
||||
|
||||
|
||||
def test_a_fresh_claim_is_not_immediately_stealable(telemetry):
|
||||
"""Defect 2b: rename preserves mtime, so a claim inherited the spool's age.
|
||||
|
||||
With the last write older than the stale threshold, a claim made now looked
|
||||
abandoned the instant it existed and a second sender took it over.
|
||||
"""
|
||||
telemetry.record("search")
|
||||
spool = telemetry._spool_path()
|
||||
old = time.time() - (telemetry.CLAIM_STALE_SECONDS + 60)
|
||||
os.utime(spool, (old, old))
|
||||
|
||||
first = telemetry._claim_spool()
|
||||
assert first is not None
|
||||
|
||||
# A second sender starting right now must find nothing to take.
|
||||
assert telemetry._claim_parked(first.parent) is None
|
||||
|
||||
|
||||
def test_a_parked_batch_is_drained_behind_the_live_spool(telemetry):
|
||||
"""Defect 6: parked claims were only reachable when no spool existed.
|
||||
|
||||
Because sessions keep recording there usually was one, so a batch parked by
|
||||
a failed send waited until the 7-day expiry deleted it unsent — even though
|
||||
its own presence is what starts the sender.
|
||||
"""
|
||||
telemetry.record("parked")
|
||||
telemetry._post = lambda payload, url: False
|
||||
telemetry.flush()
|
||||
|
||||
parked = list(telemetry.memory_core.data_dir().glob("telemetry-*.sending"))
|
||||
assert len(parked) == 1
|
||||
old = time.time() - (telemetry.CLAIM_STALE_SECONDS + 60)
|
||||
os.utime(parked[0], (old, old))
|
||||
|
||||
telemetry.record("fresh")
|
||||
sent: list[dict] = []
|
||||
telemetry._post = lambda payload, url: sent.append(payload) or True
|
||||
telemetry.flush()
|
||||
|
||||
names = {event["event"] for event in _delivered(sent)}
|
||||
assert names == {"code.parked", "code.fresh"}
|
||||
|
||||
|
||||
def test_an_untried_batch_is_not_expired_by_age_alone(telemetry):
|
||||
"""Expiry should discard what failed, not what never got a turn."""
|
||||
telemetry.record("parked")
|
||||
telemetry._post = lambda payload, url: False
|
||||
telemetry.flush()
|
||||
|
||||
parked = list(telemetry.memory_core.data_dir().glob("telemetry-*.sending"))
|
||||
assert len(parked) == 1
|
||||
ancient = time.time() - (telemetry.CLAIM_EXPIRY_SECONDS + 60)
|
||||
os.utime(parked[0], (ancient, ancient))
|
||||
|
||||
sent: list[dict] = []
|
||||
telemetry._post = lambda payload, url: sent.append(payload) or True
|
||||
telemetry.flush()
|
||||
|
||||
assert [event["event"] for event in _delivered(sent)] == ["code.parked"]
|
||||
|
||||
|
||||
def test_progress_is_recorded_after_every_batch(telemetry):
|
||||
"""A crash repeats at most one batch, not the whole file."""
|
||||
for index in range(250):
|
||||
telemetry.record("search", index=index)
|
||||
|
||||
calls = {"n": 0}
|
||||
|
||||
def die_after_two(payload, url):
|
||||
calls["n"] += 1
|
||||
if calls["n"] > 2:
|
||||
return False
|
||||
return True
|
||||
|
||||
telemetry._post = die_after_two
|
||||
telemetry.flush()
|
||||
|
||||
parked = list(telemetry.memory_core.data_dir().glob("telemetry-*.sending"))
|
||||
assert len(parked) == 1
|
||||
remaining = parked[0].read_text(encoding="utf-8").strip().splitlines()
|
||||
# Two batches of 100 landed; only the last 50 should still be pending.
|
||||
assert len(remaining) == 50
|
||||
assert json.loads(remaining[0])["properties"]["index"] == 200
|
||||
|
||||
|
||||
def test_the_heartbeat_stays_well_inside_the_lease(telemetry):
|
||||
"""The claim rewrite doubles as the lease heartbeat.
|
||||
|
||||
_post makes a single attempt with SEND_TIMEOUT and no retry, so a heartbeat
|
||||
lands at least that often. If a retry loop is ever added to _post, this is
|
||||
the assertion that catches a sender losing its claim mid-flight.
|
||||
"""
|
||||
assert telemetry.SEND_TIMEOUT * 4 < telemetry.CLAIM_STALE_SECONDS
|
||||
Reference in New Issue
Block a user