Add tests for log parsing and graph generation

framework_tests/test_log_analyzer.py

@@ -0,0 +1,91 @@
+"""Tests for sync_tests.utils.logs.log_analyzer."""
+
+from __future__ import annotations
+
+import logging
+import pathlib as pl
+
+import pytest
+
+from sync_tests.utils.logs import log_analyzer
+
+
+def _write(tmp_path: pl.Path, name: str, content: str) -> pl.Path:
+    log_file = tmp_path / name
+    log_file.write_text(content, encoding="utf-8")
+    return log_file
+
+
+def test_is_string_present_in_file_finds_match(tmp_path: pl.Path) -> None:
+    log_file = _write(tmp_path, "a.log", "line one\nline two: db-sync-node:Error boom\n")
+    assert log_analyzer.is_string_present_in_file(log_file, "db-sync-node:Error") is True
+
+
+def test_is_string_present_in_file_no_match(tmp_path: pl.Path) -> None:
+    log_file = _write(tmp_path, "a.log", "line one\nline two\n")
+    assert log_analyzer.is_string_present_in_file(log_file, "db-sync-node:Error") is False
+
+
+def test_is_string_present_in_file_treats_search_string_literally(tmp_path: pl.Path) -> None:
+    """Regex metacharacters in the search string must not be interpreted as a pattern."""
+    log_file = _write(tmp_path, "a.log", "cost 3.14 not 3x14\n")
+    # "3.14" as a regex would also match "3x14"; as a literal string it must not.
+    assert log_analyzer.is_string_present_in_file(log_file, "3.14") is True
+    no_match_file = _write(tmp_path, "b.log", "3x14\n")
+    assert log_analyzer.is_string_present_in_file(no_match_file, "3.14") is False
+
+
+def test_are_rollbacks_present_no_occurrences(tmp_path: pl.Path) -> None:
+    log_file = _write(tmp_path, "a.log", "nothing interesting here\n")
+    assert log_analyzer.are_rollbacks_present_in_logs(log_file) is False
+
+
+def test_are_rollbacks_present_single_occurrence(tmp_path: pl.Path) -> None:
+    """Documents current behavior: a single "rolling" mention is not reported as a rollback.
+
+    are_rollbacks_present_in_logs() only returns True once "rolling" is found a second
+    time, so exactly one rollback-looking line in the log is treated the same as zero.
+    """
+    log_file = _write(tmp_path, "a.log", "rolling back to slot 123\nall good after that\n")
+    assert log_analyzer.are_rollbacks_present_in_logs(log_file) is False
+
+
+def test_are_rollbacks_present_two_occurrences(tmp_path: pl.Path) -> None:
+    log_file = _write(
+        tmp_path,
+        "a.log",
+        "rolling back to slot 123\nsome other line\nrolling back to slot 456\n",
+    )
+    assert log_analyzer.are_rollbacks_present_in_logs(log_file) is True
+
+
+def test_check_db_sync_logs_warns_on_each_condition(
+    tmp_path: pl.Path, caplog: pytest.LogCaptureFixture
+) -> None:
+    log_file = _write(
+        tmp_path,
+        "db_sync.log",
+        "db-sync-node:Error something broke\n"
+        "Rollback failed badly\n"
+        "Failed to parse ledger state\n"
+        "rolling back to slot 1\n"
+        "rolling back to slot 2\n",
+    )
+    with caplog.at_level(logging.WARNING):
+        log_analyzer.check_db_sync_logs(log_file=log_file)
+
+    messages = " ".join(caplog.messages)
+    assert "Errors present" in messages
+    assert "Rollbacks present" in messages
+    assert "Failed rollbacks present" in messages
+    assert "Corrupted ledger files present" in messages
+
+
+def test_check_db_sync_logs_silent_on_clean_log(
+    tmp_path: pl.Path, caplog: pytest.LogCaptureFixture
+) -> None:
+    log_file = _write(tmp_path, "db_sync.log", "Inserted 5 EpochStake for EpochNo 10\n")
+    with caplog.at_level(logging.WARNING):
+        log_analyzer.check_db_sync_logs(log_file=log_file)
+
+    assert caplog.messages == []

framework_tests/test_metrics_extractor_dbsync.py

@@ -0,0 +1,73 @@
+"""Tests for sync_tests.utils.db_sync.metrics_extractor (db-sync log parsing)."""
+
+from __future__ import annotations
+
+import pathlib as pl
+
+import pytest
+
+from sync_tests.utils.db_sync import metrics_extractor
+
+
+@pytest.mark.parametrize(
+    ("time_str", "expected"),
+    [
+        ("00:00:01.30", 1.3),
+        ("01:02:03", 3723.0),
+        ("00:00:00.00", 0.0),
+        ("00:01:00.50", 60.5),
+    ],
+)
+def test_parse_time_duration_valid(time_str: str, expected: float) -> None:
+    assert metrics_extractor._parse_time_duration(time_str) == expected
+
+
+def test_parse_time_duration_malformed_returns_zero() -> None:
+    assert metrics_extractor._parse_time_duration("not-a-duration") == 0.0
+
+
+def test_get_db_sync_data_from_logs_full_epoch_cycle(tmp_path: pl.Path) -> None:
+    log_file = tmp_path / "db_sync.log"
+    log_file.write_text(
+        "[2026-01-01 10:00:00.00 UTC] Starting epoch 5\n"
+        "[2026-01-01 10:00:01.00 UTC] Insert Babbage Block: epoch 5, slot 1000, block 100\n"
+        "[2026-01-01 10:00:02.00 UTC] Insert Babbage Block: epoch 5, slot 1001, block 101\n"
+        "[2026-01-01 10:00:03.00 UTC] Statistics for Epoch 5\n"
+        "[2026-01-01 10:00:03.00 UTC] This epoch took: 00:00:03.00 to process.\n"
+        "[2026-01-01 10:00:04.00 UTC] Inserted epoch 5 from updateEpochWhenSyncing\n",
+        encoding="utf-8",
+    )
+
+    result = metrics_extractor.get_db_sync_data_from_logs(log_file)
+
+    assert len(result["block_insertions"]) == 2
+    first, second = result["block_insertions"]
+    assert first == {
+        "timestamp": "2026-01-01T10:00:01+00:00",
+        "epoch": 5,
+        "slot": 1000,
+        "block": 100,
+        "era": "Babbage",
+    }
+    assert second["slot"] == 1001
+    assert second["block"] == 101
+
+    assert set(result["epoch_timings"].keys()) == {5}
+    timing = result["epoch_timings"][5]
+    assert timing["start_time"] == "2026-01-01T10:00:00+00:00"
+    assert timing["end_time"] == "2026-01-01T10:00:03+00:00"
+    assert timing["duration_sec"] == 3.0
+    assert timing["blocks_count"] == 2
+
+    # epoch_details is finalized from epoch_timings at the end of the function.
+    assert result["epoch_details"][5]["duration_sec"] == 3.0
+    assert result["epoch_details"][5]["blocks_count"] == 2
+
+
+def test_get_db_sync_data_from_logs_empty_file(tmp_path: pl.Path) -> None:
+    log_file = tmp_path / "db_sync.log"
+    log_file.write_text("nothing relevant here\n", encoding="utf-8")
+
+    result = metrics_extractor.get_db_sync_data_from_logs(log_file)
+
+    assert result == {"epoch_timings": {}, "block_insertions": [], "epoch_details": {}}

framework_tests/test_metrics_extractor_node.py

@@ -0,0 +1,80 @@
+"""Tests for sync_tests.utils.logs.metrics_extractor (node log parsing)."""
+
+from __future__ import annotations
+
+import pathlib as pl
+
+from sync_tests.utils.logs import metrics_extractor
+
+
+def test_merge_sorted_unique_dedupes_across_already_sorted_inputs() -> None:
+    """merge_sorted_unique wraps heapq.merge, which requires each input pre-sorted."""
+    result = metrics_extractor.merge_sorted_unique([1, 2, 3], [2, 4], [1])
+    assert result == [1, 2, 3, 4]
+
+
+def test_get_data_from_logs_empty_file(tmp_path: pl.Path) -> None:
+    log_file = tmp_path / "node.log"
+    log_file.write_text("nothing relevant here\n", encoding="utf-8")
+
+    assert metrics_extractor.get_data_from_logs(log_file) == {}
+
+
+def test_get_data_from_logs_json_style_resources(tmp_path: pl.Path) -> None:
+    """CentiCpu-style (JSON tracer) resource lines, tip carried forward between samples."""
+    log_file = tmp_path / "node.log"
+    log_file.write_text(
+        "2026-01-01 10:00:00 cardano.node.resources trace: "
+        '"Heap",Number 1000.0 "RSS",Number 2000.0 "CentiCpu",Number 500.0\n'
+        "[2026-01-01 10:00:05.00 UTC] node ChainDB new tip 0xabc at slot 100\n"
+        "2026-01-01 10:00:10 cardano.node.resources trace: "
+        '"Heap",Number 1100.0 "RSS",Number 2100.0 "CentiCpu",Number 600.0\n'
+        "[2026-01-01 10:00:15.00 UTC] node ChainDB new tip 0xdef at slot 200\n",
+        encoding="utf-8",
+    )
+
+    result = metrics_extractor.get_data_from_logs(log_file)
+
+    # Samples before the first CPU delta (10:00:00) or before any CPU sample exists
+    # yet (10:00:05) are dropped; only timestamps with a resolvable CPU value remain.
+    assert set(result.keys()) == {
+        "2026-01-01 10:00:10+00:00",
+        "2026-01-01 10:00:15+00:00",
+    }
+    at_10 = result["2026-01-01 10:00:10+00:00"]
+    assert at_10["tip"] == 100
+    assert at_10["heap_ram"] == 1100.0
+    assert at_10["rss_ram"] == 2100.0
+    # (600 - 500) CentiCpu over 10s, multiplier 1.0 for CentiCpu source.
+    assert at_10["cpu"] == 10.0
+
+    at_15 = result["2026-01-01 10:00:15+00:00"]
+    assert at_15["tip"] == 200
+    # No resource sample exactly at 10:00:15, RSS/heap default to 0.0.
+    assert at_15["heap_ram"] == 0.0
+    assert at_15["rss_ram"] == 0.0
+    # CPU carried forward from the last known sample (10:00:10).
+    assert at_15["cpu"] == 10.0
+
+
+def test_get_data_from_logs_human_readable_resources(tmp_path: pl.Path) -> None:
+    """Cpu Ticks-style (human tracer) resource lines use a x100 multiplier."""
+    log_file = tmp_path / "node.log"
+    log_file.write_text(
+        "[2026-01-01 10:00:00.00 UTC] node Resources: Cpu Ticks 1000, "
+        "GC centiseconds 5, Mutator centiseconds 300, RTS heap 5000, RSS 6000, extra info\n"
+        "[2026-01-01 10:00:05.00 UTC] node ChainDB new tip 0xabc at slot 50\n"
+        "[2026-01-01 10:00:10.00 UTC] node Resources: Cpu Ticks 1050, "
+        "GC centiseconds 6, Mutator centiseconds 310, RTS heap 5100, RSS 6100, extra info\n",
+        encoding="utf-8",
+    )
+
+    result = metrics_extractor.get_data_from_logs(log_file)
+
+    assert set(result.keys()) == {"2026-01-01 10:00:10+00:00"}
+    entry = result["2026-01-01 10:00:10+00:00"]
+    assert entry["tip"] == 50
+    assert entry["heap_ram"] == 5100.0
+    assert entry["rss_ram"] == 6100.0
+    # (1050 - 1000) ticks over 10s, x100 multiplier for the ticks source.
+    assert entry["cpu"] == 500.0