diff --git a/src/ntfc/command_builder.py b/src/ntfc/command_builder.py index 018eafa..3435bdb 100644 --- a/src/ntfc/command_builder.py +++ b/src/ntfc/command_builder.py @@ -198,7 +198,11 @@ def _build_expect_pattern( items = expects if regexp else [re.escape(e) for e in expects] if match_all: - return "".join(f"(?=.*{item})" for item in items) + # Anchor the lookaheads so the engine evaluates them once from + # the start of the buffer. Unanchored, re.search retries them + # at every position and each scans to the end: quadratic in + # the buffer size, tens of seconds on a 100 KB console dump. + return "^" + "".join(f"(?=.*{item})" for item in items) return rf"({'|'.join(items)})" def _default_prompt_pattern(self, cmd: str, flag: str = "") -> str: diff --git a/src/ntfc/device/common.py b/src/ntfc/device/common.py index d4d3dfc..922f507 100644 --- a/src/ntfc/device/common.py +++ b/src/ntfc/device/common.py @@ -52,6 +52,7 @@ class DeviceCommon(ABC): _BUSY_LOOP_TIMEOUT = 180 # 180 sec with no data read from target _OUTPUT_TAIL_MAX = 4 * 1024 * 1024 + _FLOOD_DETECT_TIME = 10 # sec of uninterrupted output after a timeout def __init__(self, conf: "CoreConfig", echo: bool = True): """Initialize common device.""" @@ -306,15 +307,23 @@ def _read_until_pattern_loop( # noqa: C901 break # check for output flood condition. - # If we still get some data from dev, its possible that we stuck - # in some command + # A slow command can still be printing when the timeout expires, + # so keep reading until the device goes quiet. Only a device that + # never stops printing is flooding (stuck in some command). if ret == CmdStatus.TIMEOUT: - chunk = self._read_all(0.1) - if len(chunk) > 0: + flood_end = time.time() + self._FLOOD_DETECT_TIME + flood = True + while time.time() < flood_end: + chunk = self._read_all(self._read_all_sleep) + self._console_log(chunk) + if not chunk: + flood = False + break + + if flood: if not self._state_mgr.is_unhealthy(): self._log_device_event("fault detected: flood") self._state_mgr.set_unhealthy("Flood detected") - self._console_log(chunk) return CmdReturn(ret, _match, output.decode("utf-8", errors="replace")) diff --git a/tests/device/test_common.py b/tests/device/test_common.py index 80c810e..82c575f 100644 --- a/tests/device/test_common.py +++ b/tests/device/test_common.py @@ -20,6 +20,7 @@ import os import tempfile +import time from types import SimpleNamespace from unittest.mock import patch @@ -29,6 +30,7 @@ from ntfc.log.handler import LogHandler g_mock_read = b"" +g_mock_read_until = None class DeviceMock(DeviceCommon): @@ -44,6 +46,8 @@ def __init__(self, config): def _read(self, _=0): """Mock.""" + if g_mock_read_until is not None and time.time() > g_mock_read_until: + return b"" return g_mock_read def _write(self, _): @@ -120,6 +124,7 @@ def test_device_common_send_cmd_pattern(): config = mockdevice.return_value dev = DeviceMock(config) + dev._FLOOD_DETECT_TIME = 0.5 assert dev is not None assert dev.flood is False @@ -152,6 +157,31 @@ def test_device_common_send_cmd_pattern(): assert ret.status == CmdStatus.TIMEOUT +def test_device_common_slow_output_is_timeout_not_flood(): + """Output that still arrives at the timeout but then stops is a TIMEOUT.""" + with patch("ntfc.envconfig.EnvConfig") as mockdevice: + + global g_mock_read, g_mock_read_until + + config = mockdevice.return_value + config.read_poll_interval = 0.05 + dev = DeviceMock(config) + dev._dev_is_health_priv = lambda: True + + # the device keeps printing for 0.5s past the 1s command timeout + # and then goes quiet: a slow command, not a stuck one + g_mock_read = b"x" * 100 + g_mock_read_until = time.time() + 1.5 + try: + ret = dev.send_cmd_read_until_pattern(b"", b"y", 1) + finally: + g_mock_read_until = None + + assert ret.status == CmdStatus.TIMEOUT + assert dev.flood is False + assert dev.dev_is_health() is True + + def test_device_common_send_cmd_fail_pattern(): with patch("ntfc.envconfig.EnvConfig") as mockdevice: @@ -160,6 +190,7 @@ def test_device_common_send_cmd_fail_pattern(): config = mockdevice.return_value dev = DeviceMock(config) + dev._FLOOD_DETECT_TIME = 0.5 # fail_pattern detected before success pattern → FAILED, exits early g_mock_read = b"ERROR: something bad" @@ -211,6 +242,7 @@ def test_device_common_read_until_pattern(): config = mockdevice.return_value dev = DeviceMock(config) + dev._FLOOD_DETECT_TIME = 0.5 # success: pattern found in output g_mock_read = b"PASS: all tests ok" diff --git a/tests/test_command_builder.py b/tests/test_command_builder.py index 29c4a76..7aa180b 100644 --- a/tests/test_command_builder.py +++ b/tests/test_command_builder.py @@ -19,6 +19,7 @@ ############################################################################ import re +import time import pytest @@ -61,11 +62,11 @@ def test_build_expect_pattern(builder: CommandBuilder) -> None: ) assert ( builder._build_expect_pattern(["aaa", "bbb"], True, False) - == "(?=.*aaa)(?=.*bbb)" + == "^(?=.*aaa)(?=.*bbb)" ) assert ( builder._build_expect_pattern(["aaa", "bbb"], True, True) - == "(?=.*aaa)(?=.*bbb)" + == "^(?=.*aaa)(?=.*bbb)" ) assert ( builder._build_expect_pattern(["aaa", "bbb"], False, True) @@ -100,6 +101,27 @@ def test_prepare_pattern_with_expects(builder: CommandBuilder) -> None: assert re.search(p2, "cmd: command not found") +def test_prepare_pattern_match_all_is_linear(builder: CommandBuilder) -> None: + """A match_all pattern must not scan the buffer once per position.""" + p = builder._prepare_pattern( + "popen", ["Calling pclose()"], "", True, False + ) + # a device dumping thousands of builtin names before the expected line + buf = " ltp_some_test_case_name_padded_to_width\n" * 5000 + assert len(buf) > 200000 + + t0 = time.time() + assert re.search(p, buf) is None + assert time.time() - t0 < 0.5 + + assert re.search(p, buf + "Calling pclose()\n") + assert re.search(p, buf + "popen: command not found\n") + + p2 = builder._prepare_pattern("cmd", ["A", "B"], "", True, False) + assert re.search(p2, buf + "B\n" + buf + "A\n") + assert re.search(p2, buf + "A\n") is None + + def test_prepare_pattern_without_expects(builder: CommandBuilder) -> None: p = builder._prepare_pattern("cmd", None, "", True, False) assert re.search(p, "nsh> ")