Merge pull request #2799 from IntersectMBO/check_blocks_in_logs

Check blocks minting in logs

.reponotes

@@ -0,0 +1 @@
+../reponotes/cardano-node-tests

cardano_node_tests/tests/test_blocks.py

@@ -26,6 +26,7 @@
 from cardano_node_tests.utils import configuration
 from cardano_node_tests.utils import dbsync_queries
 from cardano_node_tests.utils import helpers
+from cardano_node_tests.utils import logfiles
 from cardano_node_tests.utils.versions import VERSIONS
 
 LOGGER = logging.getLogger(__name__)
@@ -35,7 +36,7 @@ class TestLeadershipSchedule:
     """Tests for cardano-cli leadership-schedule."""
 
     @allure.link(helpers.get_vcs_link())
-    @pytest.mark.needs_dbsync
+    @pytest.mark.dbsync
     @pytest.mark.parametrize("for_epoch", ("current", "next"))
     def test_pool_blocks(
         self,
@@ -47,9 +48,12 @@ def test_pool_blocks(
 
         * query leadership schedule for selected pool for current epoch or next epoch
         * wait for epoch that comes after the queried epoch
-        * get info about minted blocks in queried epoch for the selected pool
-        * compare leadership schedule with blocks that were actually minted
-        * compare db-sync records with ledger state dump
+        * check in log files that the blocks were minted in expected slots
+        * if db-sync is available:
+
+           - get info about minted blocks in queried epoch for the selected pool
+           - compare leadership schedule with blocks that were actually minted
+           - compare db-sync records with ledger state dump
         """
         # pylint: disable=unused-argument
         cluster, pool_name = cluster_use_pool
@@ -58,12 +62,18 @@ def test_pool_blocks(
         pool_rec = cluster_manager.cache.addrs_data[pool_name]
         pool_id = cluster.g_stake_pool.get_stake_pool_id(pool_rec["cold_key_pair"].vkey_file)
 
+        state_dir = cluster_nodes.get_cluster_env().state_dir
+        pool_log_fname = f"{pool_name.replace('node-', '')}.stdout"
+        pool_log = state_dir / pool_log_fname
+        seek_offsets = {str(pool_log): helpers.get_eof_offset(pool_log)}
+        timestamp = time.time()
+
         if for_epoch == "current":
-            # wait for beginning of an epoch
+            # Wait for beginning of an epoch
             queried_epoch = cluster.wait_for_new_epoch(padding_seconds=5)
         else:
-            # wait for stable stake distribution for next epoch, that is last 300 slots of
-            # current epoch
+            # Wait for stable stake distribution for next epoch, that is last 300 slots of
+            # current epoch.
             clusterlib_utils.wait_for_epoch_interval(
                 cluster_obj=cluster,
                 start=-int(300 * cluster.slot_length),
@@ -72,55 +82,70 @@ def test_pool_blocks(
             )
             queried_epoch = cluster.g_query.get_epoch() + 1
 
-        # query leadership schedule for selected pool
+        # Query leadership schedule for selected pool
         leadership_schedule = cluster.g_query.get_leadership_schedule(
             vrf_skey_file=pool_rec["vrf_key_pair"].skey_file,
             cold_vkey_file=pool_rec["cold_key_pair"].vkey_file,
             for_next=for_epoch != "current",
         )
+        slots_when_scheduled = {r.slot_no for r in leadership_schedule}
 
-        # wait for epoch that comes after the queried epoch
-        cluster.wait_for_epoch(epoch_no=queried_epoch + 1)
+        expected_msgs = [
+            (pool_log_fname, rf'TraceForgedBlock"\),\("slot",Number {s}')
+            for s in slots_when_scheduled
+        ]
 
-        # get info about minted blocks in queried epoch for the selected pool
-        minted_blocks = list(
-            dbsync_queries.query_blocks(
-                pool_id_bech32=pool_id, epoch_from=queried_epoch, epoch_to=queried_epoch
-            )
-        )
-        slots_when_minted = {r.slot_no for r in minted_blocks}
+        # Wait for epoch that comes after the queried epoch
+        cluster.wait_for_epoch(epoch_no=queried_epoch + 1)
 
         errors: tp.List[str] = []
 
-        # compare leadership schedule with blocks that were actually minted
-        slots_when_scheduled = {r.slot_no for r in leadership_schedule}
-
-        difference_scheduled = slots_when_minted.difference(slots_when_scheduled)
-        if difference_scheduled:
-            errors.append(
-                f"Some blocks were minted in other slots than scheduled: {difference_scheduled}"
+        log_msgs_errors = logfiles.check_msgs_presence_in_logs(
+            regex_pairs=expected_msgs,
+            seek_offsets=seek_offsets,
+            state_dir=state_dir,
+            timestamp=timestamp,
+        )
+        if len(log_msgs_errors) > len(leadership_schedule) // 2:
+            log_msgs_errors_joined = "\n  ".join(log_msgs_errors)
+            errors.append(f"Lot of slots missed: \n  {log_msgs_errors_joined}")
+
+        if configuration.HAS_DBSYNC:
+            # Get info about minted blocks in queried epoch for the selected pool
+            minted_blocks = list(
+                dbsync_queries.query_blocks(
+                    pool_id_bech32=pool_id, epoch_from=queried_epoch, epoch_to=queried_epoch
+                )
             )
+            slots_when_minted = {r.slot_no for r in minted_blocks}
 
-        difference_minted = slots_when_scheduled.difference(slots_when_minted)
-        if len(difference_minted) > len(leadership_schedule) // 2:
-            errors.append(f"Lot of slots missed: {difference_minted}")
+            # Compare leadership schedule with blocks that were actually minted
+            difference_scheduled = slots_when_minted.difference(slots_when_scheduled)
+            if difference_scheduled:
+                errors.append(
+                    f"Some blocks were minted in other slots than scheduled: {difference_scheduled}"
+                )
 
-        # compare db-sync records with ledger state dump
-        ledger_state = clusterlib_utils.get_ledger_state(cluster_obj=cluster)
-        clusterlib_utils.save_ledger_state(
-            cluster_obj=cluster,
-            state_name=temp_template,
-            ledger_state=ledger_state,
-        )
-        blocks_before: tp.Dict[str, int] = ledger_state["blocksBefore"]
-        pool_id_dec = helpers.decode_bech32(pool_id)
-        minted_blocks_ledger = blocks_before.get(pool_id_dec) or 0
-        minted_blocks_db = len(slots_when_minted)
-        if minted_blocks_ledger != minted_blocks_db:
-            errors.append(
-                "Numbers of minted blocks reported by ledger state and db-sync don't match: "
-                f"{minted_blocks_ledger} vs {minted_blocks_db}"
+            difference_minted = slots_when_scheduled.difference(slots_when_minted)
+            if len(difference_minted) > len(leadership_schedule) // 2:
+                errors.append(f"Lot of slots missed: {difference_minted}")
+
+            # Compare db-sync records with ledger state dump
+            ledger_state = clusterlib_utils.get_ledger_state(cluster_obj=cluster)
+            clusterlib_utils.save_ledger_state(
+                cluster_obj=cluster,
+                state_name=temp_template,
+                ledger_state=ledger_state,
             )
+            blocks_before: tp.Dict[str, int] = ledger_state["blocksBefore"]
+            pool_id_dec = helpers.decode_bech32(pool_id)
+            minted_blocks_ledger = blocks_before.get(pool_id_dec) or 0
+            minted_blocks_db = len(slots_when_minted)
+            if minted_blocks_ledger != minted_blocks_db:
+                errors.append(
+                    "Numbers of minted blocks reported by ledger state and db-sync don't match: "
+                    f"{minted_blocks_ledger} vs {minted_blocks_db}"
+                )
 
         if errors:
             # Xfail if cardano-api GH-269 is still open

cardano_node_tests/utils/logfiles.py

@@ -274,12 +274,12 @@ def add_ignore_rule(
         infile.write(f"{files_glob};;{skip_after};;{regex}\n")
 
 
-def _check_msgs_presence_in_logs(
+def check_msgs_presence_in_logs(
     regex_pairs: tp.List[tp.Tuple[str, str]],
     seek_offsets: tp.Dict[str, int],
     state_dir: pl.Path,
     timestamp: float,
-) -> None:
+) -> tp.List[str]:
     """Make sure the expected messages are present in logs."""
     errors = []
     for files_glob, regex in regex_pairs:
@@ -308,9 +308,7 @@ def _check_msgs_presence_in_logs(
             else:
                 errors.append(f"No line matching `{regex}` found in '{logfile}'.")
 
-    if errors:
-        errors_joined = "\n".join(errors)
-        raise AssertionError(errors_joined) from None
+    return errors
 
 
 @contextlib.contextmanager
@@ -342,9 +340,12 @@ def expect_errors(regex_pairs: tp.List[tp.Tuple[str, str]], worker_id: str) -> t
 
     yield
 
-    _check_msgs_presence_in_logs(
+    errors = check_msgs_presence_in_logs(
         regex_pairs=regex_pairs, seek_offsets=seek_offsets, state_dir=state_dir, timestamp=timestamp
     )
+    if errors:
+        errors_joined = "\n".join(errors)
+        raise AssertionError(errors_joined) from None
 
 
 @contextlib.contextmanager
@@ -371,9 +372,12 @@ def expect_messages(regex_pairs: tp.List[tp.Tuple[str, str]]) -> tp.Iterator[Non
 
     yield
 
-    _check_msgs_presence_in_logs(
+    errors = check_msgs_presence_in_logs(
         regex_pairs=regex_pairs, seek_offsets=seek_offsets, state_dir=state_dir, timestamp=timestamp
     )
+    if errors:
+        errors_joined = "\n".join(errors)
+        raise AssertionError(errors_joined) from None
 
 
 def search_cluster_logs() -> tp.List[tp.Tuple[pl.Path, str]]: