diff --git a/framework_tests/test_log_analyzer.py b/framework_tests/test_log_analyzer.py new file mode 100644 index 00000000..bfbbdc27 --- /dev/null +++ b/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 == [] diff --git a/framework_tests/test_metrics_extractor_dbsync.py b/framework_tests/test_metrics_extractor_dbsync.py new file mode 100644 index 00000000..c0d7d9f4 --- /dev/null +++ b/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": {}} diff --git a/framework_tests/test_metrics_extractor_node.py b/framework_tests/test_metrics_extractor_node.py new file mode 100644 index 00000000..7a63740c --- /dev/null +++ b/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 diff --git a/framework_tests/test_sync_static_graphs.py b/framework_tests/test_sync_static_graphs.py new file mode 100644 index 00000000..d1dc3d52 --- /dev/null +++ b/framework_tests/test_sync_static_graphs.py @@ -0,0 +1,157 @@ +"""Tests for sync_tests.scripts.sync_static_graphs.""" + +from __future__ import annotations + +import json +import pathlib as pl + +from sync_tests.scripts.sync_static_graphs import detect_json_mode +from sync_tests.scripts.sync_static_graphs import generate_static_graphs +from sync_tests.scripts.sync_static_graphs import normalize_dbsync_data + + +class TestDetectJsonMode: + def test_list_is_dbsync(self) -> None: + assert detect_json_mode([{"time": 0, "rss_mem_usage": 1}]) == "dbsync" + + def test_dict_with_system_metrics_list_and_epoch_timings_is_dbsync(self) -> None: + data = {"system_metrics": [{"time": 0}], "epoch_timings": {}} + assert detect_json_mode(data) == "dbsync" + + def test_dict_with_log_values_is_node(self) -> None: + data = {"log_values": {"2026-01-01T00:00:00": {"tip": 1}}} + assert detect_json_mode(data) == "node" + + def test_dict_with_block_insertion_rates_fallback_is_dbsync(self) -> None: + assert detect_json_mode({"block_insertion_rates": []}) == "dbsync" + + def test_dict_with_total_sync_time_fallback_is_dbsync(self) -> None: + assert detect_json_mode({"total_sync_time_in_sec": 100}) == "dbsync" + + def test_unrecognized_dict_defaults_to_node(self) -> None: + assert detect_json_mode({"some_other_key": 1}) == "node" + + +class TestNormalizeDbsyncData: + def test_list_input_becomes_system_metrics(self) -> None: + data = [{"time": 0, "rss_mem_usage": 100}] + result = normalize_dbsync_data(data) + assert result["system_metrics"] == data + assert result["epoch_timings"] == {} + assert result["block_insertion_rates"] == [] + assert result["epoch_details"] == {} + + def test_system_metrics_dict_converted_to_list(self) -> None: + data = {"system_metrics": {"a": {"time": 0}, "b": {"time": 1}}} + result = normalize_dbsync_data(data) + assert result["system_metrics"] == [{"time": 0}, {"time": 1}] + + def test_epoch_timings_keeps_entries_with_valid_duration_or_blocks(self) -> None: + data = { + "epoch_timings": { + "1": {"duration_sec": 120, "blocks_count": 0}, + "2": {"duration_sec": None, "blocks_count": 5}, + "3": {"duration_sec": 0, "blocks_count": 0}, + "not-a-number": {"duration_sec": 120, "blocks_count": 1}, + } + } + result = normalize_dbsync_data(data) + # Epoch 3 has duration_sec=0 (not a valid duration) but is kept anyway: + # has_valid_blocks treats any blocks_count >= 0, including 0, as valid. + assert set(result["epoch_timings"].keys()) == {1, 2, 3} + assert result["epoch_timings"][1]["duration_sec"] == 120 + + def test_epoch_timings_drops_non_integer_keys(self) -> None: + data = {"epoch_timings": {"abc": {"duration_sec": 100, "blocks_count": 1}}} + result = normalize_dbsync_data(data) + assert result["epoch_timings"] == {} + + def test_block_insertion_rates_filters_non_increasing_blocks(self) -> None: + data = { + "block_insertion_rates": [ + {"block": 100, "time": 0}, + {"block": 101, "time": 1}, + {"block": 101, "time": 2}, # not strictly increasing, dropped + {"block": 99, "time": 3}, # goes backwards, dropped + {"block": 200, "time": 4}, + ] + } + result = normalize_dbsync_data(data) + assert [entry["block"] for entry in result["block_insertion_rates"]] == [100, 101, 200] + + def test_epoch_details_defaults_to_empty_dict_when_not_a_dict(self) -> None: + result = normalize_dbsync_data({"epoch_details": "not-a-dict"}) + assert result["epoch_details"] == {} + + +def test_generate_static_graphs_dbsync_mode_produces_pngs(tmp_path: pl.Path) -> None: + results = { + "system_metrics": [ + {"time": 0, "rss_mem_usage": 1_000_000, "cpu_percent_usage": 10}, + {"time": 60, "rss_mem_usage": 1_100_000, "cpu_percent_usage": 15}, + ], + "epoch_timings": { + "1": {"start_time": None, "end_time": None, "duration_sec": 120, "blocks_count": 5}, + }, + "block_insertion_rates": [], + "epoch_details": {}, + } + results_file = tmp_path / "db_sync_preview_results.json" + results_file.write_text(json.dumps(results), encoding="utf-8") + output_dir = tmp_path / "graphs" + + generate_static_graphs( + file_list=[str(results_file)], + output_dir=str(output_dir), + dpi=50, + fmt="png", + mode="dbsync", + ) + + produced = {p.name for p in output_dir.glob("*.png")} + assert produced, "expected at least one PNG to be generated" + assert all(p.stat().st_size > 0 for p in output_dir.glob("*.png")) + + +def test_generate_static_graphs_node_mode_produces_pngs(tmp_path: pl.Path) -> None: + results = { + "env": "preview", + "tag_no1": "11.0.1", + "log_values": { + "2026-01-01T10:00:00+00:00": { + "tip": 100, + "heap_ram": 1000.0, + "rss_ram": 2000.0, + "cpu": 10.0, + }, + "2026-01-01T10:01:00+00:00": { + "tip": 200, + "heap_ram": 1100.0, + "rss_ram": 2100.0, + "cpu": 12.0, + }, + "2026-01-01T10:02:00+00:00": { + "tip": 300, + "heap_ram": 1200.0, + "rss_ram": 2200.0, + "cpu": 11.0, + }, + }, + "sync_duration_per_epoch": {"0": 60, "1": 55}, + "eras_in_test": ["shelley"], + } + results_file = tmp_path / "node_sync_preview_results.json" + results_file.write_text(json.dumps(results), encoding="utf-8") + output_dir = tmp_path / "graphs" + + generate_static_graphs( + file_list=[str(results_file)], + output_dir=str(output_dir), + dpi=50, + fmt="png", + mode="node", + ) + + produced = {p.name for p in output_dir.glob("*.png")} + assert produced, "expected at least one PNG to be generated" + assert all(p.stat().st_size > 0 for p in output_dir.glob("*.png"))