simbiot-harness/tests/test_delivery_idempotency.py

# -*- coding: utf-8 -*-
"""t-260930083937: идемпотентная автодоставка артефактов в TG (hermetic, без LLM/TG).

Запуск: ./venv/bin/python tests/test_delivery_idempotency.py

Дубли в чат (m-516173239/241 — «Ты мне её уже три раза отправил»)
приходили из гонки уровней: push в тике и delivery-демон оба проходили
проверку delivery_status != 'sent', пока TG-отправка была в полёте
(23–34с между дублями DeliverySent в сторе). Плюс ad-hoc curl sendDocument
вообще без метки delivered — каждый тик слал файл заново.

Проверяет: ledger (первая запись только одна), атомарный claim
(живой/истёкший лок, release, межпроцессная атомарность), детерминированную
гонку deliver_result (push в полёте + параллельный демон → одна отправка),
SKIP с событием, сбой TG → release → досылка демоном, requeue со сбросом
ledger и флагов модели, pre-filter deliver_pending, deliver_artifact
(dedup/force/сбой+ретрай), CLI tg-notify -k / tg-deliver-file (--force).
"""
import contextlib
import io
import json
import os
import subprocess
import sys
import threading

# ── изоляция: своя БД в /tmp (prod не трогаем) ──
_DST = "/tmp/simbiot-test-delivery-idem.db"
for p in (_DST, _DST + "-wal", _DST + "-shm"):
    if os.path.exists(p):
        os.unlink(p)
os.environ["SIMBIOT_DB"] = _DST
sys.path.insert(0, "/root/simbiot-harness")

from harness import es, tg_inbox
from harness import commands
from harness.scheduler import deliver_pending

fails = []


def check(name, cond, extra=""):
    print(("PASS" if cond else "FAIL"), name, ("| " + str(extra)) if not cond else "")
    if not cond:
        fails.append(name)


def tg_sends():
    """Все события фактической отправки (DeliverySent/ArtifactDelivered) в сторе."""
    db = es._conn()
    try:
        rows = db.execute(
            "SELECT aggregate_id, event_type FROM events "
            "WHERE event_type IN ('DeliverySent','ArtifactDelivered')").fetchall()
        return [(r["aggregate_id"], r["event_type"]) for r in rows]
    finally:
        db.close()


def count_skips(aggregate_id):
    db = es._conn()
    try:
        return db.execute(
            "SELECT COUNT(*) AS n FROM events WHERE aggregate='task' "
            "AND aggregate_id=? AND event_type='DeliverySkipped'",
            (aggregate_id,)).fetchone()["n"]
    finally:
        db.close()


def run_cli(*argv):
    """CLI-команда in-process (stdout перехвачен) — моки tg_inbox действуют."""
    import cli as cli_mod
    old = sys.argv
    sys.argv = ["cli.py"] + list(argv)
    buf = io.StringIO()
    try:
        with contextlib.redirect_stdout(buf):
            cli_mod.main()
    finally:
        sys.argv = old
    return buf.getvalue()


# ═══════════════ 1. ledger: доставлено ровно один раз ═══════════════
es.init_db()
aid = "file:/tmp/pres.html"
check("ledger: первая запись", es.record_delivery(aid, "file") is True)
check("ledger: дубль записи отклонён", es.record_delivery(aid, "file") is False)
check("ledger: recorded видит запись", es.delivery_recorded(aid) is True)
check("ledger: отсутствующий не recorded",
      es.delivery_recorded("file:/tmp/none.html") is False)

# ═══════════════ 2. claim: атомарный захват ДО отправки ═══════════════
check("claim: первый захват", es.delivery_claim("lock-1", owner="A", ttl_sec=60) is True)
check("claim: живой лок блокирует", es.delivery_claim("lock-1", owner="B", ttl_sec=60) is False)
es.delivery_claim("lock-exp", owner="A", ttl_sec=-1)  # уже истёк
check("claim: истёкший лок перехватывается",
      es.delivery_claim("lock-exp", owner="B", ttl_sec=60) is True)
es.delivery_release("lock-1")
check("claim: release открывает повторный захват",
      es.delivery_claim("lock-1", owner="B", ttl_sec=60) is True)

# межпроцессная атомарность: два дочерних процесса тянут один claim
code = ("import os,sys;os.environ['SIMBIOT_DB']=%r;"
        "sys.path.insert(0,'/root/simbiot-harness');"
        "from harness import es;"
        "print('1' if es.delivery_claim('lock-xproc', owner='child', ttl_sec=60) else '0')"
        % _DST)
r1 = subprocess.run([sys.executable, "-c", code], capture_output=True, text=True)
r2 = subprocess.run([sys.executable, "-c", code], capture_output=True, text=True)
wins = (r1.stdout.strip() + r2.stdout.strip()).replace("\n", "")
check("claim: межпроцессно ровно один победитель", sorted(wins) == ["0", "1"], wins)

# ═══════════════ 3. deliver_artifact: dedup / force / сбой+ретрай ═══════════════
calls = []
ok1 = commands.deliver_artifact("art-1", "file", lambda: (calls.append(1) or True),
                                owner="test", caption="презентация")
ok2 = commands.deliver_artifact("art-1", "file", lambda: (calls.append(1) or True),
                                owner="test")
check("artifact: первая доставка True", ok1 is True)
check("artifact: повтор False", ok2 is False)
check("artifact: send вызван один раз", len(calls) == 1, f"calls={len(calls)}")
check("artifact: ledger записан", es.delivery_recorded("art-1") is True)
check("artifact: событие ArtifactDelivered есть",
      ("art-1", "ArtifactDelivered") in tg_sends())

okf = commands.deliver_artifact("art-1", "file", lambda: (calls.append(1) or True),
                                owner="test", force=True)
check("artifact: force пробивает живой лок", okf is True)
check("artifact: force — второй send", len(calls) == 2, f"calls={len(calls)}")
check("artifact: force не «молодит» ledger (IGNORE)",
      es.record_delivery("art-1", "file") is False)

flaky = {"n": 0}
def _flaky():
    flaky["n"] += 1
    if flaky["n"] == 1:
        raise RuntimeError("TG упал")
    return True
try:
    commands.deliver_artifact("art-flaky", "file", _flaky, owner="test")
    check("artifact: сбой прокинут", False)
except RuntimeError:
    check("artifact: сбой прокинут", True)
check("artifact: сбой не записан в ledger",
      es.delivery_recorded("art-flaky") is False)
check("artifact: ретрай после сбоя успешен",
      commands.deliver_artifact("art-flaky", "file", _flaky, owner="test") is True)

# ═══════════════ 4. deliver_result: гонка уровней = одна отправка ═══════════════
# инцидент: push в тике и delivery-демон параллельно → 2× DeliverySent.
# Детерминированная гонка: поток A (тик) берёт claim и «висит в отправке»
# (как TG до 35с), B (демон) идёт в это же время → claim отклоняет.
tid, _ = commands.submit_task("Задача с автодоставкой", "детали", 5)
commands.mark_awaiting_delivery(tid, reason="тест")
es.append_event("task", tid, "TaskClaimed", {"level": "hour", "session_id": "s-test"})
es.append_event("task", tid, "TaskCompleted", {"answer": "ответ задачи"})

_orig_notify = tg_inbox.notify_chat
in_flight = threading.Event()   # держим «отправку» потока A
started = threading.Event()     # A дошёл до notify

def _slow_notify(text):
    started.set()
    in_flight.wait(timeout=10)  # имитация полёта TG-отправки
    return True

res_a = {}
def _deliver_a():
    res_a["r"] = commands.deliver_result(tid, "ответ задачи", owner="tick:hour")

tg_inbox.notify_chat = _slow_notify
try:
    ta = threading.Thread(target=_deliver_a)
    ta.start()
    check("гонка: A дошёл до отправки (claim взят)", started.wait(timeout=5))
    # параллельный уровень/демон в то же время: claim жив → пропуск
    res_b = commands.deliver_result(tid, "ответ задачи", owner="daemon")
    in_flight.set()             # отпускаем A: отправка завершается
    ta.join(timeout=10)
finally:
    tg_inbox.notify_chat = _orig_notify

sent = [a for a, t in tg_sends() if a == tid and t == "DeliverySent"]
check("гонка: ровно один DeliverySent", len(sent) == 1, f"sent={len(sent)}")
check("гонка: B (демон) пропущен claim'ом", res_b is False, f"res_b={res_b}")
check("гонка: A доставил (True)", res_a.get("r") is True, f"res_a={res_a}")
check("гонка: ledger записан", es.delivery_recorded(tid) is True)

# повтор при записанном ledger (stale read model): SKIP с событием
before = count_skips(tid)
check("stale: повтор SKIP", commands.deliver_result(tid, "ответ") is False)
check("stale: SKIP залогирован DeliverySkipped",
      count_skips(tid) == before + 1, f"skips={count_skips(tid)}")
model = es.run_projections()
check("stale: проекция delivery_skips видна",
      model["tasks"][tid].get("delivery_skips") == 1,
      model["tasks"][tid].get("delivery_skips"))

# ═══════════════ 5. сбой TG: release → демон досылает ═══════════════
tid2, _ = commands.submit_task("Задача с падением TG", "детали", 5)
commands.mark_awaiting_delivery(tid2, reason="тест")
es.append_event("task", tid2, "TaskClaimed", {"level": "hour", "session_id": "s-test2"})
es.append_event("task", tid2, "TaskCompleted", {"answer": "ответ 2"})

def _dead_notify(text):
    raise RuntimeError("TG недоступен")
tg_inbox.notify_chat = _dead_notify
try:
    check("сбой TG: deliver_result False",
          commands.deliver_result(tid2, "ответ 2", owner="daemon") is False)
finally:
    tg_inbox.notify_chat = _orig_notify
check("сбой TG: ledger пуст", es.delivery_recorded(tid2) is False)
db = es._conn()
try:
    row = db.execute("SELECT COUNT(*) AS n FROM delivery_locks WHERE artifact_id=?",
                     (tid2,)).fetchone()
    check("сбой TG: лок освобождён (не ждём TTL)", row["n"] == 0, row["n"])
finally:
    db.close()
# TG ожил: демон досылает на следующем проходе
tg_inbox.notify_chat = lambda text: True
try:
    delivered = deliver_pending()
finally:
    tg_inbox.notify_chat = _orig_notify
check("сбой TG: демон дослал на след. проходе", tid2 in delivered, delivered)
check("сбой TG: DeliverySent появился",
      (tid2, "DeliverySent") in tg_sends())

# ═══════════════ 6. requeue: сброс ledger и флагов → новая доставка ═══════════════
commands.requeue_task(tid, "доработка по просьбе Alex")
check("requeue: ledger сброшен", es.delivery_recorded(tid) is False)
model = es.run_projections()
check("requeue: флаг модели сброшен в await (не 'sent' — досылка не порезана)",
      model["tasks"][tid].get("delivery_status") == "await",
      model["tasks"][tid].get("delivery_status"))
check("requeue: задача снова ready", model["tasks"][tid]["status"] == "ready")
# доработали: новый результат должен уйти (мок)
es.append_event("task", tid, "TaskClaimed", {"level": "hour", "session_id": "s-rq"})
es.append_event("task", tid, "TaskCompleted", {"answer": "ответ после доработки"})
tg_inbox.notify_chat = lambda text: True
try:
    redone = commands.deliver_result(tid, "ответ после доработки", owner="tick:hour")
finally:
    tg_inbox.notify_chat = _orig_notify
check("requeue: новый результат доставлен", redone is True)
check("requeue: после доработки ровно +1 DeliverySent (2 всего)",
      len([1 for a, t in tg_sends() if a == tid and t == "DeliverySent"]) == 2)

# ═══════════════ 7. deliver_pending: pre-filter без дублей ═══════════════
tg_inbox.notify_chat = lambda text: True
try:
    delivered2 = deliver_pending()
finally:
    tg_inbox.notify_chat = _orig_notify
check("pending: уже доставленное не досылается", delivered2 == [], f"got={delivered2}")
# 2 задачи: tid дважды (гонка + доработка после requeue) и tid2 раз → 3
check("pending: DeliverySent не размножены (3 всего: 2×tid + 1×tid2)",
      len([1 for a, t in tg_sends() if t == "DeliverySent"]) == 3)

# ═══════════════ 8. CLI: tg-notify -k / tg-deliver-file ═══════════════
tg_inbox.notify_chat = lambda text: True
tg_inbox.send_document_to_chat = lambda path, caption="": True
try:
    r1 = run_cli("tg-notify", "тестовое уведомление", "-k", "cli-key-1")
    r2 = run_cli("tg-notify", "тестовое уведомление", "-k", "cli-key-1")
finally:
    tg_inbox.notify_chat = _orig_notify
check("cli: tg-notify -k первая — OK", "OK" in r1, r1)
check("cli: tg-notify -k повтор — SKIP", "SKIP" in r2, r2)
check("cli: ledger по ключу записан",
      es.delivery_recorded("msg:cli-key-1") is True)

open("/tmp/simbiot-test-dl.txt", "w").write("файл-артефакт")
_orig_send_doc = tg_inbox.send_document_to_chat
tg_inbox.notify_chat = lambda text: True
tg_inbox.send_document_to_chat = lambda path, caption="": True
try:
    r3 = run_cli("tg-deliver-file", "/tmp/simbiot-test-dl.txt", "-c", "подпись")
    r4 = run_cli("tg-deliver-file", "/tmp/simbiot-test-dl.txt", "-c", "подпись")
    r5 = run_cli("tg-deliver-file", "/tmp/simbiot-test-dl.txt", "-c", "повтор",
                 "--force")
finally:
    tg_inbox.notify_chat = _orig_notify
    tg_inbox.send_document_to_chat = _orig_send_doc
expected_aid = f"file:{os.path.abspath('/tmp/simbiot-test-dl.txt')}"
check("cli: tg-deliver-file первая — OK", "OK" in r3, r3)
check("cli: tg-deliver-file повтор — SKIP", "SKIP" in r4, r4)
check("cli: --force пробивает SKIP", "OK" in r5, r5)
check("cli: ledger по файлу записан",
      es.delivery_recorded(expected_aid) is True)

# ═══════════════ итог ═══════════════
print()
if fails:
    print(f"FAILED: {len(fails)} проверок провалено: {fails}")
    sys.exit(1)
print("OK: идемпотентная доставка — все проверки прошли")