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/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 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..6eeb5d6f7 --- /dev/null +++ b/framework_tests/test_submit_api.py @@ -0,0 +1,176 @@ +"""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, caplog: pytest.LogCaptureFixture) -> None: + """Stop rather than sleep beyond the budget, retaining the 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 + + +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() 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 }