Merge pull request #1829 from input-output-hk/log_ignore_timestamp

Improve searching of log files for errors

cardano_node_tests/cluster_management/manager.py

@@ -227,6 +227,7 @@ def on_test_stop(self) -> None:
         self.log(f"c{self._cluster_instance_num}: called `on_test_stop` for '{current_test}'")
 
         with locking.FileLockIfXdist(self.cluster_lock):
+            # Delete an "ignore errors" rules file that was created for the current pytest worker.
             # There's only one test running on a worker at a time. Deleting the corresponding rules
             # file right after a test is finished is therefore safe. The effect is that the rules
             # apply only from the time they were added (by `logfiles.add_ignore_rule`) until the end

cardano_node_tests/tests/test_cli.py

@@ -1233,7 +1233,6 @@ def test_ping_localhost(
     def test_ping_unix_socket(
         self,
         cluster: clusterlib.ClusterLib,
-        worker_id: str,
         ping_available: None,  # noqa: ARG002
     ):
         """Test `cardano-cli ping` on local node using unix socket."""
@@ -1263,10 +1262,10 @@ def test_ping_unix_socket(
             logfiles.add_ignore_rule(
                 files_glob="*.stdout",
                 regex="MuxError MuxUnknownMiniProtocol .* MiniProtocolNum 8",
-                ignore_file_id=worker_id,
+                ignore_file_id="ping_unix_socket",
+                # Ignore errors for next 20 seconds
+                skip_after=time.time() + 20,
             )
-            # Give enough time for the log messages to be written to the log files
-            time.sleep(2.5)
 
             blockers.GH(issue=5245, message="`MuxError MuxBearerClosed` error").finish_test()
 

cardano_node_tests/tests/test_env_network_id.py

@@ -93,24 +93,6 @@ def set_network_id_env(
     cluster.magic_args = magic_args
 
 
-@pytest.fixture
-def ignore_log_errors(
-    # Depend on `cluster` just for correct ordering of fixtures
-    cluster: clusterlib.ClusterLib,  # noqa: ARG001
-    worker_id: str,
-) -> Generator[None, None, None]:
-    """Ignore expected handshake errors in the log files."""
-    # pylint: disable=unused-argument
-    logfiles.add_ignore_rule(
-        files_glob="*.stdout",
-        regex="HandshakeError.*Refused NodeToClient",
-        ignore_file_id=worker_id,
-    )
-    yield
-    # give enough time for the log messages to be written to the log files
-    time.sleep(2.5)
-
-
 @pytest.fixture
 def payment_addrs(
     skip_on_no_env: None,  # noqa: ARG001
@@ -260,9 +242,23 @@ def test_build_transfer_funds(
         ), f"Incorrect balance for destination address `{dst_addr.address}`"
 
 
+@pytest.mark.smoke
+@pytest.mark.testnets
 class TestNegativeNetworkIdEnv:
     """Negative tests for `CARDANO_NODE_NETWORK_ID`."""
 
+    @pytest.fixture
+    def ignore_log_errors(self) -> Generator[None, None, None]:
+        """Ignore expected handshake errors in the log files."""
+        yield
+        logfiles.add_ignore_rule(
+            files_glob="*.stdout",
+            regex="HandshakeError.*Refused NodeToClient",
+            ignore_file_id="neg_network_id_env",
+            # Ignore errors for next 20 seconds
+            skip_after=time.time() + 20,
+        )
+
     @allure.link(helpers.get_vcs_link())
     @PARAM_ENV_SCENARIO
     @PARAM_ARG_SCENARIO

cardano_node_tests/tests/test_kes.py

@@ -279,7 +279,7 @@ def _refresh_opcerts() -> Dict[str, int]:
         # search for expected errors only in log file corresponding to pool with expired KES
         expected_errors = [(f"{expire_node_name}.stdout", err) for err in expected_err_regexes]
 
-        with logfiles.expect_errors(expected_errors, ignore_file_id=worker_id):
+        with logfiles.expect_errors(expected_errors, worker_id=worker_id):
             LOGGER.info(
                 f"{datetime.datetime.now(tz=datetime.timezone.utc)}: "
                 f"Waiting for {expire_timeout} sec for KES expiration."
@@ -430,7 +430,7 @@ def test_opcert_invalid_kes_period(
         )
 
         with cluster_manager.respin_on_failure():
-            with logfiles.expect_errors(expected_errors, ignore_file_id=cluster_manager.worker_id):
+            with logfiles.expect_errors(expected_errors, worker_id=cluster_manager.worker_id):
                 # restart the node with the new operational certificate (restart all nodes so
                 # the connection is established again)
                 shutil.copy(invalid_opcert_file, opcert_file)

cardano_node_tests/tests/test_tx_negative.py

@@ -24,7 +24,6 @@
 from cardano_node_tests.utils import blockers
 from cardano_node_tests.utils import cluster_nodes
 from cardano_node_tests.utils import clusterlib_utils
-from cardano_node_tests.utils import configuration
 from cardano_node_tests.utils import helpers
 from cardano_node_tests.utils import logfiles
 from cardano_node_tests.utils import tx_view
@@ -655,7 +654,6 @@ def test_wrong_network_magic(
         self,
         cluster: clusterlib.ClusterLib,
         pool_users: List[clusterlib.PoolUser],
-        worker_id: str,
     ):
         """Try to submit a TX with wrong network magic.
 
@@ -670,7 +668,7 @@ def test_wrong_network_magic(
         tx_files = clusterlib.TxFiles(signing_key_files=[pool_users[0].payment.skey_file])
         destinations = [clusterlib.TxOut(address=dst_address, amount=amount)]
 
-        # build and sign a transaction
+        # Build and sign a transaction
         fee = cluster.g_transaction.calculate_tx_fee(
             src_address=src_address,
             tx_name=temp_template,
@@ -690,17 +688,7 @@ def test_wrong_network_magic(
             tx_name=temp_template,
         )
 
-        # it should NOT be possible to submit a transaction with incorrect network magic
-        logfiles.add_ignore_rule(
-            files_glob="*.stdout",
-            regex="HandshakeError",
-            ignore_file_id=worker_id,
-        )
-        logfiles.add_ignore_rule(
-            files_glob="*.stdout",
-            regex="NodeToClientVersionData",
-            ignore_file_id=worker_id,
-        )
+        # It should NOT be possible to submit a transaction with incorrect network magic
         with pytest.raises(clusterlib.CLIError) as excinfo:
             cluster.cli(
                 [
@@ -715,8 +703,20 @@ def test_wrong_network_magic(
             )
         assert "HandshakeError" in str(excinfo.value)
 
-        # wait a bit so there's some time for error messages to appear in log file
-        time.sleep(1 if cluster.network_magic == configuration.NETWORK_MAGIC_LOCAL else 5)
+        logfiles.add_ignore_rule(
+            files_glob="*.stdout",
+            regex="HandshakeError",
+            ignore_file_id="wrong_magic",
+            # Ignore errors for next 20 seconds
+            skip_after=time.time() + 20,
+        )
+        logfiles.add_ignore_rule(
+            files_glob="*.stdout",
+            regex="NodeToClientVersionData",
+            ignore_file_id="wrong_magic",
+            # Ignore errors for next 20 seconds
+            skip_after=time.time() + 20,
+        )
 
     @allure.link(helpers.get_vcs_link())
     def test_wrong_signing_key(

cardano_node_tests/tests/tests_plutus/test_spend_raw.py

@@ -19,7 +19,6 @@
 from cardano_node_tests.tests.tests_plutus import spend_raw
 from cardano_node_tests.utils import blockers
 from cardano_node_tests.utils import clusterlib_utils
-from cardano_node_tests.utils import configuration
 from cardano_node_tests.utils import dbsync_utils
 from cardano_node_tests.utils import helpers
 from cardano_node_tests.utils import logfiles
@@ -637,7 +636,6 @@ def test_always_fails(
         self,
         cluster: clusterlib.ClusterLib,
         payment_addrs: List[clusterlib.AddressRecord],
-        worker_id: str,
     ):
         """Test locking a Tx output with a Plutus script and spending the locked UTxO.
 
@@ -660,12 +658,6 @@ def test_always_fails(
             execution_cost=plutus_common.ALWAYS_FAILS_COST,
         )
 
-        logfiles.add_ignore_rule(
-            files_glob="*.stdout",
-            regex="ValidationTagMismatch",
-            ignore_file_id=worker_id,
-        )
-
         script_utxos, collateral_utxos, __ = spend_raw._fund_script(
             temp_template=temp_template,
             cluster_obj=cluster,
@@ -686,8 +678,13 @@ def test_always_fails(
         )
         assert "PlutusFailure" in err, err
 
-        # wait a bit so there's some time for error messages to appear in log file
-        time.sleep(1 if cluster.network_magic == configuration.NETWORK_MAGIC_LOCAL else 5)
+        logfiles.add_ignore_rule(
+            files_glob="*.stdout",
+            regex="ValidationTagMismatch",
+            ignore_file_id="plutus_always_fails",
+            # Ignore errors for next 20 seconds
+            skip_after=time.time() + 20,
+        )
 
     @allure.link(helpers.get_vcs_link())
     def test_script_invalid(