From 325cd101bde7ee153793b78d9687a96fc8a3e234 Mon Sep 17 00:00:00 2001 From: Martin Kourim Date: Fri, 6 Nov 2026 15:23:37 +0100 Subject: [PATCH 1/4] fix: bound submit-api mempool retries Replace fixed retry counts with exponential backoff and equal jitter. Use a configurable elapsed-time budget and maximum delay, retry only explicit MempoolTxTooSlow rejections, and retain the last rejection in diagnostics. Transport failures continue to propagate. Cover recovery, deadline exhaustion, backoff caps, invalid settings, and non-retryable responses with deterministic unit tests. --- cardano_node_tests/utils/submit_api.py | 81 ++++++++---- framework_tests/test_submit_api.py | 169 +++++++++++++++++++++++++ 2 files changed, 226 insertions(+), 24 deletions(-) create mode 100644 framework_tests/test_submit_api.py diff --git a/cardano_node_tests/utils/submit_api.py b/cardano_node_tests/utils/submit_api.py index 9360987cc..454194a50 100644 --- a/cardano_node_tests/utils/submit_api.py +++ b/cardano_node_tests/utils/submit_api.py @@ -4,6 +4,7 @@ import dataclasses import json import logging +import math import pathlib as pl import random import shutil @@ -56,39 +57,71 @@ def tx2cbor(*, tx_file: clusterlib.FileType, destination_dir: clusterlib.FileTyp return out_file -def post_cbor(*, cbor_file: clusterlib.FileType, url: str) -> requests.Response: - """Post binary CBOR representation of Tx to `cardano-submit-api` service on `url`.""" +def post_cbor( + *, + cbor_file: clusterlib.FileType, + url: str, + retry_timeout: float = 180, + retry_max_delay: float = 30, +) -> requests.Response: + """Post a transaction, retrying only explicit `MempoolTxTooSlow` rejections. + + Request timeouts use the remaining budget, capped at 300 seconds. Requests applies + that timeout to connection/read inactivity, not strictly to total request duration. + Transport errors propagate because the transaction might already have been accepted. + + Args: + cbor_file: File containing the binary CBOR transaction. + url: Submit API endpoint. + retry_timeout: Elapsed-time budget in seconds for requests and backoff. + retry_max_delay: Maximum exponential backoff delay in seconds. Delays start at + 1-2 seconds and use jitter. Both settings must be finite and positive. + + Returns: + The first response that is not a `MempoolTxTooSlow` rejection. + + """ + if not math.isfinite(retry_timeout) or retry_timeout <= 0: + msg = "retry_timeout must be finite and positive" + raise ValueError(msg) + if not math.isfinite(retry_max_delay) or retry_max_delay <= 0: + msg = "retry_max_delay must be finite and positive" + raise ValueError(msg) + headers = {"Content-Type": "application/cbor"} with open(cbor_file, "rb") as in_fp: cbor_binary = in_fp.read() - # Retry only on `MempoolTxTooSlow`, which is a wallclock soft-timeout in the node's - # mempool. It is transient when caused by GC pauses, snapshot writes, or CPU spikes; - # backoff must outlast those. If it persists after a few retries, the cause is not - # transient (expensive tx or overloaded node) and further retries won't help. - attempts = 6 - for r in range(1, attempts + 1): - if r > 1: - LOGGER.warning(f"Resubmitting transaction to submit-api. Attempt {r}/{attempts}.") - + deadline = time.monotonic() + retry_timeout + delay_cap = min(2.0, retry_max_delay) + attempts = 0 + last_rejection = "" + while (remaining := deadline - time.monotonic()) > 0: + attempts += 1 response = http_client.get_session().post( - url, headers=headers, data=cbor_binary, timeout=300 + url, headers=headers, data=cbor_binary, timeout=min(300.0, remaining) ) - if response.status_code == 400 and "MempoolTxTooSlow" in response.text: - if r < attempts: - time.sleep(random.uniform(2, 10)) - continue - err = ( - f"Failed to submit the tx after {attempts} attempts due to " - f"`MempoolTxTooSlow`: {response.text}" - ) - raise SubmitApiError(err) + if response.status_code != 400 or "MempoolTxTooSlow" not in response.text: + return response - return response + last_rejection = response.text + delay = random.uniform(delay_cap / 2, delay_cap) + if delay >= deadline - time.monotonic(): + break + LOGGER.warning( + f"MempoolTxTooSlow on attempt {attempts}; retrying submit-api in {delay:.2f}s: " + f"{last_rejection}" + ) + time.sleep(delay) + delay_cap = min(delay_cap * 2, retry_max_delay) - msg = f"Unreachable: loop exited without return after {attempts} attempts." - raise RuntimeError(msg) + msg = ( + f"Failed to submit the tx after {attempts} attempts within the " + f"{retry_timeout:g}s retry budget due to MempoolTxTooSlow errors. " + f"Last rejection: {last_rejection}" + ) + raise SubmitApiError(msg) def submit_tx_bare(*, tx_file: clusterlib.FileType) -> SubmitApiOut: diff --git a/framework_tests/test_submit_api.py b/framework_tests/test_submit_api.py new file mode 100644 index 000000000..47e5868df --- /dev/null +++ b/framework_tests/test_submit_api.py @@ -0,0 +1,169 @@ +"""Unit tests for submit API mempool retry behavior.""" + +import functools +import pathlib as pl +import types +from unittest import mock + +import pytest +import requests + +from cardano_node_tests.utils import submit_api + + +def _response(status: int, text: str) -> requests.Response: + """Create a response without making an HTTP request.""" + response = requests.Response() + response.status_code = status + response._content = text.encode() + return response + + +@pytest.fixture +def submission(tmp_path: pl.Path, monkeypatch: pytest.MonkeyPatch) -> types.SimpleNamespace: + """Provide a fake API session, payload and monotonic clock.""" + cbor_file = tmp_path / "tx.cbor" + cbor_file.write_bytes(b"transaction") + clock = types.SimpleNamespace(now=0.0) + + def sleep(delay: float) -> None: + clock.now += delay + + sleeper = mock.Mock(side_effect=sleep) + monkeypatch.setattr( + submit_api, "time", types.SimpleNamespace(monotonic=lambda: clock.now, sleep=sleeper) + ) + jitter = mock.Mock(side_effect=lambda _low, high: high) + monkeypatch.setattr(submit_api, "random", types.SimpleNamespace(uniform=jitter)) + post = mock.Mock(return_value=_response(202, '"txid"')) + monkeypatch.setattr( + submit_api.http_client, "get_session", lambda: types.SimpleNamespace(post=post) + ) + return types.SimpleNamespace( + submit=functools.partial(submit_api.post_cbor, cbor_file=cbor_file, url="http://submit"), + post=post, + clock=clock, + sleep=sleeper, + jitter=jitter, + ) + + +def test_submission_success(submission: types.SimpleNamespace) -> None: + """Return the successful response without sleeping.""" + assert submission.submit() is submission.post.return_value + assert submission.post.call_count == 1 + assert submission.post.call_args.kwargs["data"] == b"transaction" + assert submission.post.call_args.kwargs["timeout"] == 180 + submission.sleep.assert_not_called() + + +def test_exponential_backoff(submission: types.SimpleNamespace) -> None: + """Match CLI retry delays, capping jittered backoff without a fixed attempt limit.""" + submission.post.side_effect = [_response(400, "MempoolTxTooSlow")] * 7 + [ + submission.post.return_value + ] + assert submission.submit(retry_max_delay=5) is submission.post.return_value + assert submission.sleep.call_args_list == [mock.call(d) for d in (2, 4, 5, 5, 5, 5, 5)] + assert submission.jitter.call_args_list == [mock.call(d / 2, d) for d in (2, 4, 5, 5, 5, 5, 5)] + assert [c.kwargs["timeout"] for c in submission.post.call_args_list] == [ + 180, + 178, + 174, + 169, + 164, + 159, + 154, + 149, + ] + + +def test_retry_budget(submission: types.SimpleNamespace) -> None: + """Stop rather than sleep beyond the budget, retaining the last rejection.""" + submission.post.return_value = _response(400, "MempoolTxTooSlow (last rejection)") + with pytest.raises(submit_api.SubmitApiError, match=r"3 attempts.*7s retry budget") as excinfo: + submission.submit(retry_timeout=7) + assert "last rejection" in str(excinfo.value) + assert submission.sleep.call_args_list == [mock.call(2), mock.call(4)] + assert submission.clock.now == 6 + + +def test_default_backoff_cap(submission: types.SimpleNamespace) -> None: + """Stop increasing the delay at the default thirty-second cap.""" + submission.post.side_effect = [_response(400, "MempoolTxTooSlow")] * 8 + [ + submission.post.return_value + ] + assert submission.submit() is submission.post.return_value + assert submission.sleep.call_args_list == [mock.call(d) for d in (2, 4, 8, 16, 30, 30, 30, 30)] + + +@pytest.mark.parametrize("cap", [0.5, 30]) +def test_lower_jitter_bound(submission: types.SimpleNamespace, cap: float) -> None: + """Keep equal jitter above zero and respect caps smaller than the initial delay.""" + submission.jitter.side_effect = lambda low, _high: low + submission.post.side_effect = [_response(400, "MempoolTxTooSlow")] * 3 + [ + submission.post.return_value + ] + assert submission.submit(retry_max_delay=cap) is submission.post.return_value + assert submission.sleep.call_args_list == [mock.call(min(d, cap) / 2) for d in (2, 4, 8)] + + +def test_slow_attempt_consumes_budget(submission: types.SimpleNamespace) -> None: + """Count time inside HTTP requests and do not retry after expiry.""" + + def reject(*_args: object, **_kwargs: object) -> requests.Response: + submission.clock.now += 7 + return _response(400, "MempoolTxTooSlow") + + submission.post.side_effect = reject + with pytest.raises(submit_api.SubmitApiError, match="1 attempts"): + submission.submit(retry_timeout=7) + assert submission.post.call_count == 1 + submission.sleep.assert_not_called() + + +def test_oversleep_consumes_budget(submission: types.SimpleNamespace) -> None: + """Recheck the deadline after waking up late.""" + submission.post.return_value = _response(400, "MempoolTxTooSlow") + submission.sleep.side_effect = lambda _delay: setattr(submission.clock, "now", 1000) + with pytest.raises(submit_api.SubmitApiError, match="1 attempts"): + submission.submit() + assert submission.post.call_count == 1 + + +@pytest.mark.parametrize( + ("status", "text"), + [(400, "BadInputsUTxO"), (500, "MempoolTxTooSlow"), (202, "MempoolTxTooSlow")], +) +def test_other_responses_return(submission: types.SimpleNamespace, status: int, text: str) -> None: + """Only retry a 400 response containing the explicit rejection.""" + response = _response(status, text) + submission.post.return_value = response + assert submission.submit() is response + assert submission.post.call_count == 1 + submission.sleep.assert_not_called() + + +@pytest.mark.parametrize("error", [requests.ReadTimeout("ambiguous"), requests.ConnectionError()]) +def test_transport_errors_propagate(submission: types.SimpleNamespace, error: Exception) -> None: + """Do not retry errors that leave submission status unknown.""" + submission.post.side_effect = error + with pytest.raises(type(error)) as excinfo: + submission.submit() + assert excinfo.value is error + assert submission.post.call_count == 1 + submission.sleep.assert_not_called() + + +def test_request_timeout_cap(submission: types.SimpleNamespace) -> None: + """Preserve the request timeout cap for larger budgets.""" + submission.submit(retry_timeout=900) + assert submission.post.call_args.kwargs["timeout"] == 300 + + +@pytest.mark.parametrize("setting", ["retry_timeout", "retry_max_delay"]) +@pytest.mark.parametrize("value", [0, -1, float("inf"), float("nan")]) +def test_invalid_settings(submission: types.SimpleNamespace, setting: str, value: float) -> None: + """Reject invalid retry settings before submitting anything.""" + with pytest.raises(ValueError, match=f"{setting} must be finite and positive"): + submission.submit(**{setting: value}) + submission.post.assert_not_called() From 93e7fe2881523567289b23c2686a95fe5e31b6b8 Mon Sep 17 00:00:00 2001 From: Martin Kourim Date: Fri, 6 Nov 2026 16:57:36 +0100 Subject: [PATCH 2/4] fix(tests): isolate SECP256k1 funding setup Cache payment and issuer addresses with source refill thresholds in both raw and build tests. Fund fresh minting inputs in fixtures so funding failures cannot be caught as expected script rejections. Keep mempool timeouts outside relaxed error-message assertions and restore the missing PlutusV3 assertion with current CEK error messages. All 48 cases passed across the raw run and corrected build rerun. --- .../test_mint_secp256k1_build.py | 96 ++++++++++++------- .../test_mint_secp256k1_raw.py | 86 ++++++++++------- 2 files changed, 113 insertions(+), 69 deletions(-) diff --git a/cardano_node_tests/tests/tests_plutus_v2/test_mint_secp256k1_build.py b/cardano_node_tests/tests/tests_plutus_v2/test_mint_secp256k1_build.py index a69c5be9c..08c086ca7 100644 --- a/cardano_node_tests/tests/tests_plutus_v2/test_mint_secp256k1_build.py +++ b/cardano_node_tests/tests/tests_plutus_v2/test_mint_secp256k1_build.py @@ -2,7 +2,6 @@ import logging import pathlib as pl -import typing as tp import allure import pytest @@ -32,7 +31,7 @@ def payment_addrs( cluster_manager: cluster_management.ClusterManager, cluster: clusterlib.ClusterLib, ) -> list[clusterlib.AddressRecord]: - """Create new payment address.""" + """Cache payment and issuer addresses per worker/cluster, refilling the source as needed.""" addrs = addrs_common.get_payment_addrs( name_template=common.get_test_id(cluster), cluster_manager=cluster_manager, @@ -40,44 +39,54 @@ def payment_addrs( num=2, fund_idx=[0], amount=3_000_000_000, + min_amount=300_000_000, + caching_key=helpers.get_current_line_str(), ) return addrs +@pytest.fixture +def issuer_funding( + cluster: clusterlib.ClusterLib, + payment_addrs: list[clusterlib.AddressRecord], +) -> tuple[list[clusterlib.UTXOData], list[clusterlib.UTXOData]]: + """Fund fresh minting inputs and collateral before testing script rejection.""" + minting_cost = plutus_common.compute_cost( + execution_cost=plutus_common.MINTING_V2_REF_COST, + protocol_params=cluster.g_query.get_protocol_params(), + ) + mint_utxos, collateral_utxos, *_ = mint_build._fund_issuer( + cluster_obj=cluster, + temp_template=common.get_test_id(cluster), + payment_addr=payment_addrs[0], + issuer_addr=payment_addrs[1], + minting_cost=minting_cost, + amount=200_000_000, + ) + return mint_utxos, collateral_utxos + + class TestSECP256k1: - def _fund_issuer_mint_token( + """Test SECP256k1 minting with valid and invalid signature vectors.""" + + def _mint_token( self, cluster_obj: clusterlib.ClusterLib, temp_template: str, payment_addrs: list[clusterlib.AddressRecord], + issuer_funding: tuple[list[clusterlib.UTXOData], list[clusterlib.UTXOData]], script_file: pl.Path, redeemer_file: pl.Path, - ): - """Fund the token issuer and mint a token.""" - __: tp.Any # mypy workaround + ) -> None: + """Mint a token using previously funded inputs and collateral.""" payment_addr = payment_addrs[0] issuer_addr = payment_addrs[1] lovelace_amount = 2_000_000 token_amount = 5 - script_fund = 200_000_000 - - minting_cost = plutus_common.compute_cost( - execution_cost=plutus_common.MINTING_V2_REF_COST, - protocol_params=cluster_obj.g_query.get_protocol_params(), - ) - - mint_utxos, collateral_utxos, __, __ = mint_build._fund_issuer( - cluster_obj=cluster_obj, - temp_template=temp_template, - payment_addr=payment_addr, - issuer_addr=issuer_addr, - minting_cost=minting_cost, - amount=script_fund, - ) - - # Step 2: mint the "qacoin" + mint_utxos, collateral_utxos = issuer_funding + # Build the script transaction using only this test's funding outputs. policyid = cluster_obj.g_transaction.get_policyid(script_file) asset_name = f"qacoin{clusterlib.get_rand_str(4)}".encode().hex() token = f"{policyid}.{asset_name}" @@ -139,6 +148,7 @@ def test_use_secp_builtin_functions( self, cluster: clusterlib.ClusterLib, payment_addrs: list[clusterlib.AddressRecord], + issuer_funding: tuple[list[clusterlib.UTXOData], list[clusterlib.UTXOData]], algorithm: str, plutus_version: str, ): @@ -165,10 +175,11 @@ def test_use_secp_builtin_functions( redeemer_file = redeemer_dir / "positive.redeemer" try: - self._fund_issuer_mint_token( + self._mint_token( cluster_obj=cluster, temp_template=temp_template, payment_addrs=payment_addrs, + issuer_funding=issuer_funding, script_file=script_file, redeemer_file=redeemer_file, ) @@ -215,13 +226,14 @@ def test_negative_secp_builtin_functions( self, cluster: clusterlib.ClusterLib, payment_addrs: list[clusterlib.AddressRecord], + issuer_funding: tuple[list[clusterlib.UTXOData], list[clusterlib.UTXOData]], test_vector: str, algorithm: str, plutus_version: str, ): - """Try to mint a token with invalid test vectors. + """Reject invalid signature vectors after successfully funding the issuer. - Expect failure. + Funding failures must surface as setup errors, not expected script rejections. """ temp_template = common.get_test_id(cluster) @@ -241,16 +253,19 @@ def test_negative_secp_builtin_functions( before_pv8 = clusterlib_utils.get_protocol_version(cluster_obj=cluster) < 8 + # Capture only the script operation, never the successful funding setup. with pytest.raises(clusterlib.CLIError) as excinfo: - self._fund_issuer_mint_token( + self._mint_token( cluster_obj=cluster, temp_template=temp_template, payment_addrs=payment_addrs, + issuer_funding=issuer_funding, script_file=script_file, redeemer_file=redeemer_file, ) exc_value = str(excinfo.value) + assert "MempoolTxTooSlow" not in exc_value, exc_value # Before protocol version 8 the SECP256k1 is blocked. # After that the usage is limited by high cost model. @@ -269,7 +284,8 @@ def test_negative_secp_builtin_functions( ) if before_pv8: - assert is_forbidden or is_overspending, exc_value + with common.allow_unstable_error_messages(): + assert is_forbidden or is_overspending, exc_value # From protocol version 8 the SECP256k1 functions are allowed and # when we provide wrong data meaningful error messages are expected. elif plutus_version == "v2": @@ -282,18 +298,24 @@ def test_negative_secp_builtin_functions( "no_pubkey": "Invalid verification key", "no_sig": "Invalid signature", } - assert expected_error_messages[test_vector] in exc_value, exc_value + with common.allow_unstable_error_messages(): + assert expected_error_messages[test_vector] in exc_value, exc_value elif plutus_version == "v3": - # PT5: PlutusTx.Prelude.check: input is 'False'. The untyped script we use for - # PlutusV3 is different from the PlutusV2 script, and doesn't produce the same error - # messages. + # These untyped V3 scripts fail in the CEK machine, rather than emitting + # PlutusTx.Prelude.check's PT5 trace. Malformed inputs also report builtin logs. + validation_error = ( + "The machine terminated because of an error, " + "either from a built-in function or from an explicit use of 'error'." + ) expected_error_messages = { - "invalid_sig": "PT5", - "invalid_pubkey": "PT5", - "no_msg": ("Invalid message hash" if algorithm == "ecdsa" else "PT5"), - "no_pubkey": "PT5", - "no_sig": "PT5", + "invalid_sig": validation_error, + "invalid_pubkey": validation_error, + "no_msg": ("Invalid message hash" if algorithm == "ecdsa" else validation_error), + "no_pubkey": "Invalid verification key", + "no_sig": "Invalid signature", } + with common.allow_unstable_error_messages(): + assert expected_error_messages[test_vector] in exc_value, exc_value else: _msg = f"Unsupported plutus version: {plutus_version}" raise ValueError(_msg) diff --git a/cardano_node_tests/tests/tests_plutus_v2/test_mint_secp256k1_raw.py b/cardano_node_tests/tests/tests_plutus_v2/test_mint_secp256k1_raw.py index 28c39a646..5c2f9dc88 100644 --- a/cardano_node_tests/tests/tests_plutus_v2/test_mint_secp256k1_raw.py +++ b/cardano_node_tests/tests/tests_plutus_v2/test_mint_secp256k1_raw.py @@ -3,7 +3,6 @@ import logging import pathlib as pl import re -import typing as tp import allure import pytest @@ -32,7 +31,7 @@ def payment_addrs( cluster_manager: cluster_management.ClusterManager, cluster: clusterlib.ClusterLib, ) -> list[clusterlib.AddressRecord]: - """Create new payment address.""" + """Cache payment and issuer addresses per worker/cluster, refilling the source as needed.""" addrs = addrs_common.get_payment_addrs( name_template=common.get_test_id(cluster), cluster_manager=cluster_manager, @@ -40,43 +39,56 @@ def payment_addrs( num=2, fund_idx=[0], amount=3_000_000_000, + min_amount=300_000_000, + caching_key=helpers.get_current_line_str(), ) return addrs +@pytest.fixture +def issuer_funding( + cluster: clusterlib.ClusterLib, + payment_addrs: list[clusterlib.AddressRecord], +) -> tuple[list[clusterlib.UTXOData], list[clusterlib.UTXOData], plutus_common.ScriptCost]: + """Fund fresh minting inputs and collateral before testing script rejection.""" + minting_cost = plutus_common.compute_cost( + execution_cost=plutus_common.MINTING_V2_REF_COST, + protocol_params=cluster.g_query.get_protocol_params(), + ) + mint_utxos, collateral_utxos, *_ = mint_raw._fund_issuer( + cluster_obj=cluster, + temp_template=common.get_test_id(cluster), + payment_addr=payment_addrs[0], + issuer_addr=payment_addrs[1], + minting_cost=minting_cost, + amount=2_000_000, + fee_txsize=600_000, + ) + return mint_utxos, collateral_utxos, minting_cost + + class TestSECP256k1: - def _fund_issuer_mint_token( + """Test SECP256k1 minting with valid and invalid signature vectors.""" + + def _mint_token( self, cluster_obj: clusterlib.ClusterLib, temp_template: str, payment_addrs: list[clusterlib.AddressRecord], + issuer_funding: tuple[ + list[clusterlib.UTXOData], list[clusterlib.UTXOData], plutus_common.ScriptCost + ], script_file: pl.Path, redeemer_file: pl.Path, - ): - """Fund the token issuer and mint a token.""" - __: tp.Any # mypy workaround - payment_addr = payment_addrs[0] + ) -> None: + """Mint a token using previously funded inputs and collateral.""" issuer_addr = payment_addrs[1] - + mint_utxos, collateral_utxos, minting_cost = issuer_funding lovelace_amount = 2_000_000 token_amount = 5 fee_txsize = 600_000 - minting_cost = plutus_common.compute_cost( - execution_cost=plutus_common.MINTING_V2_REF_COST, - protocol_params=cluster_obj.g_query.get_protocol_params(), - ) - - mint_utxos, collateral_utxos, __, __ = mint_raw._fund_issuer( - cluster_obj=cluster_obj, - temp_template=temp_template, - payment_addr=payment_addr, - issuer_addr=issuer_addr, - minting_cost=minting_cost, - amount=lovelace_amount, - fee_txsize=fee_txsize, - ) - + # Build the script transaction using only this test's funding outputs. policyid = cluster_obj.g_transaction.get_policyid(script_file) asset_name = f"qacoin{clusterlib.get_rand_str(4)}".encode().hex() token = f"{policyid}.{asset_name}" @@ -142,6 +154,9 @@ def test_use_secp_builtin_functions( self, cluster: clusterlib.ClusterLib, payment_addrs: list[clusterlib.AddressRecord], + issuer_funding: tuple[ + list[clusterlib.UTXOData], list[clusterlib.UTXOData], plutus_common.ScriptCost + ], algorithm: str, plutus_version: str, ): @@ -168,10 +183,11 @@ def test_use_secp_builtin_functions( redeemer_file = redeemer_dir / "positive.redeemer" try: - self._fund_issuer_mint_token( + self._mint_token( cluster_obj=cluster, temp_template=temp_template, payment_addrs=payment_addrs, + issuer_funding=issuer_funding, script_file=script_file, redeemer_file=redeemer_file, ) @@ -194,13 +210,16 @@ def test_negative_secp_builtin_functions( self, cluster: clusterlib.ClusterLib, payment_addrs: list[clusterlib.AddressRecord], + issuer_funding: tuple[ + list[clusterlib.UTXOData], list[clusterlib.UTXOData], plutus_common.ScriptCost + ], test_vector: str, algorithm: str, plutus_version: str, ): - """Try to mint a token with invalid test vectors. + """Reject invalid signature vectors after successfully funding the issuer. - Expect failure. + Funding failures must surface as setup errors, not expected script rejections. """ temp_template = common.get_test_id(cluster) @@ -220,15 +239,18 @@ def test_negative_secp_builtin_functions( before_pv8 = clusterlib_utils.get_protocol_version(cluster_obj=cluster) < 8 + # Capture only the script operation, never the successful funding setup. with pytest.raises(clusterlib.CLIError) as excinfo: - self._fund_issuer_mint_token( + self._mint_token( cluster_obj=cluster, temp_template=temp_template, payment_addrs=payment_addrs, + issuer_funding=issuer_funding, script_file=script_file, redeemer_file=redeemer_file, ) exc_value = str(excinfo.value) + assert "MempoolTxTooSlow" not in exc_value, exc_value # Before protocol version 8 the SECP256k1 is blocked. # After that the usage is limited by high cost model. @@ -255,8 +277,8 @@ def test_negative_secp_builtin_functions( "no_sig": decoding_error, } - if before_pv8: - assert is_forbidden or is_overspending, exc_value - else: - assert re.search(expected_error_messages[test_vector], exc_value), exc_value - # Assert expected_error_messages[test_vector] in exc_value, exc_value + with common.allow_unstable_error_messages(): + if before_pv8: + assert is_forbidden or is_overspending, exc_value + else: + assert re.search(expected_error_messages[test_vector], exc_value), exc_value From 2a0c56cf9b3355107c4b611d925ebcf1dcbcc96d Mon Sep 17 00:00:00 2001 From: Martin Kourim Date: Fri, 6 Nov 2026 16:57:36 +0100 Subject: [PATCH 3/4] test: verify mempool retry diagnostics Exercise changing rejection messages during submit-api retries and assert that exhaustion reports the latest rejection, not the first. Check warning logs retain each rejection and its selected backoff. The framework unit tests and utility doctests passed. --- framework_tests/test_submit_api.py | 11 +++++++++-- 1 file changed, 9 insertions(+), 2 deletions(-) diff --git a/framework_tests/test_submit_api.py b/framework_tests/test_submit_api.py index 47e5868df..6eeb5d6f7 100644 --- a/framework_tests/test_submit_api.py +++ b/framework_tests/test_submit_api.py @@ -77,12 +77,19 @@ def test_exponential_backoff(submission: types.SimpleNamespace) -> None: ] -def test_retry_budget(submission: types.SimpleNamespace) -> None: +def test_retry_budget(submission: types.SimpleNamespace, caplog: pytest.LogCaptureFixture) -> None: """Stop rather than sleep beyond the budget, retaining the last rejection.""" - submission.post.return_value = _response(400, "MempoolTxTooSlow (last rejection)") + submission.post.side_effect = [ + _response(400, "MempoolTxTooSlow (first rejection)"), + _response(400, "MempoolTxTooSlow (last rejection)"), + _response(400, "MempoolTxTooSlow (last rejection)"), + ] with pytest.raises(submit_api.SubmitApiError, match=r"3 attempts.*7s retry budget") as excinfo: submission.submit(retry_timeout=7) assert "last rejection" in str(excinfo.value) + assert "first rejection" not in str(excinfo.value) + assert "retrying submit-api in 2.00s: MempoolTxTooSlow (first rejection)" in caplog.text + assert "retrying submit-api in 4.00s: MempoolTxTooSlow (last rejection)" in caplog.text assert submission.sleep.call_args_list == [mock.call(2), mock.call(4)] assert submission.clock.now == 6 From 7e0145ebabc0b5de67de8fb8e6b61f1180f2cf1d Mon Sep 17 00:00:00 2001 From: Martin Kourim Date: Fri, 6 Nov 2026 16:57:36 +0100 Subject: [PATCH 4/4] feat(runner): capture node resource pressure Sample resources at a configurable interval, defaulting to 60 seconds. Record node thread scheduling counters, visible cgroup quotas and throttling, and available GC/CPU metrics from configured endpoints. Support legacy hasPrometheus and modern PrometheusSimple backends. Validate the interval before destructive setup and document controlled lower-concurrency reruns without changing global concurrency limits. Validate monitoring with smoke checks and live four-node snapshots. Linters passed. --- README.md | 1 + agent_docs/failure_analysis_prompt.md | 4 +- agent_docs/mempool_timeouts.md | 44 +++++++++++++++ runner/monitor_resources.sh | 77 +++++++++++++++++++++++++++ runner/regression.sh | 15 +++++- 5 files changed, 138 insertions(+), 3 deletions(-) create mode 100644 agent_docs/mempool_timeouts.md create mode 100644 runner/monitor_resources.sh diff --git a/README.md b/README.md index a8451d5c8..216f1c260 100644 --- a/README.md +++ b/README.md @@ -192,6 +192,7 @@ You can fine-tune test runs using these environment variables: | `TX_FIREHOSE_REV` | `tx-firehose` version (default: `leios-prototype`). | | `PYTEST_ARGS` | Extra options passed to pytest. | | `TEST_THREADS` | Number of pytest workers (default: `20`). | +| `MONITOR_INTERVAL` | Resource snapshot interval in seconds (default: `60`). | | `TIME_DRIFT_POOL` | Pool (1-3) for libfaketime clock skew; unset = off. | | `TIME_DRIFT_SPEC` | libfaketime `FAKETIME` string, e.g. `+0 x1.008`. | | `LIBFAKETIME_PATH` | Override path to `libfaketimeMT.so.1`. | diff --git a/agent_docs/failure_analysis_prompt.md b/agent_docs/failure_analysis_prompt.md index 9208fd395..ea9017666 100644 --- a/agent_docs/failure_analysis_prompt.md +++ b/agent_docs/failure_analysis_prompt.md @@ -12,7 +12,9 @@ Inputs available under `{RUN_DIR}/` (use only what exists): - `{RUN_DIR}/errors_all.log` — output of `runner/grep_errors.sh`: case-insensitive grep for `:error:|failed|failure` in `*.stdout`/`*.stderr` files under `testing_artifacts/`, with paths relative to that dir. Rotated logs (`*.stdout.`, `*.stderr.`) are **not** grepped, so a thin or empty `errors_all.log` doesn't prove there were no errors - grep the rotated logs directly when an early crash is suspected - `{RUN_DIR}/scheduling.log` — cluster instance manager log - `{RUN_DIR}/testrun-report.xml` — junit XML -- `{RUN_DIR}/monitor.log` — system resource snapshots every 10 min +- `{RUN_DIR}/monitor.log` - resource snapshots at the configured interval (60 seconds by default + in current regression runs; older runs used 10 minutes), including host usage, node thread + scheduling counters, visible cgroup CPU throttling, and available node GC/CPU metrics - `{RUN_DIR}/testing_artifacts/pytest-*/cm-status.db` — cluster-management SQLite status database ("test running", resource and flag records as they were at the end of the run); query with `sqlite3 -readonly -header 'SELECT * FROM overview ORDER BY instance_num, kind'` Counting tests (IMPORTANT): diff --git a/agent_docs/mempool_timeouts.md b/agent_docs/mempool_timeouts.md new file mode 100644 index 000000000..96752c799 --- /dev/null +++ b/agent_docs/mempool_timeouts.md @@ -0,0 +1,44 @@ +# Investigating mempool latency + +`MempoolTxTooSlow` measures wall-clock validation latency, including GC and scheduling +delays. Local submissions use this rejection for both soft and hard timeouts. An empty +mempool does not rule out CPU starvation. + +## Resource diagnostics + +`runner/regression.sh` samples `monitor.log` every 60 seconds by default. Override with +`MONITOR_INTERVAL=10` for short incidents. Snapshots include: + +- Host CPU, memory, disk and CPU pressure. +- Node PIDs, lifetime-average CPU usage, thread counts and main-thread context switches. +- `/proc//task/*/schedstat`: CPU runtime, runnable queue wait, and timeslices, + summed over live threads, including RTS workers. Compare snapshots for the same PID; + thread exits/restarts can reset counters, so sums are not strictly monotonic. +- Cgroup v2 CPU quotas, throttling counters and pressure at visible node/ancestor groups. + Rising `nr_throttled`/`throttled_usec` points at quota contention. Namespace-hidden + groups and cgroup v1 cannot be fully diagnosed with these snapshots. +- GC, allocation, heap, pause and CPU metrics exposed by each configured local + Prometheus endpoint. Names and availability depend on the node/tracing configuration; + absent metrics are not evidence that there were no GC pauses. + Both legacy `hasPrometheus` and newer `PrometheusSimple` backends are discovered. + +Scrapes are best-effort, capped at two seconds per endpoint. Sampling interval is the +sleep between snapshots; collecting a snapshot adds some time. These are diagnostic +counters, not an automatic overload detector or a reason to relax node protection. + +## Controlled reruns + +Reduce concurrency explicitly, without changing repository defaults: + +```sh +TEST_THREADS=2 MAX_TESTS_PER_CLUSTER=2 MONITOR_INTERVAL=10 ./runner/regression.sh +``` + +To rerun selected tests on an existing dev cluster, source its environment and use +`MAX_TESTS_PER_CLUSTER=2 pytest -n 2 ...`. Keep the original workload and lower-load +results separate; a passing lower-load run does not prove the contention was fixed. + +Read-only query timeouts are separate from submission rejections. Do not retry an +entire transaction-building operation or extend CLI timeouts indiscriminately. A +transport timeout can leave submission status unknown; existing confirmation logic +must resolve it before any resubmission. diff --git a/runner/monitor_resources.sh b/runner/monitor_resources.sh new file mode 100644 index 000000000..af83bf635 --- /dev/null +++ b/runner/monitor_resources.sh @@ -0,0 +1,77 @@ +#!/usr/bin/env bash +# Best-effort node and cgroup diagnostics, sourced by regression.sh's resource monitor. + +monitor_node_resources() { + local workdir="$1" pid cg cgdir config port metric hierarchy cgpath + local task runtime wait_ns timeslices total_runtime total_wait total_timeslices threads + local -A cgroups=([/sys/fs/cgroup]=1) + + echo "--- NODE PROCESSES (CPU is lifetime average) ---" + ps -C cardano-node -o pid,ppid,pcpu,pmem,nlwp,stat,etimes,time,args || true + while read -r pid; do + echo "--- NODE PID $pid ---" + # Include the RTS worker threads, not just the process leader's schedstat. + total_runtime=0 total_wait=0 total_timeslices=0 threads=0 + for task in "/proc/$pid/task/"[0-9]*; do + [ -r "$task/schedstat" ] || continue + if read -r runtime wait_ns timeslices < "$task/schedstat"; then + total_runtime=$((total_runtime + runtime)) + total_wait=$((total_wait + wait_ns)) + total_timeslices=$((total_timeslices + timeslices)) + threads=$((threads + 1)) + fi + done + echo "schedstat (live-thread sums: runtime_ns wait_ns timeslices; threads=$threads):" + echo "$total_runtime $total_wait $total_timeslices" + echo "RSS, thread count, and main-thread context switches:" + grep -E '^(VmRSS|Threads|voluntary_ctxt_switches|nonvoluntary_ctxt_switches):' "/proc/$pid/status" || true + + cg="" + if [ -r "/proc/$pid/cgroup" ]; then + while IFS=: read -r hierarchy _ cgpath; do + if [ "$hierarchy" = 0 ]; then + cg="$cgpath" + break + fi + done < "/proc/$pid/cgroup" + fi + # Cgroup namespaces can hide the host path. The visible root is still sampled below. + if [[ "$cg" = /* && "$cg" != *"/.."* ]] && [ -d "/sys/fs/cgroup$cg" ]; then + cgdir="/sys/fs/cgroup${cg%/}" + while [[ "$cgdir" = /sys/fs/cgroup* ]]; do + cgroups["$cgdir"]=1 + [ "$cgdir" != /sys/fs/cgroup ] || break + cgdir="${cgdir%/*}" + done + else + echo "Process cgroup not visible in this namespace: $cg" + fi + done < <(pgrep -x cardano-node || true) + + echo "--- HOST CPU PRESSURE ---" + if [ -r /proc/pressure/cpu ]; then cat /proc/pressure/cpu; fi + for cgdir in "${!cgroups[@]}"; do + for metric in cpu.max cpu.stat cpu.pressure memory.events; do + if [ -r "$cgdir/$metric" ]; then + echo "--- CGROUP $cgdir/$metric (counters are cumulative) ---" + cat "$cgdir/$metric" || true + fi + done + done + + # Poll configured local Prometheus ports, not guessed port offsets. Missing/older metrics + # endpoints are harmless; never let a slow endpoint stall the monitoring loop indefinitely. + for config in "$workdir"/state-cluster*/config-*.json; do + [ -f "$config" ] || continue + while read -r port; do + echo "--- NODE GC/CPU METRICS $config (port $port) ---" + curl --fail --silent --show-error --max-time 2 "http://127.0.0.1:$port/metrics" | + grep -Ei '^[a-zA-Z_:][a-zA-Z0-9_:]*(gc|heap|cpu|mutator|alloc|pause)[a-zA-Z0-9_:]*({|[[:space:]])' || true + done < <(jq -r '[ + (.hasPrometheus?[1]? // empty), + (.TraceOptions[]?.backends[]? | strings | + capture("^PrometheusSimple [^ ]+ (?[0-9]+)$")? | .port | tonumber) + ] | unique[] | select(type == "number") | + select(. > 0 and . < 65536 and floor == .)' "$config" 2>/dev/null) + done +} diff --git a/runner/regression.sh b/runner/regression.sh index 0a495bc55..92dbd3dd9 100755 --- a/runner/regression.sh +++ b/runner/regression.sh @@ -44,6 +44,13 @@ fi # there. assert_deselect_file || exit 3 +# Validate before stopping clusters or clearing artifacts. +MONITOR_INTERVAL="${MONITOR_INTERVAL:-60}" +if ! [[ "$MONITOR_INTERVAL" =~ ^[1-9][0-9]*$ ]]; then + echo "MONITOR_INTERVAL must be a positive integer number of seconds." >&2 + exit 3 +fi + # Categorize `.bin` entries. Usable executables take priority on PATH. Entries # that PATH lookup cannot use (no exec bit, directories, dangling symlinks) # are merely ignored. An executable regular file that is not a usable binary @@ -345,7 +352,7 @@ echo "::endgroup::" # end group for "Script setup" echo "::group::Nix env setup" printf "start: %(%H:%M:%S)T\n" -1 -# Function to monitor system resources and log them every 10 minutes +# Function to monitor host/node resources at the configured sampling interval. monitor_system() { # Drop the inherited workdir lock FD so this background subshell does not # keep the lock held if it outlives the parent script. @@ -359,6 +366,9 @@ monitor_system() { set +e # don't exit on error in this monitoring loop, just log the error and keep going trap - ERR EXIT SIGINT # reset traps in this subshell so they don't interfere with the main script's traps + # shellcheck disable=SC1091 + . runner/monitor_resources.sh + while true; do { echo "===== $(date) =====" @@ -368,10 +378,11 @@ monitor_system() { free -h echo "--- DISK ---" df -h . + monitor_node_resources "$WORKDIR" echo } >> "$monitor_log" 2>&1 - sleep 600 # 10 minutes + sleep "$MONITOR_INTERVAL" done }