mirror of
https://github.com/espressif/esp-idf.git
synced 2026-10-02 03:00:34 +03:00
ci(tools): Keep Windows build-system work dir short and logs off the live log
Relative CI_PROJECT_DIR after cd nested --work-dir under tools/test_build_system and blew MAX_PATH. Save failed-command output next to artifacts instead of streaming a 12 KB record that still hangs shard 3/6. Co-authored-by: Cursor <cursoragent@cursor.com>
This commit is contained in:
@@ -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
|
||||
|
||||
@@ -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
|
||||
@@ -186,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}')
|
||||
|
||||
@@ -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',
|
||||
|
||||
@@ -19,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',
|
||||
@@ -29,44 +33,23 @@ _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
|
||||
|
||||
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)
|
||||
return lines
|
||||
|
||||
|
||||
def _log_process_failure(
|
||||
@@ -75,13 +58,14 @@ def _log_process_failure(
|
||||
workdir: Path | str,
|
||||
error: subprocess.CalledProcessError,
|
||||
) -> None:
|
||||
"""Save the untouched output to files, then log one clipped record.
|
||||
"""Save the untouched output to files, then log paths and failure lines.
|
||||
|
||||
The files keep the whole output available whatever the failure is, so the
|
||||
clipped record no longer has to carry everything needed to debug it. Writing
|
||||
them before logging also means the output survives a stalled live log.
|
||||
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.
|
||||
"""
|
||||
log_dir = Path(workdir) / 'failed_command_logs'
|
||||
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)
|
||||
@@ -99,8 +83,10 @@ def _log_process_failure(
|
||||
]
|
||||
for stream_name, output_path in saved_paths.items():
|
||||
message.append(f'Full {stream_name}: {output_path}')
|
||||
message.append(f'Stdout: {_clip_log_output(error.stdout)}')
|
||||
message.append(f'Stderr: {_clip_log_output(error.stderr)}')
|
||||
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))
|
||||
|
||||
|
||||
|
||||
@@ -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')
|
||||
|
||||
Reference in New Issue
Block a user