[PATCH BlueZ v1 03/11] test: functional: report what a test is waiting for

[Luiz Augusto von Dentz <luiz.dentz@gmail.com>]

From: Luiz Augusto von Dentz <luiz.von.dentz@intel.com>

A test that is stuck gives no clue about what it is waiting for until it
times out, which makes it hard to tell a slow test from a hung one.

Report the calls that take too long, along with how much of their
timeout is left. When the terminal can be updated in place the report is
refreshed as it goes and erased once the call completes, so only the
waits that are actually slow are visible. The workers of pytest-xdist
share the terminal, and none of them can update a line of its own, so
they report whole lines instead, prefixed with the worker they come
from.

The report goes to the terminal directly, as pytest captures the output
at file descriptor level, and is disabled when there is none, e.g. under
CI, or with --progress=no.

Assisted-by: opencode:claude-opus-5
---
 test/functional/conftest.py | 201 ++++++++++++++++++++++++++++++++++++
 1 file changed, 201 insertions(+)

diff --git a/test/functional/conftest.py b/test/functional/conftest.py
index ce6301319031..4e0bda882de3 100644
--- a/test/functional/conftest.py
+++ b/test/functional/conftest.py
@@ -2,9 +2,14 @@
 # SPDX-License-Identifier: GPL-2.0-or-later
 import os
 import re
+import sys
+import threading
+import time
 from pathlib import Path
 import pytest
 
+from pytest_bluezenv import rpc, utils
+
 from .le_utils import host_setup_is_le, pair_le
 
 
@@ -15,15 +20,211 @@ def pytest_addoption(parser):
         default=None,
         help=("List tests"),
     )
+    parser.addoption(
+        "--progress",
+        action="store",
+        default=None,
+        choices=["yes", "no"],
+        help=("Show what a test is waiting for (default: yes on a tty)"),
+    )
+
+
+# Wait for this long before reporting what a call is waiting for, so the
+# calls that complete right away do not produce any output
+PROGRESS_DELAY = 1.0
+PROGRESS_INTERVAL = 0.25
+
+# When the line cannot be updated in place the report is repeated at this
+# interval instead, and only once the call is taking clearly too long
+PROGRESS_LINE_DELAY = 5.0
+PROGRESS_LINE_INTERVAL = 10.0
+
+PROGRESS_STREAM = None
+
+
+class Status:
+    """
+    Status line telling what a test is waiting for, updated in place by
+    the terminal reporter of pytest so the report it writes itself is
+    left alone.
+    """
+
+    def __init__(self, reporter):
+        self.reporter = reporter
+        self.shown = False
+
+    def show(self, text):
+        # Leave the line pytest is on, so what it reports there is not
+        # overwritten by the status. Nothing is written when the line
+        # is already one of ours.
+        if not self.shown:
+            self.reporter.ensure_newline()
+            self.shown = True
+
+        self.reporter.rewrite(text, erase=True, light=True)
+
+    def clear(self):
+        if not self.shown:
+            return
+
+        self.reporter.rewrite("", erase=True)
+        self.shown = False
+
+
+def _progress_desc(name, method, a):
+    """
+    Describe what a call is waiting for, e.g.
+
+        host.0.1: pexpect.expect 'Pairing successful'
+    """
+    if method == "call_plugin" and len(a) > 1:
+        plugin, func, args = a[0], a[1], a[2:]
+
+        # Drop the identifier of the spawned process, if any
+        if args and isinstance(args[0], int):
+            args = args[1:]
+
+        desc = f"{plugin}.{func}"
+    else:
+        desc, args = str(method), a
+
+    if args:
+        arg = args[0]
+        # Calls running something on a host pass the function itself
+        arg = getattr(arg, "__name__", None) or str(arg)
+        if len(arg) > 60:
+            arg = arg[:57] + "..."
+        desc = f"{desc} {arg!r}"
+
+    return f"{name}: {desc}" if name else desc
+
+
+def _progress_status(elapsed, timeout):
+    if timeout:
+        left = max(0.0, timeout - elapsed)
+        return f"{elapsed:.0f}s, {left:.0f}s left"
+
+    return f"{elapsed:.0f}s"
+
+
+def _progress_run(status, desc, timeout, done, stream=None, prefix=""):
+    start = time.monotonic()
+    next_line = PROGRESS_LINE_DELAY
+
+    while not done.wait(PROGRESS_INTERVAL if status else 0.5):
+        elapsed = time.monotonic() - start
+
+        if status:
+            if elapsed < PROGRESS_DELAY:
+                continue
+
+            status.show(f"waiting {desc} [{_progress_status(elapsed, timeout)}]")
+            continue
+
+        # The line cannot be updated in place, so report it as it goes
+        if elapsed < next_line:
+            continue
+
+        next_line = elapsed + PROGRESS_LINE_INTERVAL
+        stream.write(
+            f"{prefix}waiting {desc}" f" [{_progress_status(elapsed, timeout)}]\n"
+        )
+        stream.flush()
+
+    if status:
+        status.clear()
+
+
+def _progress_call(orig, status=None, stream=None, prefix=""):
+    def call(self, method, *a, **kw):
+        # The timeout of the calls waiting for something on a host is the
+        # one used by the plugin serving them
+        timeout = kw.get("timeout")
+        if not timeout and method == "call_plugin" and "expect" in a[:2]:
+            timeout = utils.DEFAULT_TIMEOUT
+
+        name = getattr(self.log, "name", "")
+        name = name[len("rpc.") :] if name.startswith("rpc.") else ""
+
+        done = threading.Event()
+        progress = threading.Thread(
+            target=_progress_run,
+            args=(status, _progress_desc(name, method, a), timeout, done),
+            kwargs={"stream": stream, "prefix": prefix},
+            daemon=True,
+        )
+        progress.start()
+
+        try:
+            return orig(self, method, *a, **kw)
+        finally:
+            done.set()
+            progress.join()
+
+    return call
+
+
+def _setup_progress(config):
+    """
+    Report what a test is waiting for, so it is possible to tell when one
+    is taking longer than it should.
+    """
+    global PROGRESS_STREAM
+
+    if config.option.progress == "no":
+        return
+
+    # The workers of pytest-xdist run in their own process and share the
+    # terminal with each other and with the controller reporting the
+    # results, so none of them can update a line of its own: report the
+    # calls taking too long as whole lines instead
+    worker = getattr(config, "workerinput", None)
+
+    if not worker:
+        reporter = config.pluginmanager.get_plugin("terminalreporter")
+
+        # No markup means no terminal to update a line on, e.g. when the
+        # output is redirected or under CI
+        if not reporter or not reporter.hasmarkup:
+            return
+
+        rpc.Connection.call = _progress_call(
+            rpc.Connection.call, status=Status(reporter)
+        )
+        return
+
+    # The output of a worker is captured at file descriptor level and
+    # forwarded to the controller, so it goes to the terminal directly
+    try:
+        PROGRESS_STREAM = open("/dev/tty", "w", buffering=1)
+    except OSError:
+        # Not running from a terminal, e.g. under CI
+        return
+
+    rpc.Connection.call = _progress_call(
+        rpc.Connection.call,
+        stream=PROGRESS_STREAM,
+        prefix=f"[{worker['workerid']}] ",
+    )
 
 
 def pytest_configure(config):
+    _setup_progress(config)
+
     if config.option.list:
         config.option.reportchars = "A"
         config.option.no_header = True
         config.option.verbose = -2
 
 
+def pytest_unconfigure(config):
+    global PROGRESS_STREAM
+
+    if PROGRESS_STREAM:
+        PROGRESS_STREAM.close()
+        PROGRESS_STREAM = None
+
+
 COLLECT_ERRORS = []
 
 
-- 
2.55.0