Merge branch 'fix/win_tests' into 'master'

Fix Windows build system timeouts by saving failed command output to files

See merge request espressif/esp-idf!52502

.gitlab/ci/test-win.yml

@@ -55,7 +55,9 @@ test_tools_win:
 # Build tests
 .test_build_system_template_win:
   extends: .host_test_win_template
-  timeout: 4 hours
+  # Shard 6/6 can take ~2h1m on master; 2h is too tight. 3h still cuts the
+  # 4h freeze cost without failing a healthy long shard.
+  timeout: 3 hours
   artifacts:
     paths:
       - XUNIT_RESULT.xml
@@ -65,9 +67,13 @@ test_tools_win:
     reports:
       junit: XUNIT_RESULT.xml
   script:
+    # CI_PROJECT_DIR is relative on these runners (builds/espressif/esp-idf), so it
+    # cannot be used after cd. The job starts in the directory artifact paths are
+    # relative to, so record it before cd and build absolute paths from it.
+    - $Env:IDF_TEST_PROJECT_DIR = (Get-Location).Path
     - cd tools\test_build_system
     - idf-ci gitlab download-known-failure-cases-file ${KNOWN_FAILURE_CASES_FILE_NAME}
-    - pytest --parallel-count ${CI_NODE_TOTAL} --parallel-index ${CI_NODE_INDEX} --junitxml=${CI_PROJECT_DIR}\XUNIT_RESULT.xml --ignore-result-files ${KNOWN_FAILURE_CASES_FILE_NAME} --durations=10
+    - pytest --parallel-count ${CI_NODE_TOTAL} --parallel-index ${CI_NODE_INDEX} --work-dir "$Env:IDF_TEST_PROJECT_DIR\test_build_system" --junitxml="$Env:IDF_TEST_PROJECT_DIR\XUNIT_RESULT.xml" --ignore-result-files ${KNOWN_FAILURE_CASES_FILE_NAME} --durations=10
 
 pytest_build_system_win:
   extends:
@@ -91,9 +97,10 @@ pytest_build_system_win_minimal_cmake:
         Write-Error "ERROR: Wrong CMake version! Detected: $actualVersion, but expected: $Env:MINIMAL_CMAKE_VERSION"
         exit 1
       }
+    - $Env:IDF_TEST_PROJECT_DIR = (Get-Location).Path
     - cd tools\test_build_system
     - idf-ci gitlab download-known-failure-cases-file ${KNOWN_FAILURE_CASES_FILE_NAME}
-    - pytest -k cmake --junitxml=${CI_PROJECT_DIR}\XUNIT_RESULT.xml --ignore-result-files ${KNOWN_FAILURE_CASES_FILE_NAME} --durations=10
+    - pytest -k cmake --work-dir "$Env:IDF_TEST_PROJECT_DIR\test_build_system" --junitxml="$Env:IDF_TEST_PROJECT_DIR\XUNIT_RESULT.xml" --ignore-result-files ${KNOWN_FAILURE_CASES_FILE_NAME} --durations=10
 
 pytest_buildv2_system_win:
   extends:
@@ -101,11 +108,13 @@ pytest_buildv2_system_win:
     - .rules:labels:buildv2
   parallel: 6
   script:
+    - $Env:IDF_TEST_PROJECT_DIR = (Get-Location).Path
     - cd tools\test_build_system
     - idf-ci gitlab download-known-failure-cases-file ${KNOWN_FAILURE_CASES_FILE_NAME}
     - pytest
       --buildv2
       --parallel-count ${CI_NODE_TOTAL}
       --parallel-index ${CI_NODE_INDEX}
-      --junitxml=${CI_PROJECT_DIR}\XUNIT_RESULT.xml
+      --work-dir "$Env:IDF_TEST_PROJECT_DIR\test_build_system"
+      --junitxml="$Env:IDF_TEST_PROJECT_DIR\XUNIT_RESULT.xml"
       --ignore-result-files ${KNOWN_FAILURE_CASES_FILE_NAME}

tools/test_build_system/README.md

@@ -31,7 +31,7 @@ If you are working on a bug fix or a feature and one of the tests starts to fail
 
 1. Find the name of the failing test in the CI job log
 1. Follow the steps in the section above to run that one test
-1. By default, the fixtures which create temporary directories will remove them after the test. To prevent the directories from being removed, run `pytest` with `--work-dir /some/path` flag. The temporary directories will be created under `/some/path`, and you will be able to inspect them once the test fails.
+1. By default, the fixtures which create temporary directories will remove them after the test. To prevent the directories from being removed, run `pytest` with `--work-dir /some/path` flag. The temporary directories will be created under `/some/path`, and you will be able to inspect them once the test fails. Failed `idf.py` / `cmake` output is also written to `failed_command_logs/` under that work directory.
 1. You can increase the logging level to see the commands being executed by the test by running `pytest` with `--log-cli-level DEBUG` argument.
 
 ## Adding new tests

tools/test_build_system/conftest.py

@@ -15,6 +15,7 @@ from _pytest.fixtures import FixtureRequest
 from _pytest.main import Session
 from _pytest.nodes import Item
 from test_build_system_helpers import EXT_IDF_PATH
+from test_build_system_helpers import FAILED_COMMAND_LOG_DIR_ENV
 from test_build_system_helpers import EnvDict
 from test_build_system_helpers import IdfPyFunc
 from test_build_system_helpers import get_idf_build_env
@@ -36,7 +37,31 @@ def _get_git_submodule_paths(repo_path: Path) -> list[str]:
     return submodule_paths
 
 
-def _create_idf_copy_via_worktree(path_from: Path, path_to: Path) -> str:
+def _is_materialized_submodule(path: Path) -> bool:
+    """Whether path holds submodule content rather than a placeholder.
+
+    ``git worktree add`` leaves a submodule as an empty directory or as a
+    gitlink file, and both are unusable as component sources.
+    """
+    try:
+        return path.is_dir() and any(path.iterdir())
+    except OSError:
+        return False
+
+
+def _copy_submodule(src_submodule: Path, dst_submodule: Path) -> None:
+    """Replace the worktree placeholder with the submodule content of the source repo."""
+    # rmtree() cannot remove a gitlink file (even with ignore_errors=True), and
+    # copytree() would then leave a file where CMake expects a directory
+    # (e.g. mbedtls/include).
+    if dst_submodule.is_file() or dst_submodule.is_symlink():
+        dst_submodule.unlink()
+    elif dst_submodule.exists():
+        shutil.rmtree(dst_submodule)
+    shutil.copytree(src_submodule, dst_submodule, symlinks=True, ignore=shutil.ignore_patterns('.git'))
+
+
+def _create_idf_copy_via_worktree(path_from: Path, path_to: Path) -> str | None:
     """
     Create IDF copy using git worktree (fast) + copying submodule directories.
 
@@ -45,6 +70,12 @@ def _create_idf_copy_via_worktree(path_from: Path, path_to: Path) -> str:
     repo (which has them already checked out) instead of running git submodule
     update (which can fail due to auth issues on CI).
 
+    Return the worktree branch name, or None if a submodule could not be
+    materialized. In that case the worktree is removed again and the caller
+    creates the copy with shutil.copytree instead. Leaving a placeholder behind
+    would produce a copy that only fails once a test builds it, as a missing
+    include directory or source file of the affected component.
+
     After copying submodules, remove the worktree's top-level ``.git`` file so
     the result matches the old ``shutil.copytree`` behavior (no git repo at
     ``IDF_PATH``). Otherwise CMake's ``git_submodule_check`` runs inside the
@@ -67,18 +98,15 @@ def _create_idf_copy_via_worktree(path_from: Path, path_to: Path) -> str:
         src_submodule = path_from / submodule_rel_path
         dst_submodule = path_to / submodule_rel_path
 
-        # Only copy if the source submodule is a populated directory. A gitlink
-        # file or empty dir means the source checkout did not materialize it.
-        if src_submodule.is_dir() and any(src_submodule.iterdir()):
+        # Nothing to copy when the source checkout did not materialize the submodule.
+        if _is_materialized_submodule(src_submodule):
             logging.debug(f'copying submodule {submodule_rel_path}')
-            # Worktree submodule paths are often gitlink files; rmtree() cannot
-            # remove those (even with ignore_errors=True), and copytree() then
-            # leaves a file where CMake expects a directory (e.g. mbedtls/include).
-            if dst_submodule.is_file() or dst_submodule.is_symlink():
-                dst_submodule.unlink()
-            elif dst_submodule.exists():
-                shutil.rmtree(dst_submodule)
-            shutil.copytree(src_submodule, dst_submodule, symlinks=True, ignore=shutil.ignore_patterns('.git'))
+            _copy_submodule(src_submodule, dst_submodule)
+
+        if not _is_materialized_submodule(dst_submodule):
+            logging.warning(f'submodule {submodule_rel_path} could not be copied into {path_to}')
+            _cleanup_worktree(path_from, path_to, branch_name)
+            return None
 
     # Match old shutil-based idf_copy: no top-level .git (see docstring above).
     (path_to / '.git').unlink(missing_ok=True)
@@ -159,21 +187,33 @@ def pytest_addoption(parser: pytest.Parser) -> None:
 @pytest.fixture(scope='session')
 def _session_work_dir(request: FixtureRequest) -> typing.Generator[tuple[Path, bool], None, None]:
     work_dir = request.config.getoption('--work-dir')
+    previous_log_dir = os.environ.get(FAILED_COMMAND_LOG_DIR_ENV)
 
     if work_dir:
-        work_dir = os.path.join(work_dir, datetime.datetime.now(datetime.timezone.utc).strftime('%Y-%m-%d_%H-%M-%S'))
-        logging.debug(f'using work directory: {work_dir}')
-        os.makedirs(work_dir, exist_ok=True)
+        # resolve allows using relative paths with --work-dir option
+        work_dir_path = Path(work_dir).resolve() / datetime.datetime.now(datetime.timezone.utc).strftime(
+            '%Y-%m-%d_%H-%M-%S'
+        )
+        logging.debug(f'using work directory: {work_dir_path}')
+        os.makedirs(work_dir_path, exist_ok=True)
         clean_dir = None
         is_temp_dir = False
     else:
-        work_dir = mkdtemp()
-        logging.debug(f'created temporary work directory: {work_dir}')
-        clean_dir = work_dir
+        work_dir_path = Path(mkdtemp()).resolve()
+        logging.debug(f'created temporary work directory: {work_dir_path}')
+        clean_dir = work_dir_path
         is_temp_dir = True
 
-    # resolve allows using relative paths with --work-dir option
-    yield Path(work_dir).resolve(), is_temp_dir
+    log_dir = work_dir_path / 'failed_command_logs'
+    log_dir.mkdir(parents=True, exist_ok=True)
+    os.environ[FAILED_COMMAND_LOG_DIR_ENV] = str(log_dir)
+
+    yield work_dir_path, is_temp_dir
+
+    if previous_log_dir is None:
+        os.environ.pop(FAILED_COMMAND_LOG_DIR_ENV, None)
+    else:
+        os.environ[FAILED_COMMAND_LOG_DIR_ENV] = previous_log_dir
 
     if clean_dir:
         logging.debug(f'cleaning up {clean_dir}')
@@ -310,6 +350,8 @@ def idf_copy(func_work_dir: Path, request: FixtureRequest) -> typing.Generator[P
         # Clean up any partial worktree before fallback
         if path_to.exists():
             shutil.rmtree(path_to, ignore_errors=True)
+
+    if branch_name is None:
         _create_idf_copy_via_shutil(path_from, path_to)
 
     os.environ['IDF_PATH'] = str(path_to)

tools/test_build_system/test_build_system_helpers/__init__.py

@@ -13,6 +13,7 @@ from .file_utils import bin_files_differ
 from .file_utils import file_contains
 from .file_utils import replace_in_file
 from .idf_utils import EXT_IDF_PATH
+from .idf_utils import FAILED_COMMAND_LOG_DIR_ENV
 from .idf_utils import EnvDict
 from .idf_utils import IdfPyFunc
 from .idf_utils import find_python
@@ -33,6 +34,7 @@ __all__ = [
     'run_idf_py',
     'EXT_IDF_PATH',
     'EnvDict',
+    'FAILED_COMMAND_LOG_DIR_ENV',
     'IdfPyFunc',
     'Snapshot',
     'get_snapshot',

tools/test_build_system/test_build_system_helpers/idf_utils.py

@@ -6,6 +6,7 @@ import shutil
 import subprocess
 import sys
 import typing
+import uuid
 from pathlib import Path
 
 try:
@@ -18,6 +19,10 @@ except KeyError:
 EnvDict = dict[str, str]
 IdfPyFunc = typing.Callable[..., subprocess.CompletedProcess]
 
+# Session fixture in conftest.py sets this to the pytest --work-dir tree so
+# failed-command files survive --cleanup-idf-copy of the app directory.
+FAILED_COMMAND_LOG_DIR_ENV = 'IDF_TEST_FAILED_COMMAND_LOG_DIR'
+
 
 _LOG_ERROR_MARKERS = (
     'CMake Error',
@@ -28,44 +33,61 @@ _LOG_ERROR_MARKERS = (
 )
 
 
-def _clip_log_output(text: str | None, max_lines: int = 80, max_line_len: int = 400) -> str:
-    """Last ``max_lines`` of process output for logging, plus failure lines.
+def _shorten_log_line(line: str, max_line_len: int = 200) -> str:
+    if len(line) <= max_line_len:
+        return line
+    return line[:max_line_len] + f'... [{len(line) - max_line_len} chars omitted]'
 
-    pytest.ini enables ``log_cli``, so ``logging.error(full_stdout)`` after a
-    failed build is one record. On Windows CI that live-log can stall for hours
-    even when the line count is small: CMake's ``-- Component paths:`` line is
-    a single multi-KB (sometimes multi-MB) string.
-    """
+
+def _failure_lines(text: str | None, max_lines: int = 20) -> list[str]:
+    """Marker lines only. Do not send build tails over the CI live log."""
     if not text:
-        return ''
-    lines = text.splitlines()
-
-    def _short(line: str) -> str:
-        if len(line) <= max_line_len:
-            return line
-        return line[:max_line_len] + f'... [{len(line) - max_line_len} chars omitted]'
-
-    omitted = max(0, len(lines) - max_lines)
-    tail_start = len(lines) - max_lines if omitted else 0
-    tail = lines[tail_start:]
-
-    failures: list[str] = []
-    for idx, line in enumerate(lines):
-        if idx >= tail_start:
-            break
+        return []
+    lines: list[str] = []
+    for line in text.splitlines():
         if any(marker in line for marker in _LOG_ERROR_MARKERS):
-            failures.append(line)
-            if len(failures) >= 40:
+            lines.append(_shorten_log_line(line))
+            if len(lines) >= max_lines:
                 break
+    return lines
 
-    parts: list[str] = []
-    if failures:
-        parts.append('[... failure lines ...]')
-        parts.extend(_short(line) for line in failures)
-    if omitted:
-        parts.append(f'[... {omitted} lines omitted ...]')
-    parts.extend(_short(line) for line in tail)
-    return '\n'.join(parts)
+
+def _log_process_failure(
+    command_name: str,
+    cmd: list[str],
+    workdir: Path | str,
+    error: subprocess.CalledProcessError,
+) -> None:
+    """Save the untouched output to files, then log paths and failure lines.
+
+    The files keep the whole output. The live log only names those files and
+    repeats a few marker lines: a 12 KB record of clipped stdout still hangs
+    Windows CI the same way an unclipped one did.
+    """
+    env_log_dir = os.environ.get(FAILED_COMMAND_LOG_DIR_ENV)
+    log_dir = Path(env_log_dir) if env_log_dir else Path(workdir) / 'failed_command_logs'
+    saved_paths: dict[str, Path] = {}
+    try:
+        log_dir.mkdir(parents=True, exist_ok=True)
+        prefix = f'{command_name}_{uuid.uuid4().hex}'
+        for stream_name, output in (('stdout', error.stdout), ('stderr', error.stderr)):
+            output_path = log_dir / f'{prefix}.{stream_name}.txt'
+            output_path.write_text(output or '', encoding='utf-8')
+            saved_paths[stream_name] = output_path
+    except OSError as write_error:
+        logging.error('Full output of the failed command could not be saved: %s', write_error)
+
+    message = [
+        f'The following {command_name} command has failed: {" ".join(cmd)}',
+        f'Working directory: {workdir}',
+    ]
+    for stream_name, output_path in saved_paths.items():
+        message.append(f'Full {stream_name}: {output_path}')
+    failure_lines = _failure_lines(error.stdout) + _failure_lines(error.stderr)
+    if failure_lines:
+        message.append('Failure lines:')
+        message.extend(failure_lines)
+    logging.error('\n'.join(message))
 
 
 def normalize_output(text: str) -> str:
@@ -155,10 +177,7 @@ def run_idf_py(
             input=input_str,
         )
     except subprocess.CalledProcessError as e:
-        logging.error('The following idf.py command has failed: {}'.format(' '.join(cmd)))
-        logging.error(f'Working directory: {workdir}')
-        logging.error(f'Stdout: {_clip_log_output(e.stdout)}')
-        logging.error(f'Stderr: {_clip_log_output(e.stderr)}')
+        _log_process_failure('idf.py', cmd, workdir, e)
         raise
 
 
@@ -200,10 +219,7 @@ def run_cmake(
             errors='backslashreplace',
         )
     except subprocess.CalledProcessError as e:
-        logging.error('The following cmake command has failed: {}'.format(' '.join(cmd)))
-        logging.error(f'Working directory: {workdir}')
-        logging.error(f'Stdout: {_clip_log_output(e.stdout)}')
-        logging.error(f'Stderr: {_clip_log_output(e.stderr)}')
+        _log_process_failure('cmake', cmd, build_dir, e)
         raise
 
 

tools/test_build_system/test_common.py

@@ -6,7 +6,6 @@ import os
 import re
 import shutil
 import stat
-import subprocess
 import sys
 import textwrap
 from pathlib import Path
@@ -95,13 +94,16 @@ def test_hints_no_color_output_when_noninteractive(idf_py: IdfPyFunc) -> None:
         'main/build_test_app.c', '// placeholder_inside_main', 'esp_chip_info_t chip_info; esp_chip_info(&chip_info);'
     )
 
-    with pytest.raises(subprocess.CalledProcessError) as exc_info:
-        idf_py('build')
+    # Expected failure: do not go through run_idf_py(check=True). That path
+    # still has to write one logging.error record, and on Windows CI that write
+    # is what hangs shard 3/6 after this test.
+    ret = idf_py('build', check=False)
 
     # the shared esp_pylib logger drops color escape sequences on
     # non-interactive (non-TTY) output, so the hint appears without any ANSI color codes.
-    assert 'esp_chip_info.h' in exc_info.value.stdout
-    assert '\x1b[' not in exc_info.value.stdout
+    assert ret.returncode != 0
+    assert 'esp_chip_info.h' in ret.stdout
+    assert '\x1b[' not in ret.stdout
 
 
 @pytest.mark.usefixtures('test_app_copy')