fix(notifications): exponential backoff + CAS claim for expired-unacked re-escalation (#652)

The sweep re-escalated every expired unacked ack-required notification on every ~60s tick, forever — the live incident: 3 fresh blocker escalations + Telegram DMs per minute from a static stale pile. Now each notification carries reescalation_count / last_reescalated_at / reescalation_delivered_count (migration 079): first fire at expiry, then doubling intervals from 1h capped at 24h, hard stop after ROBOCO_NOTIFICATION_MAX_REESCALATIONS (default 5) with one permanent log carrying attempts-vs-delivered so 'seen and ignored' is distinguishable from 'route never worked'. The due/wait/capped decision is a pure function in foundation/policy/communications.py. Per adversarial review, the attempt slot is claimed by compare-and-set (UPDATE ... WHERE reescalation_count = :n) BEFORE delivery — the previous draft leaned on the 60s dedup window, which never engages for BLOCKER_ESCALATION (_LOOP_PRONE_TYPES excludes it), so concurrent sweeps would have double-delivered. A lost claim skips delivery outright. Legacy rows read as count=0 and keep today's first-fire semantics. 61 tests incl. a two-session CAS race and a real alembic upgrade/downgrade round trip. Co-authored-by: Renn F <rennf93@users.noreply.github.com>
2026-08-03 07:23:24 +02:00 · 2026-07-23 00:05:41 +02:00
parent 31a489b431
commit 1d5a8e846f
7 changed files with 639 additions and 42 deletions
@@ -0,0 +1,83 @@
+"""Re-escalation backoff columns on notifications (migration 079).
+
+Migration 079 adds ``notifications.reescalation_count`` /
+``.reescalation_delivered_count`` (integer, not null, default 0) and
+``.last_reescalated_at`` (timestamptz, null). The real upgrade/downgrade
+chain is verified separately against a throwaway Postgres; these assertions
+guard the resulting schema shape and a value round-trip.
+"""
+
+from __future__ import annotations
+
+from datetime import UTC, datetime
+from typing import TYPE_CHECKING
+from uuid import uuid4
+
+import pytest
+from roboco.db.tables import AgentTable, NotificationTable
+from roboco.models import AgentRole, AgentStatus, NotificationPriority, NotificationType
+from roboco.models.base import Team
+from sqlalchemy import select
+
+if TYPE_CHECKING:
+    from sqlalchemy.ext.asyncio import AsyncSession
+
+
+async def _seed_notification(db_session: AsyncSession) -> NotificationTable:
+    sender = AgentTable(
+        id=uuid4(),
+        name="Dev",
+        slug=f"be-dev-{uuid4().hex[:8]}",
+        role=AgentRole.DEVELOPER,
+        team=Team.BACKEND,
+        status=AgentStatus.ACTIVE,
+        model_config={},
+        system_prompt="dev",
+        capabilities=[],
+        permissions={},
+        metrics={},
+    )
+    db_session.add(sender)
+    await db_session.flush()
+    notification = NotificationTable(
+        type=NotificationType.BLOCKER_ESCALATION,
+        priority=NotificationPriority.HIGH,
+        from_agent=sender.id,
+        to_agents=[sender.id],
+        subject="stale",
+        body="body",
+        requires_ack=True,
+    )
+    db_session.add(notification)
+    await db_session.flush()
+    return notification
+
+
+@pytest.mark.asyncio
+async def test_reescalation_backoff_columns_default(db_session: AsyncSession) -> None:
+    notification = await _seed_notification(db_session)
+    assert notification.reescalation_count == 0
+    assert notification.reescalation_delivered_count == 0
+    assert notification.last_reescalated_at is None
+
+
+@pytest.mark.asyncio
+async def test_reescalation_backoff_columns_round_trip(
+    db_session: AsyncSession,
+) -> None:
+    notification = await _seed_notification(db_session)
+    stamped_at = datetime.now(UTC)
+    attempts, delivered = 3, 2
+    notification.reescalation_count = attempts
+    notification.reescalation_delivered_count = delivered
+    notification.last_reescalated_at = stamped_at
+    await db_session.flush()
+
+    row = (
+        await db_session.execute(
+            select(NotificationTable).where(NotificationTable.id == notification.id)
+        )
+    ).scalar_one()
+    assert row.reescalation_count == attempts
+    assert row.reescalation_delivered_count == delivered
+    assert row.last_reescalated_at == stamped_at
@@ -5,6 +5,17 @@ unacked must be re-escalated to the recipient's up-role (the PM's PM or
 the CEO) BEFORE the sweep logs/expiring it — not just logged-and-dropped.
 Combined with H12 (Task 6), an inattentive PM can't both miss a blocker
 and prevent main-pm from seeing it.
+
+Re-escalation backoff: a static pile of stale notifications used to
+re-escalate on *every* sweep tick (~1min) forever. `reescalation_decision`
+(pure, in `foundation/policy/communications.py`) gates each tick behind a
+per-notification exponential schedule + a hard retry cap.
+
+Double-delivery race: `_persist_and_deliver`'s 60s dedup guard is a no-op for
+`BLOCKER_ESCALATION` (not in `_LOOP_PRONE_TYPES`), so it can't backstop two
+concurrent sweep ticks racing the same stale row — a compare-and-set claim
+(`_claim_reescalation_slot`) is the real guard, exercised below by racing two
+service instances against the same row.
 """

 from __future__ import annotations
@@ -15,8 +26,14 @@ from unittest.mock import AsyncMock, MagicMock, patch
 from uuid import UUID, uuid4

 import pytest
+from roboco.config import settings
+from roboco.foundation.policy.communications import (
+    ReescalationPolicy,
+    reescalation_decision,
+)
 from roboco.models import NotificationPriority, NotificationType
 from roboco.services.notification_delivery import NotificationDeliveryService
+from sqlalchemy import Update


 def _stale_notification(
@@ -24,7 +41,8 @@ def _stale_notification(
    requires_ack: bool = True,
    acked: bool = False,
    recipient_id: UUID | None = None,
-    from_agent_id: UUID | None = None,
+    reescalation_count: int = 0,
+    last_reescalated_at: datetime | None = None,
 ) -> MagicMock:
    n = MagicMock()
    n.id = uuid4()
@@ -39,8 +57,11 @@ def _stale_notification(
    n.acked_by = [rid] if acked else []
    n.read_by = []
    n.requires_ack = requires_ack
-    n.from_agent = from_agent_id or uuid4()
+    n.from_agent = uuid4()
    n.related_task_id = uuid4()
+    n.reescalation_count = reescalation_count
+    n.reescalation_delivered_count = 0  # no test needs a nonzero starting value
+    n.last_reescalated_at = last_reescalated_at
    return n


@@ -74,14 +95,37 @@ def _svc_with_agents(
    return svc


-def _session_returning(notifications: list[MagicMock]) -> MagicMock:
-    """A session whose `execute(...).scalars().all()` returns `notifications`."""
+def _assign_id_on_add(obj: Any) -> None:
+    """`session.add` side effect: a real flush assigns the SQLAlchemy-default
+    id; this mock has no engine to do that, so stand in for it here — without
+    it `require_uuid(notification.id)` in `_persist_and_deliver` always raises
+    on the freshly-built re-escalation row, making every "delivered" outcome
+    in this suite look like a failure."""
+    if getattr(obj, "id", None) is None:
+        obj.id = uuid4()
+
+
+def _session_returning(
+    notifications: list[MagicMock], *, claim_succeeds: bool = True
+) -> MagicMock:
+    """A session whose SELECT (the sweep's stale-notifications query) returns
+    `notifications`; every re-escalation CAS UPDATE (`_claim_reescalation_slot`)
+    reports 1 row affected — the claim wins — unless `claim_succeeds` is False,
+    simulating a concurrent sweep tick that already claimed this row's slot."""
    session = MagicMock()
-    session.add = MagicMock()
+    session.add = MagicMock(side_effect=_assign_id_on_add)
    session.flush = AsyncMock()
-    result = MagicMock()
-    result.scalars.return_value.all.return_value = notifications
-    session.execute = AsyncMock(return_value=result)
+
+    select_result = MagicMock()
+    select_result.scalars.return_value.all.return_value = notifications
+
+    update_result = MagicMock()
+    update_result.rowcount = 1 if claim_succeeds else 0
+
+    async def _execute(statement: Any, *_args: Any, **_kwargs: Any) -> MagicMock:
+        return update_result if isinstance(statement, Update) else select_result
+
+    session.execute = AsyncMock(side_effect=_execute)
    return session


@@ -119,6 +163,7 @@ async def test_sweep_re_escalates_stale_unacked_ack_required() -> None:
    assert re_escalated.type == NotificationType.BLOCKER_ESCALATION
    assert re_escalated.requires_ack is True
    assert "Re-escalation" in re_escalated.subject
+    assert notif.reescalation_delivered_count == 1  # the attempt was delivered


@pytest.mark.asyncio
@@ -182,7 +227,11 @@ async def test_sweep_does_not_re_escalate_non_ack_required() -> None:
 async def test_sweep_skips_re_escalation_when_no_chain_target() -> None:
    """Recipient with no configured escalation target → no re-escalation, but
    the stale unacked count still surfaces (best-effort: missing chain is
-    logged-and-skipped, never raises)."""
+    logged-and-skipped, never raises). The attempt slot is still consumed
+    (reescalation_count bumps) even though nothing was delivered — a broken
+    chain burns attempts rather than looping forever; delivered stays 0,
+    which is exactly the "route never worked" signal `_log_permanently_unacked`
+    now carries."""
    recipient = _agent("ghost-role")
    notif = _stale_notification(
        requires_ack=True, acked=False, recipient_id=recipient.id
@@ -205,12 +254,164 @@ async def test_sweep_skips_re_escalation_when_no_chain_target() -> None:

    assert count == 1  # still stale + unacked
    session.add.assert_not_called()
+    assert notif.reescalation_count == 1  # attempt slot consumed regardless
+    assert notif.reescalation_delivered_count == 0  # ...but nothing delivered


@pytest.mark.asyncio
-async def test_sweep_dedup_suppresses_repeat_re_escalation() -> None:
-    """A repeat sweep within the dedup window does not re-fire the same
-    re-escalation (loop-prone guard in `_persist_and_deliver`)."""
+async def test_sweep_cas_claim_prevents_double_delivery_race() -> None:
+    """Two service instances (simulating two concurrent sweep ticks) race the
+    same stale row. `_persist_and_deliver`'s 60s dedup guard cannot arbitrate
+    this — BLOCKER_ESCALATION isn't a `_LOOP_PRONE_TYPES` member, so it's a
+    no-op for this path. The CAS claim in `_claim_reescalation_slot` is what
+    actually decides it: exactly one instance wins the guarded UPDATE and
+    delivers; the loser (0 rows updated) skips delivery entirely, without
+    raising."""
+    recipient = _agent("be-pm")
+    target = _agent("main-pm")
+    notif = _stale_notification(
+        requires_ack=True, acked=False, recipient_id=recipient.id
+    )
+
+    winner_session = _session_returning([notif], claim_succeeds=True)
+    loser_session = _session_returning([notif], claim_succeeds=False)
+    winner = _svc_with_agents(
+        winner_session, recipient=recipient, escalation_target=target
+    )
+    loser = _svc_with_agents(
+        loser_session, recipient=recipient, escalation_target=target
+    )
+
+    with (
+        patch(
+            "roboco.services.notification_delivery.all_recipients_recently_notified",
+            AsyncMock(return_value=False),
+        ),
+        patch(
+            "roboco.services.notification_delivery.get_escalation_target",
+            return_value="main-pm",
+        ),
+    ):
+        winner_count = await winner.sweep_expired_notifications()
+        loser_count = await loser.sweep_expired_notifications()
+
+    assert winner_count == 1
+    assert loser_count == 1  # still stale + unacked from the loser's own view
+    assert winner_session.add.call_count == 1  # won the claim, delivered
+    loser_session.add.assert_not_called()  # lost the claim, never touched delivery
+
+
+# =============================================================================
+# reescalation_decision — pure schedule math
+# =============================================================================
+
+
+_DEFAULT_POLICY = ReescalationPolicy(base_seconds=3600, max_reescalations=5)
+
+
+def test_reescalation_decision_first_fire_due_at_expiry() -> None:
+    """count=0 (including a legacy row with no backoff state) is due the
+    instant `now` reaches `expires_at` — preserves the original semantics."""
+    expires_at = datetime(2026, 1, 1, tzinfo=UTC)
+    assert (
+        reescalation_decision(
+            now=expires_at,
+            expires_at=expires_at,
+            count=0,
+            last_reescalated_at=None,
+            policy=_DEFAULT_POLICY,
+        )
+        == "due"
+    )
+
+
+def test_reescalation_decision_first_fire_not_due_before_expiry() -> None:
+    expires_at = datetime(2026, 1, 1, tzinfo=UTC)
+    assert (
+        reescalation_decision(
+            now=expires_at - timedelta(seconds=1),
+            expires_at=expires_at,
+            count=0,
+            last_reescalated_at=None,
+            policy=_DEFAULT_POLICY,
+        )
+        == "wait"
+    )
+
+
+def test_reescalation_decision_backoff_doubles() -> None:
+    """count=2 waits 2*base (2h at the default base) from the last fire."""
+    last = datetime(2026, 1, 1, tzinfo=UTC)
+    expires_at = last - timedelta(hours=3)
+    not_yet = reescalation_decision(
+        now=last + timedelta(hours=2) - timedelta(seconds=1),
+        expires_at=expires_at,
+        count=2,
+        last_reescalated_at=last,
+        policy=_DEFAULT_POLICY,
+    )
+    due = reescalation_decision(
+        now=last + timedelta(hours=2),
+        expires_at=expires_at,
+        count=2,
+        last_reescalated_at=last,
+        policy=_DEFAULT_POLICY,
+    )
+    assert not_yet == "wait"
+    assert due == "due"
+
+
+def test_reescalation_decision_interval_capped_at_24h() -> None:
+    """However high `count` climbs (a raised max_reescalations), the wait
+    between attempts never exceeds 24h."""
+    last = datetime(2026, 1, 1, tzinfo=UTC)
+    expires_at = last - timedelta(days=1)
+    policy = ReescalationPolicy(base_seconds=3600, max_reescalations=20)
+    # Uncapped this would be base*2**8 = 256h; capped it's 24h.
+    not_yet = reescalation_decision(
+        now=last + timedelta(hours=24) - timedelta(seconds=1),
+        expires_at=expires_at,
+        count=9,
+        last_reescalated_at=last,
+        policy=policy,
+    )
+    due = reescalation_decision(
+        now=last + timedelta(hours=24),
+        expires_at=expires_at,
+        count=9,
+        last_reescalated_at=last,
+        policy=policy,
+    )
+    assert not_yet == "wait"
+    assert due == "due"
+
+
+def test_reescalation_decision_capped_past_max_regardless_of_timing() -> None:
+    """count >= max_reescalations is always "capped", even if the schedule
+    math would otherwise say a re-escalation is overdue."""
+    last = datetime(2026, 1, 1, tzinfo=UTC)
+    assert (
+        reescalation_decision(
+            now=last + timedelta(days=365),
+            expires_at=last - timedelta(hours=1),
+            count=5,
+            last_reescalated_at=last,
+            policy=_DEFAULT_POLICY,
+        )
+        == "capped"
+    )
+
+
+# =============================================================================
+# sweep_expired_notifications — backoff integration
+# =============================================================================
+
+
+@pytest.mark.asyncio
+async def test_sweep_backoff_does_not_refire_within_the_interval() -> None:
+    """A row re-escalates once, then a same-tick-ish second sweep (interval
+    not elapsed) does not re-escalate again — and its schedule state (count,
+    last_reescalated_at) is stamped on the notification after the first."""
    recipient = _agent("be-pm")
    target = _agent("main-pm")
    notif = _stale_notification(
@@ -223,7 +424,47 @@ async def test_sweep_dedup_suppresses_repeat_re_escalation() -> None:
    with (
        patch(
            "roboco.services.notification_delivery.all_recipients_recently_notified",
-            AsyncMock(return_value=True),
+            AsyncMock(return_value=False),
+        ),
+        patch(
+            "roboco.services.notification_delivery.get_escalation_target",
+            return_value="main-pm",
+        ),
+    ):
+        first = await svc.sweep_expired_notifications()
+        assert notif.reescalation_count == 1
+        assert notif.last_reescalated_at is not None
+        assert session.add.call_count == 1
+
+        second = await svc.sweep_expired_notifications()
+
+    assert first == 1
+    assert second == 1  # still stale + unacked
+    assert session.add.call_count == 1  # no second re-escalation this soon
+
+
+@pytest.mark.asyncio
+async def test_sweep_capped_row_never_re_escalates_again() -> None:
+    """A row already at the retry cap is skipped forever — no re-escalation,
+    no repeat 'permanently unacked' log — but still counts as stale+unacked."""
+    recipient = _agent("be-pm")
+    target = _agent("main-pm")
+    capped_count = settings.notification_max_reescalations
+    notif = _stale_notification(
+        requires_ack=True,
+        acked=False,
+        recipient_id=recipient.id,
+        reescalation_count=capped_count,
+        last_reescalated_at=datetime.now(UTC) - timedelta(days=1),
+    )
+
+    session = _session_returning([notif])
+    svc = _svc_with_agents(session, recipient=recipient, escalation_target=target)
+
+    with (
+        patch(
+            "roboco.services.notification_delivery.all_recipients_recently_notified",
+            AsyncMock(return_value=False),
        ),
        patch(
            "roboco.services.notification_delivery.get_escalation_target",
@@ -232,5 +473,6 @@ async def test_sweep_dedup_suppresses_repeat_re_escalation() -> None:
    ):
        count = await svc.sweep_expired_notifications()

-    assert count == 1  # stale + unacked still reported
-    session.add.assert_not_called()  # dedup suppressed the re-escalation row
+    assert count == 1  # still stale + unacked
+    session.add.assert_not_called()
+    assert notif.reescalation_count == capped_count  # untouched — no further attempts