app/backend/tests/test_metrics.py

"""The collector writes down what the bus only ever broadcast.

Not under ``tests/flow`` with the rest of the engine: that package opts out of
the database, and writing to it is this module's whole job.
"""

import asyncio
import time
from datetime import UTC, datetime

from sqlmodel import Session, select

from fluksio.flow.events import EventBus
from fluksio.flow.executor import ExecutionService
from fluksio.flow.messages import DType, MessageSpec
from fluksio.flow.metrics import DETAIL_CAP, RUN_STALE_S, MetricsCollector
from fluksio.flow.nodes import Node
from fluksio.flow.pipeline import Pipeline
from fluksio.flow.queue import MemoryWorkQueue
from fluksio.models import EngineEvent, FlowRun, MetricBucket

FLOW = "metrics-test"
NODE = "metrics-test.calc"


def _events(collector: MetricsCollector, ts: float, run: str) -> None:
    collector.handle(
        {
            "type": "cascade_started",
            "run": run,
            "flow": FLOW,
            "node": "metrics-test.in",
            "cause": "external",
            "deliveries": 1,
            "ts": ts,
        }
    )
    collector.handle(
        {
            "type": "node_executed",
            "flow": FLOW,
            "node": NODE,
            "outputs": 2,
            "duration_ms": 5.0,
            "run": run,
            "ts": ts,
        }
    )
    collector.handle(
        {"type": "work_latency", "flow": FLOW, "node": NODE, "lag_ms": 12.0, "ts": ts}
    )
    # The traceback arrives as its own event, just before the failure.
    collector.handle(
        {
            "type": "node_log",
            "flow": FLOW,
            "node": NODE,
            "level": "error",
            "text": "Traceback: line 3, in run",
            "ts": ts,
        }
    )
    collector.handle(
        {
            "type": "node_error",
            "flow": FLOW,
            "node": NODE,
            "error": "ValueError: bad input",
            "run": run,
            "ts": ts,
        }
    )


def test_events_become_rollups_failures_runs_and_audit(db: Session) -> None:
    collector = MetricsCollector(EventBus())
    # The current minute, pinned: the second flush has to land in the same
    # bucket, and anything past the retention window is pruned on write.
    ts = datetime.now(UTC).replace(second=0, microsecond=0).timestamp()
    _events(collector, ts, "1-0")
    collector.handle(
        {
            "type": "audit",
            "action": "published",
            "flow": FLOW,
            "user": "someone@example.com",
            "ts": ts,
        }
    )
    collector.handle(
        {"type": "cascade_finished", "run": "1-0", "flow": FLOW, "ts": ts + 0.5}
    )
    asyncio.run(collector.flush())

    bucket = db.exec(
        select(MetricBucket).where(MetricBucket.flow == FLOW, MetricBucket.node == NODE)
    ).one()
    assert (bucket.executions, bucket.errors, bucket.messages) == (1, 1, 2)
    assert bucket.duration_max_ms == 5.0
    assert (bucket.lag_max_ms, bucket.items) == (12.0, 1)

    failure = db.exec(
        select(EngineEvent).where(
            EngineEvent.flow == FLOW, EngineEvent.type == "node_error"
        )
    ).one()
    assert "ValueError: bad input" in failure.detail
    assert "line 3, in run" in failure.detail

    audit = db.exec(
        select(EngineEvent).where(EngineEvent.flow == FLOW, EngineEvent.type == "audit")
    ).one()
    assert (audit.actor, audit.detail) == ("someone@example.com", "published")

    run = db.exec(select(FlowRun).where(FlowRun.id == "1-0")).one()
    assert (run.status, run.flow, run.source) == ("error", FLOW, "external")
    assert (run.nodes, run.errors) == (1, 1)
    assert run.duration_ms > 0

    # The same minute, written again: the counters add rather than duplicate.
    _events(collector, ts + 10, "2-0")
    asyncio.run(collector.flush())
    db.expire_all()
    bucket = db.exec(
        select(MetricBucket).where(MetricBucket.flow == FLOW, MetricBucket.node == NODE)
    ).one()
    assert (bucket.executions, bucket.errors) == (2, 2)

    # Never finished, so it is still open — the prune is what closes it.
    open_run = db.exec(select(FlowRun).where(FlowRun.id == "2-0")).one()
    assert open_run.status == "running"


def test_a_flush_the_database_refused_is_written_by_the_next_one(
    db: Session, monkeypatch
) -> None:
    collector = MetricsCollector(EventBus())
    ts = datetime.now(UTC).replace(second=0, microsecond=0).timestamp()
    collector.handle(
        {
            "type": "audit",
            "action": "held back",
            "flow": FLOW,
            "user": "held@example.com",
            "ts": ts,
        }
    )

    def refuse(*_args: object) -> None:
        raise RuntimeError("the database is gone")

    monkeypatch.setattr(collector, "_write", refuse)
    asyncio.run(collector.flush())
    monkeypatch.undo()
    asyncio.run(collector.flush())

    audit = db.exec(
        select(EngineEvent).where(EngineEvent.actor == "held@example.com")
    ).one()
    assert audit.detail == "held back"


def test_batched_rollups_add_and_redelivery_clears_a_finished_run(db: Session) -> None:
    collector = MetricsCollector(EventBus())
    ts = time.time()
    for i in range(2):
        collector.handle(
            {"type": "cascade_started", "run": f"bulk-{i}", "flow": "bulk", "ts": ts}
        )
        collector.handle(
            {
                "type": "node_executed",
                "flow": "bulk",
                "node": f"bulk.n{i}",
                "run": f"bulk-{i}",
                "outputs": 1,
                "duration_ms": 10.0,
                "ts": ts,
            }
        )
    collector.handle({"type": "cascade_finished", "run": "bulk-0", "ts": ts + 1})
    # Write the same open/finished batch twice, as a retained run is upserted.
    collector._write(collector._buckets, [], list(collector._runs.values()), False)
    collector.handle(
        {
            "type": "cascade_started",
            "run": "bulk-0",
            "flow": "bulk",
            "deliveries": 2,
            "ts": ts + 2,
        }
    )
    collector.handle({"type": "cascade_finished", "run": "bulk-1", "ts": ts + 3})
    for bucket in collector._buckets.values():
        bucket["duration_sum_ms"] = 4.0
        bucket["duration_max_ms"] = 4.0
    collector._write(collector._buckets, [], list(collector._runs.values()), False)

    buckets = db.exec(select(MetricBucket).where(MetricBucket.flow == "bulk")).all()
    assert len(buckets) == 2
    assert all(
        (b.executions, b.messages, b.duration_sum_ms, b.duration_max_ms)
        == (2, 2, 14.0, 10.0)
        for b in buckets
    )
    reopened = db.get(FlowRun, "bulk-0")
    assert reopened is not None
    assert (reopened.status, reopened.finished_at, reopened.deliveries) == (
        "running",
        None,
        2,
    )
    finished = db.get(FlowRun, "bulk-1")
    assert finished is not None and finished.finished_at is not None
    assert finished.status == "ok"


def test_a_node_id_wider_than_the_column_still_records(db: Session) -> None:
    collector = MetricsCollector(EventBus())
    ts = datetime.now(UTC).replace(second=0, microsecond=0).timestamp()
    long_node = f"{FLOW}.{'w' * 400}"
    collector.handle(
        {
            "type": "node_executed",
            "flow": FLOW,
            "node": long_node,
            "duration_ms": 1.0,
            "ts": ts,
        }
    )
    asyncio.run(collector.flush())

    bucket = db.exec(
        select(MetricBucket).where(MetricBucket.node == long_node[:255])
    ).one()
    assert bucket.executions == 1


def test_a_run_that_did_not_fail_reads_ok(db: Session) -> None:
    collector = MetricsCollector(EventBus())
    ts = time.time()
    collector.handle(
        {
            "type": "cascade_started",
            "run": "manual-abc",
            "flow": FLOW,
            "node": "metrics-test.in",
            "cause": "manual",
            "deliveries": 1,
            "ts": ts,
        }
    )
    collector.handle(
        {"type": "cascade_finished", "run": "manual-abc", "flow": FLOW, "ts": ts + 0.1}
    )
    asyncio.run(collector.flush())

    run = db.exec(select(FlowRun).where(FlowRun.id == "manual-abc")).one()
    assert (run.status, run.source) == ("ok", "manual")


def test_a_traceback_no_failure_ever_claims_is_dropped() -> None:
    """One entry per node that ever errored would else last the process out."""
    node = f"{FLOW}.stale"
    collector = MetricsCollector(EventBus())
    collector.handle(
        {
            "type": "node_log",
            "flow": FLOW,
            "node": node,
            "level": "error",
            "text": "x" * (DETAIL_CAP * 2),
            "ts": time.time() - RUN_STALE_S - 1,
        }
    )

    # Untruncated, one of these holds a whole run of a chatty node.
    assert len(collector._tracebacks[(FLOW, node)][1]) == DETAIL_CAP

    # Something to write, so the flush does not stop at its early return.
    collector.handle(
        {"type": "node_executed", "flow": FLOW, "node": node, "ts": time.time()}
    )
    asyncio.run(collector.flush())

    assert collector._tracebacks == {}


def test_a_batch_run_is_recorded_beside_the_cascades(db: Session) -> None:
    """`fluksio run` showed on /runs and nowhere on Home.

    It opens no cascade, so the collector saw its nodes and its failures with
    no record to fold them into. The start is aged past the staleness cutoff on
    purpose: a training step of an hour is a normal one, and only
    `run_finished` may end a batch run.
    """
    collector = MetricsCollector(EventBus())
    started = time.time() - RUN_STALE_S - 60
    collector.handle(
        {"type": "run_started", "run": "run-batch", "flow": FLOW, "ts": started}
    )
    collector.handle(
        {
            "type": "node_executed",
            "flow": FLOW,
            "node": NODE,
            "run": "run-batch",
            "duration_ms": 5.0,
            "ts": started,
        }
    )
    asyncio.run(collector.flush())

    row = db.exec(select(FlowRun).where(FlowRun.id == "run-batch")).one()
    assert (row.status, row.source, row.nodes) == ("running", "run", 1)

    collector.handle(
        {
            "type": "run_finished",
            "run": "run-batch",
            "flow": FLOW,
            "status": "ok",
            "ts": started + 30,
        }
    )
    asyncio.run(collector.flush())

    db.expire_all()
    row = db.exec(select(FlowRun).where(FlowRun.id == "run-batch")).one()
    assert (row.status, row.duration_ms) == ("ok", 30_000.0)


def test_a_failure_keeps_the_run_it_happened_in(db: Session) -> None:
    """The payload always carried it; the row used to drop it.

    Nothing told this collector the run had started, so there is no `FlowRun`
    beside it — the failure still has to name what it happened in.
    """
    collector = MetricsCollector(EventBus())
    ts = datetime.now(UTC).replace(second=0, microsecond=0).timestamp()
    collector.handle(
        {
            "type": "node_error",
            "flow": FLOW,
            "node": NODE,
            "error": "ValueError: in a run",
            "run": "run-abc123",
            "ts": ts,
        }
    )
    asyncio.run(collector.flush())

    failure = db.exec(select(EngineEvent).where(EngineEvent.run == "run-abc123")).one()
    assert failure.detail.startswith("ValueError: in a run")


def test_a_rate_limit_flush_is_a_run_that_names_its_parent(db: Session) -> None:
    """A flush used to run under no id, so what it set off was in no run."""
    collector = MetricsCollector(EventBus())

    class Bus:
        """Hands every event straight to the collector."""

        def publish(self, event: dict) -> None:
            collector.handle(event)

    window = 0.05
    source = Node(
        f=lambda params: None,
        provides=[MessageSpec(name="raw", dtype=DType.FLOAT)],
        name="in",
    )
    relay = Node(
        f=lambda raw, params: {"level": raw},
        requires=[MessageSpec(name="raw", dtype=DType.FLOAT)],
        provides=[MessageSpec(name="level", dtype=DType.FLOAT, interval=window)],
        name="relay",
    )
    source.assign_flow("metrics-flush", "in")
    relay.assign_flow("metrics-flush", "relay")
    queue = MemoryWorkQueue()
    pipeline = Pipeline(nodes=[source, relay], work_queue=queue, events=Bus())
    service = ExecutionService(queue, events=Bus())
    service.bind(pipeline)

    # The second value lands inside the relay's window and is held.
    held_in = ""
    for value in (1.0, 2.0):
        source.inject({"raw": value})
        for item in queue.claim(10, 10):
            service._run_item(item)
            held_in = item.entry_id
    time.sleep(window * 2)
    queue.move_due(time.time())
    for item in queue.claim(10, 10):
        service._run_item(item)
    asyncio.run(collector.flush())

    flush = db.exec(select(FlowRun).where(FlowRun.source == "flush")).one()
    assert (flush.status, flush.parent) == ("ok", held_in)
    parent = db.get(FlowRun, held_in)
    assert parent is not None
    assert (parent.flow, parent.source) == ("metrics-flush", "external")