From db652485a887a69c78fc86b56e822604f1511f6c Mon Sep 17 00:00:00 2001 From: raiden00pl Date: Sat, 10 Oct 2026 09:22:49 +0200 Subject: [PATCH 1/2] device: report a slow command as TIMEOUT, not flood Only mark the device as flooding when its output never stops after the command timeout. Output that still arrives at the timeout but then goes quiet is just a slow command. Signed-off-by: raiden00pl --- src/ntfc/device/common.py | 19 ++++++++++++++----- tests/device/test_common.py | 32 ++++++++++++++++++++++++++++++++ 2 files changed, 46 insertions(+), 5 deletions(-) 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" From d95f639aa271de5b727e9ebb6d5840ce46325215 Mon Sep 17 00:00:00 2001 From: raiden00pl Date: Sat, 10 Oct 2026 10:04:22 +0200 Subject: [PATCH 2/2] command_builder: anchor the match_all lookahead pattern Unanchored (?=.*X) lookaheads are retried at every buffer position and each scans to the end, so one search over a 100 KB console dump took seconds and large outputs such as help timed out. Signed-off-by: raiden00pl --- src/ntfc/command_builder.py | 6 +++++- tests/test_command_builder.py | 26 ++++++++++++++++++++++++-- 2 files changed, 29 insertions(+), 3 deletions(-) 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/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> ")