527 lines
18 KiB
Python
527 lines
18 KiB
Python
"""Event delivery: the outbox, and what happens when a module does not answer.
|
|
|
|
Every change a workspace makes has to reach the modules that hold its data —
|
|
provisioning, renames, status changes. The outbox is what makes that survive a
|
|
module being down, and it had almost no coverage: the retry arithmetic, the
|
|
signing, and the terminal-failure path were all untested.
|
|
|
|
The delivery loop existed twice, once per entry point, and the two copies had
|
|
already drifted. These tests assert both behave identically, so a fix to one
|
|
cannot silently miss the other.
|
|
"""
|
|
|
|
from __future__ import annotations
|
|
|
|
import json
|
|
import uuid
|
|
from datetime import datetime, timedelta, timezone
|
|
|
|
import pytest
|
|
|
|
from app.core.tenant_context import unscoped
|
|
from app.models.system.event_log_model import EventLog, EventStatus
|
|
from app.services.auth.event_service import EventService
|
|
|
|
from .conftest import requires_db
|
|
|
|
pytestmark = requires_db
|
|
|
|
SECRET = "test-hmac-secret"
|
|
|
|
|
|
class Response:
|
|
"""Just enough of httpx's response for the delivery loop."""
|
|
|
|
def __init__(self, status_code: int, text: str = ""):
|
|
self.status_code = status_code
|
|
self.text = text
|
|
|
|
|
|
@pytest.fixture
|
|
def module_target(db, tenant_factory, module_factory, environment_factory,
|
|
tenant_module_factory):
|
|
from types import SimpleNamespace
|
|
|
|
tenant = tenant_factory()
|
|
module = module_factory()
|
|
env = environment_factory(module, secret=SECRET)
|
|
link = tenant_module_factory(tenant, module)
|
|
return SimpleNamespace(tenant=tenant, module=module, env=env, link=link)
|
|
|
|
|
|
@pytest.fixture
|
|
def transport(monkeypatch):
|
|
"""Records what was sent and decides what comes back.
|
|
|
|
Nothing here should reach the network; a test that does is a test that fails
|
|
on a train.
|
|
"""
|
|
from app.services.auth import event_service
|
|
|
|
class Transport:
|
|
def __init__(self):
|
|
self.sent = []
|
|
self.responses = [Response(200)]
|
|
|
|
def __call__(self, url, content=None, headers=None, timeout=None):
|
|
self.sent.append({"url": url, "content": content, "headers": headers})
|
|
if len(self.responses) > 1:
|
|
return self.responses.pop(0)
|
|
return self.responses[0]
|
|
|
|
def always(self, status, text=""):
|
|
self.responses = [Response(status, text)]
|
|
|
|
fake = Transport()
|
|
monkeypatch.setattr(event_service.httpx, "post", fake)
|
|
return fake
|
|
|
|
|
|
def _logs(db, tenant=None):
|
|
query = db.query(EventLog)
|
|
return query.order_by(EventLog.created_at).all()
|
|
|
|
|
|
def test_an_event_becomes_an_outbox_row(db, module_target):
|
|
"""Written to the database in the caller's transaction, not posted inline.
|
|
|
|
That is the whole point of an outbox: if the change rolls back, the event
|
|
announcing it rolls back with it.
|
|
"""
|
|
with unscoped():
|
|
EventService.emit_event(
|
|
db, "TENANT_UPDATED", {"tenant_id": str(module_target.tenant.id)},
|
|
tenant_id=module_target.tenant.id,
|
|
)
|
|
rows = _logs(db)
|
|
|
|
assert len(rows) == 1
|
|
assert rows[0].status == EventStatus.PENDING
|
|
assert rows[0].target_module_id == module_target.module.id
|
|
|
|
|
|
def test_delivery_is_scoped_to_workspaces_that_hold_the_module(
|
|
db, module_target, tenant_factory, module_factory, environment_factory
|
|
):
|
|
"""An event about one workspace must not be posted to a module another
|
|
workspace uses — the payload names the tenant, so that is a leak."""
|
|
other_module = module_factory()
|
|
environment_factory(other_module, secret="other")
|
|
|
|
with unscoped():
|
|
EventService.emit_event(
|
|
db, "TENANT_UPDATED", {"tenant_id": str(module_target.tenant.id)},
|
|
tenant_id=module_target.tenant.id,
|
|
)
|
|
rows = _logs(db)
|
|
|
|
assert {r.target_module_id for r in rows} == {module_target.module.id}
|
|
|
|
|
|
def test_a_deactivated_module_is_not_a_target(db, module_target):
|
|
with unscoped():
|
|
module_target.link.is_active = False
|
|
db.flush()
|
|
EventService.emit_event(
|
|
db, "TENANT_UPDATED", {"tenant_id": str(module_target.tenant.id)},
|
|
tenant_id=module_target.tenant.id,
|
|
)
|
|
assert _logs(db) == []
|
|
|
|
|
|
def test_an_event_with_no_targets_writes_nothing(db, tenant_factory):
|
|
"""Documented, not endorsed. A provisioning request that resolves to no
|
|
module is logged as a warning and dropped — the workspace is created and
|
|
nothing downstream ever hears about it."""
|
|
tenant = tenant_factory()
|
|
with unscoped():
|
|
EventService.emit_event(
|
|
db, "TENANT_PROVISION_REQUESTED", {"tenant_id": str(tenant.id)},
|
|
tenant_id=tenant.id,
|
|
)
|
|
assert _logs(db) == []
|
|
|
|
|
|
def test_provisioning_events_go_to_the_provisioning_endpoint(db, module_target):
|
|
"""The rest go to the generic event stream. Sending a provision request to
|
|
the stream would leave a workspace unprovisioned with nothing failing."""
|
|
with unscoped():
|
|
EventService.emit_event(
|
|
db, "TENANT_PROVISION_REQUESTED", {"tenant_id": str(module_target.tenant.id)},
|
|
tenant_id=module_target.tenant.id,
|
|
)
|
|
provisioning = _logs(db)[0].target_url
|
|
|
|
EventService.emit_event(
|
|
db, "SOMETHING_ELSE", {"tenant_id": str(module_target.tenant.id)},
|
|
tenant_id=module_target.tenant.id,
|
|
)
|
|
stream = _logs(db)[1].target_url
|
|
|
|
assert provisioning.endswith(module_target.env.provisioning_endpoint.lstrip("/"))
|
|
assert stream.endswith("/api/internal/events")
|
|
|
|
|
|
@pytest.mark.parametrize("deliver", ["queue_item", "outbox"])
|
|
def test_a_delivered_event_is_signed_with_the_environment_secret(
|
|
db, module_target, transport, deliver
|
|
):
|
|
"""The receiving module has no other way to tell a real event from a POST
|
|
anyone could make to a public URL."""
|
|
import hashlib
|
|
import hmac
|
|
|
|
with unscoped():
|
|
EventService.emit_event(
|
|
db, "TENANT_UPDATED", {"tenant_id": str(module_target.tenant.id)},
|
|
tenant_id=module_target.tenant.id,
|
|
)
|
|
event_id = str(_logs(db)[0].event_id)
|
|
|
|
if deliver == "queue_item":
|
|
EventService.process_queue_item(db, event_id)
|
|
else:
|
|
EventService.process_outbox(db)
|
|
|
|
assert len(transport.sent) == 1
|
|
sent = transport.sent[0]
|
|
expected = hmac.new(SECRET.encode(), sent["content"].encode(), hashlib.sha256).hexdigest()
|
|
assert sent["headers"]["X-SaaS-Signature"] == expected
|
|
|
|
|
|
@pytest.mark.parametrize("deliver", ["queue_item", "outbox"])
|
|
def test_a_success_completes_the_row(db, module_target, transport, deliver):
|
|
with unscoped():
|
|
EventService.emit_event(
|
|
db, "TENANT_UPDATED", {"tenant_id": str(module_target.tenant.id)},
|
|
tenant_id=module_target.tenant.id,
|
|
)
|
|
event_id = str(_logs(db)[0].event_id)
|
|
|
|
if deliver == "queue_item":
|
|
EventService.process_queue_item(db, event_id)
|
|
else:
|
|
EventService.process_outbox(db)
|
|
|
|
row = _logs(db)[0]
|
|
|
|
assert row.status == EventStatus.COMPLETED
|
|
assert row.error_log is None
|
|
|
|
|
|
@pytest.mark.parametrize("deliver", ["queue_item", "outbox"])
|
|
def test_a_failure_schedules_a_retry_rather_than_giving_up(
|
|
db, module_target, transport, deliver
|
|
):
|
|
"""A module being briefly down must not lose the event."""
|
|
transport.always(503, "unavailable")
|
|
|
|
with unscoped():
|
|
EventService.emit_event(
|
|
db, "TENANT_UPDATED", {"tenant_id": str(module_target.tenant.id)},
|
|
tenant_id=module_target.tenant.id,
|
|
)
|
|
event_id = str(_logs(db)[0].event_id)
|
|
|
|
if deliver == "queue_item":
|
|
EventService.process_queue_item(db, event_id)
|
|
else:
|
|
EventService.process_outbox(db)
|
|
|
|
row = _logs(db)[0]
|
|
|
|
assert row.status == EventStatus.PENDING
|
|
assert row.retry_count == 1
|
|
assert row.next_retry_at > datetime.now(timezone.utc)
|
|
assert "503" in row.error_log
|
|
|
|
|
|
def test_the_backoff_grows_and_is_capped(db, module_target, transport):
|
|
"""Uncapped doubling reaches years. Capped at a day, a module that comes
|
|
back after a long outage still receives what it missed."""
|
|
transport.always(500)
|
|
|
|
with unscoped():
|
|
EventService.emit_event(
|
|
db, "TENANT_UPDATED", {"tenant_id": str(module_target.tenant.id)},
|
|
tenant_id=module_target.tenant.id,
|
|
)
|
|
row = _logs(db)[0]
|
|
event_id = str(row.event_id)
|
|
|
|
delays = []
|
|
for _ in range(6):
|
|
row.next_retry_at = datetime.now(timezone.utc) - timedelta(seconds=1)
|
|
db.flush()
|
|
before = datetime.now(timezone.utc)
|
|
EventService.process_queue_item(db, event_id)
|
|
db.refresh(row)
|
|
delays.append((row.next_retry_at - before).total_seconds())
|
|
|
|
assert delays == sorted(delays), f"backoff must not shrink: {delays}"
|
|
assert all(d <= 86_400 + 5 for d in delays), f"capped at a day: {delays}"
|
|
|
|
|
|
def test_an_event_gives_up_eventually(db, module_target, transport):
|
|
"""Retrying for ever keeps a dead endpoint in the working set indefinitely,
|
|
and buries live events behind it."""
|
|
transport.always(500)
|
|
|
|
with unscoped():
|
|
EventService.emit_event(
|
|
db, "TENANT_UPDATED", {"tenant_id": str(module_target.tenant.id)},
|
|
tenant_id=module_target.tenant.id,
|
|
)
|
|
row = _logs(db)[0]
|
|
row.retry_count = 10
|
|
row.next_retry_at = datetime.now(timezone.utc) - timedelta(seconds=1)
|
|
db.flush()
|
|
|
|
EventService.process_queue_item(db, str(row.event_id))
|
|
db.refresh(row)
|
|
|
|
assert row.status == EventStatus.FAILED
|
|
|
|
|
|
def test_a_retry_is_not_attempted_before_its_time(db, module_target, transport):
|
|
with unscoped():
|
|
EventService.emit_event(
|
|
db, "TENANT_UPDATED", {"tenant_id": str(module_target.tenant.id)},
|
|
tenant_id=module_target.tenant.id,
|
|
)
|
|
row = _logs(db)[0]
|
|
row.next_retry_at = datetime.now(timezone.utc) + timedelta(hours=1)
|
|
db.flush()
|
|
|
|
EventService.process_outbox(db)
|
|
|
|
assert transport.sent == []
|
|
|
|
|
|
def test_a_completed_event_is_not_delivered_twice(db, module_target, transport):
|
|
"""The queue can hand the same id back — Redis has no exactly-once."""
|
|
with unscoped():
|
|
EventService.emit_event(
|
|
db, "TENANT_UPDATED", {"tenant_id": str(module_target.tenant.id)},
|
|
tenant_id=module_target.tenant.id,
|
|
)
|
|
event_id = str(_logs(db)[0].event_id)
|
|
|
|
EventService.process_queue_item(db, event_id)
|
|
EventService.process_queue_item(db, event_id)
|
|
|
|
assert len(transport.sent) == 1
|
|
|
|
|
|
def test_a_missing_environment_is_a_terminal_failure_and_it_sticks(
|
|
db, module_target, transport
|
|
):
|
|
"""The row is marked FAILED and the mark has to survive.
|
|
|
|
`continue` skipped the commit at the end of the loop body, so on the last
|
|
row of a batch the status never reached the database and the event was
|
|
retried for ever against configuration that no longer exists.
|
|
"""
|
|
with unscoped():
|
|
EventService.emit_event(
|
|
db, "TENANT_UPDATED", {"tenant_id": str(module_target.tenant.id)},
|
|
tenant_id=module_target.tenant.id,
|
|
)
|
|
row = _logs(db)[0]
|
|
row.target_environment_slug = "no-such-environment"
|
|
db.flush()
|
|
event_id = str(row.event_id)
|
|
|
|
EventService.process_queue_item(db, event_id)
|
|
|
|
db.expire_all()
|
|
reloaded = db.query(EventLog).filter(EventLog.event_id == uuid.UUID(event_id)).one()
|
|
|
|
assert transport.sent == []
|
|
assert reloaded.status == EventStatus.FAILED
|
|
assert reloaded.error_log
|
|
|
|
|
|
def test_a_network_error_is_retried_not_lost(db, module_target, monkeypatch):
|
|
"""An exception must land in the same retry path as a bad status code."""
|
|
from app.services.auth import event_service
|
|
|
|
def explode(*args, **kwargs):
|
|
raise RuntimeError("connection reset")
|
|
|
|
with unscoped():
|
|
EventService.emit_event(
|
|
db, "TENANT_UPDATED", {"tenant_id": str(module_target.tenant.id)},
|
|
tenant_id=module_target.tenant.id,
|
|
)
|
|
event_id = str(_logs(db)[0].event_id)
|
|
|
|
monkeypatch.setattr(event_service.httpx, "post", explode)
|
|
EventService.process_queue_item(db, event_id)
|
|
|
|
row = _logs(db)[0]
|
|
|
|
assert row.status == EventStatus.PENDING
|
|
assert row.retry_count == 1
|
|
assert "connection reset" in row.error_log
|
|
|
|
|
|
def test_a_follow_up_fires_only_after_the_first_event_lands(
|
|
db, module_target, transport
|
|
):
|
|
"""Roles are provisioned after the workspace exists. Emitting both at once
|
|
races, and the module receives roles for a tenant it has never heard of."""
|
|
with unscoped():
|
|
EventService.emit_event(
|
|
db,
|
|
"TENANT_PROVISION_REQUESTED",
|
|
{"tenant_id": str(module_target.tenant.id)},
|
|
tenant_id=module_target.tenant.id,
|
|
follow_up_event={
|
|
"event_type": "ROLE_PROVISION_REQUESTED",
|
|
"payload": {"tenant_id": str(module_target.tenant.id)},
|
|
"tenant_id": str(module_target.tenant.id),
|
|
},
|
|
)
|
|
assert [r.event_type for r in _logs(db)] == ["TENANT_PROVISION_REQUESTED"]
|
|
|
|
EventService.process_queue_item(db, str(_logs(db)[0].event_id))
|
|
types = [r.event_type for r in _logs(db)]
|
|
|
|
assert "ROLE_PROVISION_REQUESTED" in types
|
|
|
|
|
|
def test_a_follow_up_does_not_fire_when_the_first_event_fails(
|
|
db, module_target, transport
|
|
):
|
|
transport.always(500)
|
|
|
|
with unscoped():
|
|
EventService.emit_event(
|
|
db,
|
|
"TENANT_PROVISION_REQUESTED",
|
|
{"tenant_id": str(module_target.tenant.id)},
|
|
tenant_id=module_target.tenant.id,
|
|
follow_up_event={
|
|
"event_type": "ROLE_PROVISION_REQUESTED",
|
|
"payload": {"tenant_id": str(module_target.tenant.id)},
|
|
"tenant_id": str(module_target.tenant.id),
|
|
},
|
|
)
|
|
EventService.process_queue_item(db, str(_logs(db)[0].event_id))
|
|
types = [r.event_type for r in _logs(db)]
|
|
|
|
assert "ROLE_PROVISION_REQUESTED" not in types
|
|
|
|
|
|
def test_the_payload_names_the_event_and_when_it_happened(db, module_target, transport):
|
|
"""Receivers deduplicate on `event_id`; without it, a retry that succeeded
|
|
on the module's side but timed out on ours is applied twice."""
|
|
with unscoped():
|
|
EventService.emit_event(
|
|
db, "TENANT_UPDATED", {"tenant_id": str(module_target.tenant.id)},
|
|
tenant_id=module_target.tenant.id,
|
|
)
|
|
EventService.process_queue_item(db, str(_logs(db)[0].event_id))
|
|
|
|
body = json.loads(transport.sent[0]["content"])
|
|
assert body["event_type"] == "TENANT_UPDATED"
|
|
assert body["event_id"]
|
|
assert body["timestamp"]
|
|
assert body["data"]["tenant_id"] == str(module_target.tenant.id)
|
|
|
|
|
|
def test_the_delivery_headers_name_the_event_and_the_attempt(db, module_target,
|
|
transport):
|
|
"""A receiver has to be able to dedupe before parsing, and to tell a
|
|
redelivery from a genuine duplicate.
|
|
|
|
The header is a hint only — headers are outside the signature, so the
|
|
authoritative id is the one inside the signed body. A receiver that deduped
|
|
on the header would be letting the caller choose its idempotency key.
|
|
"""
|
|
with unscoped():
|
|
EventService.emit_event(
|
|
db, "TENANT_UPDATED", {"tenant_id": str(module_target.tenant.id)},
|
|
tenant_id=module_target.tenant.id,
|
|
)
|
|
event_id = str(_logs(db)[0].event_id)
|
|
EventService.process_queue_item(db, event_id)
|
|
|
|
headers = transport.sent[0]["headers"]
|
|
body = json.loads(transport.sent[0]["content"])
|
|
|
|
assert headers["X-SaaS-Event-Id"] == event_id
|
|
assert headers["X-SaaS-Event-Id"] == body["event_id"], "the hint must match the signed value"
|
|
assert headers["X-SaaS-Delivery-Attempt"] == "1"
|
|
assert headers["X-SaaS-Signature-Version"] == EventService.SIGNATURE_VERSION
|
|
|
|
|
|
def test_a_redelivery_keeps_the_event_id_and_counts_up(db, module_target, transport):
|
|
"""Stable id, rising attempt: that pair is what makes a retry safe to apply
|
|
and legible in a log."""
|
|
transport.always(500)
|
|
|
|
with unscoped():
|
|
EventService.emit_event(
|
|
db, "TENANT_UPDATED", {"tenant_id": str(module_target.tenant.id)},
|
|
tenant_id=module_target.tenant.id,
|
|
)
|
|
row = _logs(db)[0]
|
|
event_id = str(row.event_id)
|
|
|
|
for _ in range(2):
|
|
row.next_retry_at = datetime.now(timezone.utc) - timedelta(seconds=1)
|
|
db.flush()
|
|
EventService.process_queue_item(db, event_id)
|
|
|
|
attempts = [s["headers"]["X-SaaS-Delivery-Attempt"] for s in transport.sent]
|
|
ids = {s["headers"]["X-SaaS-Event-Id"] for s in transport.sent}
|
|
|
|
assert attempts == ["1", "2"]
|
|
assert ids == {event_id}
|
|
|
|
|
|
def test_emitting_reports_how_many_modules_it_will_reach(db, module_target,
|
|
tenant_factory):
|
|
"""So a caller can tell "provisioned to two modules" from "provisioned to
|
|
nobody" — which used to be indistinguishable from the outside."""
|
|
with unscoped():
|
|
reached = EventService.emit_event(
|
|
db, "TENANT_PROVISION_REQUESTED",
|
|
{"tenant_id": str(module_target.tenant.id)},
|
|
tenant_id=module_target.tenant.id,
|
|
)
|
|
assert reached == 1
|
|
|
|
lonely = tenant_factory()
|
|
assert EventService.emit_event(
|
|
db, "TENANT_PROVISION_REQUESTED", {"tenant_id": str(lonely.id)},
|
|
tenant_id=lonely.id,
|
|
) == 0
|
|
|
|
|
|
def test_a_provisioning_request_that_reaches_nobody_is_logged_as_an_error(
|
|
db, tenant_factory, caplog
|
|
):
|
|
"""A workspace that exists here and nowhere else is not a routine dropped
|
|
broadcast, and should not share a log level with one."""
|
|
import logging
|
|
|
|
lonely = tenant_factory()
|
|
with unscoped(), caplog.at_level(logging.WARNING):
|
|
EventService.emit_event(
|
|
db, "TENANT_PROVISION_REQUESTED", {"tenant_id": str(lonely.id)},
|
|
tenant_id=lonely.id,
|
|
)
|
|
EventService.emit_event(
|
|
db, "TENANT_UPDATED", {"tenant_id": str(lonely.id)},
|
|
tenant_id=lonely.id,
|
|
)
|
|
|
|
levels = {
|
|
r.levelno for r in caplog.records if "reached no modules" in r.getMessage()
|
|
}
|
|
assert logging.ERROR in levels, "provisioning reaching nobody is an error"
|
|
assert logging.WARNING in levels, "an informational broadcast is not"
|