rm3100/tests/test_logger.py

"""The capture loop: miss counting, flagging, and the configuration warnings.

sample_loop() is the subtlest code in the repo -- it decides how many
measurements passed unseen, and getting it wrong slips sample_index against chip
time in a way nothing downstream can detect. It is driven here by a scripted
sensor against a fake clock, so a stall of an exact size can be injected and the
resulting rows checked exactly.
"""

import queue

import pytest

import capture
import logger
import rm3100
from conftest import FakeSensor, grid_events

PERIOD = 0.01           # 100 Hz, chosen so stalls are easy to state in periods


def drain(q):
    """Every row the loop queued, in order."""
    rows = []
    while not q.empty():
        rows.append(q.get_nowait())
    return rows


def run_loop(sensor, fake_clock, duration, dt=PERIOD, maxsize=0):
    """Run sample_loop against a fake sensor. Returns (rows, stats)."""
    fake_clock(sensor)
    q = queue.Queue(maxsize=maxsize)
    stats = {"rows": 0, "missed": 0, "ambiguous": 0, "max_bracket": 0.0,
             "truncated": False}
    logger.sample_loop(sensor, q, duration, dt, stats)
    return drain(q), stats


def indices(rows):
    return [r[0] for r in rows]


def flags(rows):
    return [r[5] for r in rows]


# --------------------------------------------------------------------------
# The clean case
# --------------------------------------------------------------------------

def test_a_clean_run_loses_nothing(fake_clock):
    sensor = FakeSensor(grid_events(PERIOD, 60))
    rows, stats = run_loop(sensor, fake_clock, duration=0.5)

    assert stats["missed"] == 0
    assert stats["ambiguous"] == 0
    assert all(f == "" for f in flags(rows))
    assert len(rows) > 40


def test_the_sample_index_is_contiguous_from_zero(fake_clock):
    sensor = FakeSensor(grid_events(PERIOD, 60))
    rows, _ = run_loop(sensor, fake_clock, duration=0.5)
    assert indices(rows) == list(range(len(rows)))


def test_every_measurement_is_read_exactly_once(fake_clock):
    """No duplicates: DRC1 clears DRDY on the results read, so a re-read cannot
    return the same measurement -- and the loop must not ask for one."""
    sensor = FakeSensor(grid_events(PERIOD, 60))
    rows, _ = run_loop(sensor, fake_clock, duration=0.5)
    x_values = [r[2] for r in rows]
    assert len(set(x_values)) == len(x_values)
    assert x_values == sorted(x_values)          # grid_events counts upward


def test_the_timestamp_is_the_bracket_midpoint(fake_clock):
    """Not the read time: the measurement completed somewhere in the bracket."""
    sensor = FakeSensor(grid_events(PERIOD, 40))
    rows, _ = run_loop(sensor, fake_clock, duration=0.3)
    times = [r[1] for r in rows]
    gaps = [b - a for a, b in zip(times, times[1:])]
    # Resolved only to the poll interval, which is what a real bracket gives too.
    assert all(g == pytest.approx(PERIOD, abs=1e-3) for g in gaps)


def test_the_worst_bracket_is_recorded(fake_clock):
    sensor = FakeSensor(grid_events(PERIOD, 40))
    _, stats = run_loop(sensor, fake_clock, duration=0.3)
    # No stall, so the bracket is one poll interval and nowhere near a period.
    assert 0 < stats["max_bracket"] < PERIOD / 2


def test_a_stale_drdy_at_start_is_discarded(fake_clock):
    """BIST leaves DRDY high over zeroed registers; sample 0 must be fresh."""
    sensor = FakeSensor(grid_events(PERIOD, 40, start=0.0, counts=(0, 0, 0)))
    sensor.pending = (0, 0, 0)          # as if left set by whatever ran before
    rows, _ = run_loop(sensor, fake_clock, duration=0.2)
    assert rows
    assert rows[0][2:5] != (0, 0, 0) or sensor.reads[0] == (0, 0, 0)
    # The discard happened: one more read than rows written.
    assert len(sensor.reads) == len(rows) + 1


def test_duration_zero_keeps_running(fake_clock):
    """0 means 'until Ctrl-C', so the deadline must be infinite, not immediate.

    Nothing inside the loop ends it, so the sensor is what stops the test --
    which is also the proof that the loop was still going.
    """
    sensor = FakeSensor(grid_events(PERIOD, 200), max_polls=2000)
    fake_clock(sensor)
    q = queue.Queue()
    stats = {"rows": 0, "missed": 0, "ambiguous": 0, "max_bracket": 0.0,
             "truncated": False}
    with pytest.raises(FakeSensor.Exhausted):
        logger.sample_loop(sensor, q, 0.0, PERIOD, stats)
    # It kept sampling until the sensor gave out, rather than returning at once.
    assert q.qsize() >= 50


# --------------------------------------------------------------------------
# Losing measurements
# --------------------------------------------------------------------------

def test_a_two_period_stall_records_one_placeholder(fake_clock):
    """Two completions inside one bracket: one was read, one was lost."""
    sensor = FakeSensor(grid_events(PERIOD, 60), stalls=[(0.2, 2.1 * PERIOD)])
    rows, stats = run_loop(sensor, fake_clock, duration=0.5)

    assert stats["missed"] == 1
    assert stats["ambiguous"] == 0
    placeholders = [r for r in rows if logger.WARN_MISSED in r[5]]
    assert len(placeholders) == 1
    # A placeholder carries no data and keeps the index contiguous.
    assert placeholders[0][2:5] == (None, None, None)
    assert indices(rows) == list(range(len(rows)))


def test_a_longer_stall_records_every_lost_grid_point(fake_clock):
    sensor = FakeSensor(grid_events(PERIOD, 80), stalls=[(0.2, 4.1 * PERIOD)])
    rows, stats = run_loop(sensor, fake_clock, duration=0.7)

    assert stats["missed"] == 3
    assert sum(logger.WARN_MISSED in r[5] for r in rows) == 3
    assert indices(rows) == list(range(len(rows)))


def test_placeholders_sit_on_the_grid_not_bunched_at_the_end(fake_clock):
    """They mark where the lost measurements actually completed."""
    sensor = FakeSensor(grid_events(PERIOD, 80), stalls=[(0.2, 4.1 * PERIOD)])
    rows, _ = run_loop(sensor, fake_clock, duration=0.7)
    lost = [r for r in rows if logger.WARN_MISSED in r[5]]
    gaps = [b[1] - a[1] for a, b in zip(lost, lost[1:])]
    assert all(g == pytest.approx(PERIOD, rel=0.05) for g in gaps)


def test_a_late_read_within_one_period_is_not_a_miss(fake_clock):
    """The case that motivated the bracket: a host stall that lost nothing.

    An interval-based estimator would insert a spurious placeholder here and
    slip the index for the rest of the run.
    """
    sensor = FakeSensor(grid_events(PERIOD, 60), stalls=[(0.2, 1.1 * PERIOD)])
    rows, stats = run_loop(sensor, fake_clock, duration=0.5)

    assert stats["missed"] == 0
    assert all(logger.WARN_MISSED not in f for f in flags(rows))


def test_the_stall_shows_up_in_the_worst_bracket(fake_clock):
    """Losing nothing is not the same as having had margin."""
    sensor = FakeSensor(grid_events(PERIOD, 60), stalls=[(0.2, 1.1 * PERIOD)])
    _, stats = run_loop(sensor, fake_clock, duration=0.5)
    assert stats["max_bracket"] > 0.7 * PERIOD


# --------------------------------------------------------------------------
# Ambiguity
# --------------------------------------------------------------------------

def test_a_gap_near_a_half_period_is_flagged_ambiguous(fake_clock):
    """1.35 periods rounds to one, so no placeholder -- but it is a guess."""
    sensor = FakeSensor(grid_events(PERIOD, 60), stalls=[(0.2, 1.35 * PERIOD)])
    rows, stats = run_loop(sensor, fake_clock, duration=0.5)

    assert stats["ambiguous"] == 1
    assert stats["missed"] == 0
    flagged = [r for r in rows if logger.WARN_AMBIGUOUS in r[5]]
    assert len(flagged) == 1
    # It rides on the real sample ending the gap, which keeps its data.
    assert flagged[0][2] is not None
    assert logger.WARN_MISSED not in flagged[0][5]


def test_an_ambiguous_gap_that_did_lose_something_flags_both(fake_clock):
    sensor = FakeSensor(grid_events(PERIOD, 60), stalls=[(0.2, 2.5 * PERIOD)])
    rows, stats = run_loop(sensor, fake_clock, duration=0.5)

    assert stats["ambiguous"] == 1
    assert stats["missed"] == 2
    placeholders = [r for r in rows if logger.WARN_MISSED in r[5]]
    assert placeholders
    assert all(logger.WARN_AMBIGUOUS in r[5] for r in placeholders)


def test_a_gap_landing_squarely_on_a_period_is_not_ambiguous(fake_clock):
    sensor = FakeSensor(grid_events(PERIOD, 60), stalls=[(0.2, 2.02 * PERIOD)])
    _, stats = run_loop(sensor, fake_clock, duration=0.5)
    assert stats["ambiguous"] == 0
    assert stats["missed"] == 1


def test_the_ambiguity_margin_is_the_documented_quarter_period():
    assert logger.AMBIGUITY_MARGIN == 0.25


# --------------------------------------------------------------------------
# Backpressure
# --------------------------------------------------------------------------

def test_a_full_queue_truncates_rather_than_holing_the_index(fake_clock):
    """A dropped row would break contiguity and make the file unloadable."""
    sensor = FakeSensor(grid_events(PERIOD, 200))
    rows, stats = run_loop(sensor, fake_clock, duration=1.5, maxsize=8)

    assert stats["truncated"] is True
    assert len(rows) == 8
    assert indices(rows) == list(range(8))


def test_an_ample_queue_never_truncates(fake_clock):
    sensor = FakeSensor(grid_events(PERIOD, 60))
    _, stats = run_loop(sensor, fake_clock, duration=0.5, maxsize=10_000)
    assert stats["truncated"] is False


# --------------------------------------------------------------------------
# calibrate_period
# --------------------------------------------------------------------------

def test_calibrate_period_recovers_the_true_period(fake_clock):
    """The nominal value is 6-9% out on real hardware; the fit has to beat that."""
    sensor = FakeSensor(grid_events(PERIOD, 400))
    fake_clock(sensor)
    dt, host_cost = logger.calibrate_period(sensor, PERIOD * 1.07, seconds=1.0)
    assert dt == pytest.approx(PERIOD, rel=1e-3)
    assert host_cost > 0


def test_calibrate_period_bootstraps_when_the_nominal_is_badly_wrong(fake_clock):
    """When the cycle count governs, the TMRC table value is out by a factor.

    A threshold built on it rejects every interval, so the period is seeded from
    observation instead.
    """
    sensor = FakeSensor(grid_events(PERIOD, 400))
    fake_clock(sensor)
    dt, _ = logger.calibrate_period(sensor, PERIOD / 8, seconds=1.0)
    assert dt == pytest.approx(PERIOD, rel=1e-3)


def test_calibrate_period_reports_a_plausible_host_cost(fake_clock):
    sensor = FakeSensor(grid_events(PERIOD, 400))
    fake_clock(sensor)
    _, host_cost = logger.calibrate_period(sensor, PERIOD, seconds=1.0)
    # One poll plus one read, and nothing else charged to the sample.
    assert host_cost == pytest.approx(
        sensor.poll_cost + sensor.read_cost, rel=0.5)
    assert host_cost < PERIOD


def test_calibrate_period_gives_up_without_enough_clean_samples(fake_clock):
    """Returning None is itself the answer: the rate is not sustainable."""
    sensor = FakeSensor(grid_events(PERIOD, 4))
    fake_clock(sensor)
    assert logger.calibrate_period(sensor, PERIOD, seconds=0.5) == (None, None)


# --------------------------------------------------------------------------
# End to end: sample_loop -> writer_thread -> capture.load
# --------------------------------------------------------------------------

def test_a_logged_run_reloads_through_capture(tmp_path, fake_clock):
    """The two halves of the format contract, checked against each other."""
    sensor = FakeSensor(grid_events(PERIOD, 400), stalls=[(0.5, 2.1 * PERIOD)])
    fake_clock(sensor)
    q = queue.Queue()
    stats = {"rows": 0, "missed": 0, "ambiguous": 0, "max_bracket": 0.0,
             "truncated": False}
    logger.sample_loop(sensor, q, 2.0, PERIOD, stats)
    q.put(logger._SENTINEL)

    path = tmp_path / "run.csv"
    meta = {
        "rm3100_capture": 1,
        "nominal_rate_hz": 1 / PERIOD,
        "cycle_count": 100,
        "tesla_per_count": repr(rm3100.tesla_per_count(100)),
        "calibrated_period_s": repr(PERIOD),
        "note": "synthetic",
    }
    logger.writer_thread(q, str(path), meta, stats)

    cap = capture.load(str(path))
    assert len(cap.sample_index) == stats["rows"]
    assert cap.missed.sum() == stats["missed"] == 1
    assert cap.meta["note"] == "synthetic"
    assert cap.true_rate_hz == pytest.approx(1 / PERIOD, rel=1e-3)


def test_the_writer_writes_zeros_not_blanks_for_a_placeholder(tmp_path):
    """x/y/z must parse as integers on every row; the flag marks the empty ones."""
    q = queue.Queue()
    q.put((0, 1_700_000_000.0, 10, 20, 30, ""))
    q.put((1, 1_700_000_000.01, None, None, None, logger.WARN_MISSED))
    q.put(logger._SENTINEL)
    stats = {"rows": 0, "missed": 1}

    path = tmp_path / "w.csv"
    logger.writer_thread(q, str(path), {
        "rm3100_capture": 1,
        "tesla_per_count": repr(rm3100.tesla_per_count(100))}, stats)

    lines = path.read_text().splitlines()
    assert lines[-1] == f"1,1700000000.010000,0,0,0,{logger.WARN_MISSED}"
    assert stats["rows"] == 2


def test_the_header_is_one_line_per_key(tmp_path):
    handle_path = tmp_path / "h.csv"
    with open(handle_path, "w") as handle:
        logger.write_header(handle, {"a": 1, "b": "two"})
    assert handle_path.read_text() == "# a: 1\n# b: two\n"


# --------------------------------------------------------------------------
# Configuration warnings -- each one guards against a silent capture defect
# --------------------------------------------------------------------------

def warnings_for(capsys, cfg, bus_speed=750, requested_rate=None):
    logger.print_plan(cfg, bus_speed, requested_rate)
    return capsys.readouterr().err


def test_the_default_configuration_warns_about_nothing(capsys):
    assert warnings_for(capsys, rm3100.plan()) == ""


def test_a_thin_dither_margin_is_warned_about(capsys):
    err = warnings_for(capsys, rm3100.plan(cycle_count=40))
    assert "below the recommended" in err
    assert "characterize.py" in err          # and says how to settle it


def test_an_idling_sensor_is_warned_about(capsys):
    err = warnings_for(capsys, rm3100.plan(cycle_count=50, tmrc=0x99))
    assert "idle" in err


def test_a_rate_that_could_not_be_met_is_warned_about(capsys):
    err = warnings_for(capsys, rm3100.plan(rate_hz=5000), requested_rate=5000)
    assert "was requested but this configuration runs" in err


def test_sampling_below_twice_mains_is_warned_about(capsys):
    """The one error post-processing cannot undo."""
    err = warnings_for(capsys, rm3100.plan(rate_hz=32), requested_rate=32)
    assert "Nyquist" in err and "mains" in err
    assert "4.0" in err                      # 60 Hz folds to ~4 Hz at 32 Hz


def test_an_extrapolated_cycle_count_is_warned_about(capsys):
    err = warnings_for(capsys, rm3100.plan(cycle_count=1000))
    assert "extrapolated" in err
    assert str(rm3100.MAX_SPEC_CYCLE_COUNT) in err


def test_a_bus_that_cannot_keep_up_is_warned_about_with_a_fix(capsys):
    err = warnings_for(capsys, rm3100.plan(), bus_speed=20)
    assert "of every period" in err
    assert "kHz would fit" in err


def test_the_plan_derivation_is_printed_for_checking(capsys):
    logger.print_plan(rm3100.plan(), 750, None)
    out = capsys.readouterr().out
    for field in ("cycle count", "sensor ceiling", "TMRC", "predicted rate",
                  "resolution", "duty", "bus 750 kHz"):
        assert field in out


def test_the_requested_rate_is_echoed_when_given(capsys):
    logger.print_plan(rm3100.plan(rate_hz=50), 750, 50)
    assert "requested" in capsys.readouterr().out


# --------------------------------------------------------------------------
# Small helpers
# --------------------------------------------------------------------------

def test_set_thread_nice_reports_what_took_effect():
    """Lowering own priority needs no privilege, so this must work anywhere."""
    got = logger.set_thread_nice(logger.WRITER_NICE)
    assert got in (logger.WRITER_NICE, None)


def test_raising_priority_without_privilege_returns_none():
    if logger.set_thread_nice(0) is None:
        pytest.skip("thread priority is unavailable on this platform")
    import os
    if os.geteuid() == 0:
        pytest.skip("running as root, where the raise succeeds")
    assert logger.set_thread_nice(logger.SAMPLER_NICE) is None


def test_restore_ownership_is_a_no_op_for_a_normal_user(tmp_path):
    path = tmp_path / "f.csv"
    path.write_text("x")
    logger.restore_ownership(str(path))      # must not raise
    assert path.read_text() == "x"