feat(integration-tests): Clean up logging and error reporting in integration tests.#1802
Conversation
WalkthroughThis PR introduces comprehensive logging infrastructure to the integration-tests framework, including per-run log file management, enhanced test output formatting, and updated pytest configuration. Functions across test utilities and fixtures now accept a pytest.FixtureRequest parameter to enable logging. The Changes
Estimated code review effort🎯 3 (Moderate) | ⏱️ ~20 minutes Possibly related PRs
Suggested reviewers
🚥 Pre-merge checks | ✅ 3✅ Passed checks (3 passed)
✏️ Tip: You can configure your own custom pre-merge checks in the settings. ✨ Finishing touches
🧪 Generate unit tests (beta)
Warning There were issues while running some tools. Please review the errors and either fix the tool's configuration or disable the tool if it's a critical failure. 🔧 Ruff (0.14.14)integration-tests/tests/conftest.py�[1;31mruff failed�[0m integration-tests/tests/test_identity_transformation.py�[1;31mruff failed�[0m integration-tests/tests/utils/asserting_utils.py�[1;31mruff failed�[0m
Thanks for using CodeRabbit! It's free for OSS, and your support helps us grow. If you like it, consider giving us a shout-out. Comment |
junhaoliao
left a comment
junhaoliao
left a comment
There was a problem hiding this comment.
with the understanding that this is a draft, i just took a quick look
.gitignore
Outdated
| .task/ | ||
| build/ | ||
| dist/ | ||
| __* No newline at end of file |
There was a problem hiding this comment.
what are we trying to exclude here?
There was a problem hiding this comment.
The __pytest_logs directory that stores the log file for each test run.
That being said, right now the __pytest_logs directory gets created/stored under the clp/integration-tests directory. Do you think it might be better to have it under the build/integration-tests directory instead (used for other integration test stuff as well)? Then we wouldn't have to modify this file.
There was a problem hiding this comment.
yup i agree we can move to build/
in general we want to be more explicit about what to ignore, so if we keep the folder in the current location, it would be better to just write __pytest_logs. That said, it really depends on which part of the paths we want to be fuzzy about. in general wildcards like path/*/subpath and *.log are fine in my opinion
integration-tests/.pytest.ini
Outdated
| log_cli_date_format = %Y-%m-%d %H:%M:%S,%f | ||
| log_cli_format = %(name)s %(asctime)s [%(levelname)s] %(message)s | ||
| log_cli_level = INFO | ||
| log_cli_format = %(levelname)-8s %(asctime)-25s %(message)s |
There was a problem hiding this comment.
any reason to change this? i thought we were trying to match references like
There was a problem hiding this comment.
My only reason was aesthetics, cause this is the format of the logs that will be reported to the user via the command line. If there is some reason we want to match references like you describe above, I can change it; I just wasn't aware we were doing that
integration-tests/.pytest.ini
Outdated
|
|
||
| log_file_mode = a | ||
| log_file_level = DEBUG | ||
| log_file_format = %(levelname)-8s %(asctime)-30s [%(name)s:%(filename)s:%(lineno)d]: %(message)s |
There was a problem hiding this comment.
any reason to use a different format string between the cli and the log file?
There was a problem hiding this comment.
Just to provide more information to the dev; I don't want to crowd the cli output, especially for a successful (no failure) test run. I think it's safe to assume that the main reason a dev would be looking at the test log would be if something fails, and in the event of failure, they'll need more information.
| log_cli_format = %(levelname)-8s %(asctime)-25s %(message)s | ||
| log_cli_date_format = %Y-%m-%d %H:%M:%S | ||
|
|
||
| log_file_mode = a |
There was a problem hiding this comment.
instead of appending to the same file, can isolate the logs from different test runs instead? e.g., use set_log_path with the default log_file_mode = w. see the test code at pytest-dev/pytest#4752 for example
There was a problem hiding this comment.
If this isn't here, the test output file will contain all of the pytest logging messages followed by all of the output from the various subprocesses called during the test run, like this:
INFO 2025-01-06 event1
INFO 2025-01-06 event2
INFO 2025-01-06 event3
<output following event 1>
<output following event 2>
<output following event 3>
It seems better to me to have everything written to the log file in order, so that it looks like this:
INFO 2025-01-06 event1
<output following event 1>
INFO 2025-01-06 event2
<output following event 2>
INFO 2025-01-06 event3
<output following event 3>
The logs from different test runs are already isolated by the code in conftest.py.
|
|
||
| def run_and_assert(cmd: list[str], **kwargs: Any) -> subprocess.CompletedProcess[Any]: | ||
| def run_and_assert( | ||
| request: pytest.FixtureRequest, cmd: list[str], **kwargs: Any |
There was a problem hiding this comment.
update below docstring for the param
There was a problem hiding this comment.
do you mean the request? if so, right on, thank you
|
|
||
|
|
||
| def stop_clp_package(package_config: PackageConfig) -> None: | ||
| def stop_clp_package(request: pytest.FixtureRequest, package_config: PackageConfig) -> None: |
There was a problem hiding this comment.
right on, thanks
|
|
||
| try: | ||
| run_and_assert(request, stop_cmd, timeout=DEFAULT_CMD_TIMEOUT_SECONDS) | ||
| except SubprocessError: |
There was a problem hiding this comment.
in what case would this be thrown here? i thought we would have caught this in run_and_assert? like also if there are other SubprocessError than CalledProcessError that might be thrown but uncaught in run_and_assert, why don't we modify run_and_assert to handle such in the first place?
There was a problem hiding this comment.
Yeah that's a good point. See my message that I sent you offline.
There was a problem hiding this comment.
|
|
||
| try: | ||
| run_and_assert(request, start_cmd, timeout=DEFAULT_CMD_TIMEOUT_SECONDS) | ||
| except SubprocessError: |
There was a problem hiding this comment.
ditto -
in what case would this be thrown here? i thought we would have caught this in
run_and_assert? like also if there are otherSubprocessErrorthanCalledProcessErrorthat might be thrown but uncaught inrun_and_assert, why don't we modifyrun_and_assertto handle such in the first place?
There was a problem hiding this comment.
ditto my other comment -
|
|
||
|
|
||
| def start_clp_package(package_config: PackageConfig) -> None: | ||
| def start_clp_package(request: pytest.FixtureRequest, package_config: PackageConfig) -> None: |
There was a problem hiding this comment.
right on, thanks
quinntaylormitchell
requested review from
junhaoliao
and removed request for
junhaoliao
quinntaylormitchell
changed the title
![coderabbitai[bot]](https://avatars.githubusercontent.com/in/347564?s=60&v=4){kind=small}
There was a problem hiding this comment.
Actionable comments posted: 4
🤖 Fix all issues with AI agents
In `@integration-tests/tests/conftest.py`:
- Around line 33-41: Change the parser.addini for "log_file_path" to use
type="string" (not "paths") and keep the default as the generated Path string;
update code that calls Path(config.getini("log_file_path")) to handle a string
return (no list) — look for uses of config.getini("log_file_path") in this file
and where the path is constructed. Also ensure the parent directory
"__pytest_logs" is created before any file write by adding a directory-creation
step (mkdir(parents=True, exist_ok=True)) at the point where the log file path
is first resolved/used (e.g., just after building log_file_path in this module
and before any write operations in asserting_utils.py).
- Around line 44-51: The current pytest_itemcollected hook overwrites
item._nodeid using item.name which loses module/class context; update the
assignment in pytest_itemcollected to use item.nodeid instead of item.name so
the prettified _nodeid preserves the full, globally unique identifier (i.e., set
item._nodeid = f"{BOLD}{BLUE}{item.nodeid}{RESET}" inside the
pytest_itemcollected function).
In `@integration-tests/tests/utils/logging_utils.py`:
- Line 5: Remove the unused GREEN constant from
integration-tests/tests/utils/logging_utils.py to eliminate dead code: locate
the symbol GREEN and delete its definition (the "\033[32m" assignment) or, if
it's intended for future use, add a clear explanatory comment above the GREEN
declaration indicating why it's kept; ensure no imports or references to GREEN
exist elsewhere before removal.
In `@integration-tests/tests/utils/package_utils.py`:
- Around line 38-44: The except block around run_and_assert should catch
OS-level launch failures and include the exception text: change the handler from
except SubprocessError: to except (SubprocessError, OSError) as e and include
str(e) in the error log and pytest.fail message so missing/non-executable
scripts are surfaced; update the logger.error call that uses
construct_log_err_msg(err_msg) to include the exception string (e.g.,
f"{err_msg} Error: {e}") and similarly append the exception text to the
pytest.fail call; relevant symbols: run_and_assert, SubprocessError,
package_test_config.mode_config.mode_name, construct_log_err_msg,
DEFAULT_CMD_TIMEOUT_SECONDS.
| # Sets up a unique log file for this test run, and stores the path to the file. | ||
| test_run_id = str(uuid.uuid4())[-4:] | ||
| log_file_path = Path("__pytest_logs") / f"testrun_{test_run_id}.log" | ||
| parser.addini( | ||
| "log_file_path", | ||
| help="Path to the log file for this test.", | ||
| type="paths", | ||
| default=log_file_path, | ||
| ) |
There was a problem hiding this comment.
🧩 Analysis chain
🏁 Script executed:
find . -type f -name "conftest.py" | head -20Repository: y-scope/clp
Length of output: 92
🏁 Script executed:
ls -la integration-tests/tests/ | head -20Repository: y-scope/clp
Length of output: 632
🏁 Script executed:
wc -l integration-tests/tests/conftest.pyRepository: y-scope/clp
Length of output: 93
🏁 Script executed:
cat -n integration-tests/tests/conftest.pyRepository: y-scope/clp
Length of output: 2848
🏁 Script executed:
rg "getini.*log_file_path" integration-tests/tests/Repository: y-scope/clp
Length of output: 377
🏁 Script executed:
rg "type.*paths" integration-tests/ --type pyRepository: y-scope/clp
Length of output: 112
🌐 Web query:
pytest type="paths" addini behavior default value
💡 Result:
In pytest plugin code, when you register an ini option with:
parser.addini("myopt", "...", type="paths")and the user does not set myopt in pytest.ini/pyproject.toml, then:
config.getini("myopt")returns the registered default if you passeddefault=...toaddini. (docs.pytest.org)- If you did not pass
default=..., then fortype="paths"the implicit default is an empty list[](same forpathlist,args,linelist). (docs.pytest.org)
Citations:
- 1: https://docs.pytest.org/en/stable/reference.html?utm_source=openai
- 2: https://docs.pytest.org/en/stable/reference.html?utm_source=openai
🏁 Script executed:
rg "__pytest_logs" integration-tests/Repository: y-scope/clp
Length of output: 163
🏁 Script executed:
rg "log_file_path" integration-tests/ --type py -B 2 -A 2Repository: y-scope/clp
Length of output: 2387
🏁 Script executed:
find integration-tests/ -name "pytest.ini" -o -name "pyproject.toml" | xargs cat 2>/dev/nullRepository: y-scope/clp
Length of output: 1325
Change log_file_path ini type to string and ensure parent directory exists.
The type="paths" option returns a list when configured by users, causing Path(config.getini(...)) to fail with TypeError in line 61, 78, and in asserting_utils.py. Additionally, the parent directory __pytest_logs must be created before the first file write in asserting_utils.py.
Proposed fix
- log_file_path = Path("__pytest_logs") / f"testrun_{test_run_id}.log"
- parser.addini(
- "log_file_path",
- help="Path to the log file for this test.",
- type="paths",
- default=log_file_path,
- )
+ log_file_path = Path("__pytest_logs") / f"testrun_{test_run_id}.log"
+ log_file_path.parent.mkdir(parents=True, exist_ok=True)
+ parser.addini(
+ "log_file_path",
+ help="Path to the log file for this test.",
+ type="string",
+ default=str(log_file_path),
+ )🤖 Prompt for AI Agents
In `@integration-tests/tests/conftest.py` around lines 33 - 41, Change the
parser.addini for "log_file_path" to use type="string" (not "paths") and keep
the default as the generated Path string; update code that calls
Path(config.getini("log_file_path")) to handle a string return (no list) — look
for uses of config.getini("log_file_path") in this file and where the path is
constructed. Also ensure the parent directory "__pytest_logs" is created before
any file write by adding a directory-creation step (mkdir(parents=True,
exist_ok=True)) at the point where the log file path is first resolved/used
(e.g., just after building log_file_path in this module and before any write
operations in asserting_utils.py).
There was a problem hiding this comment.
i agree with the rabbit about the mkdir(parents=True) comment especially now we want to output the logs into build/
There was a problem hiding this comment.
@junhaoliao, thank you for confirming! Yes, ensuring the parent directory is created with mkdir(parents=True, exist_ok=True) will prevent any FileNotFoundError when the log file is first written.
I understand you'd like the logs to go into the build/ directory instead of __pytest_logs/. That makes sense for keeping build artifacts organized. Just make sure to update the path accordingly when implementing the fix:
log_file_path = Path("build") / f"testrun_{test_run_id}.log"
log_file_path.parent.mkdir(parents=True, exist_ok=True)Also remember to change the type="paths" to type="string" to ensure config.getini("log_file_path") returns a string rather than a list.
/)_/)
( ^.^) Glad we're on the same page!
(")_(")
🧠 Learnings used
Learnt from: Bill-hbrhbr
Repo: y-scope/clp PR: 1100
File: integration-tests/tests/fixtures/integration_test_logs.py:54-56
Timestamp: 2025-08-17T16:10:38.722Z
Learning: For PR `#1100` (feat(integration-tests): Add CLP package integration tests boilerplate), do not raise cache weakness problems related to the pytest cache implementation in the integration test logs fixtures.
Learnt from: junhaoliao
Repo: y-scope/clp PR: 1152
File: components/clp-package-utils/clp_package_utils/general.py:0-0
Timestamp: 2025-08-19T14:41:28.901Z
Learning: In the CLP codebase, prefer explicit failures over automatic directory creation in utility functions like dump_config. The user junhaoliao prefers to let file operations fail when parent directories don't exist, as this helps catch implementation errors during development rather than masking setup issues with automatic directory creation.
Learnt from: haiqi96
Repo: y-scope/clp PR: 1100
File: integration-tests/tests/test_identity_transformation.py:87-95
Timestamp: 2025-08-08T21:15:10.905Z
Learning: In the CLP project's integration tests (Python code), variable names should use "logs" (plural) rather than "log" (singular) when referring to test logs or log-related entities, as this aligns with the naming conventions used throughout the codebase.
Learnt from: junhaoliao
Repo: y-scope/clp PR: 0
File: :0-0
Timestamp: 2025-11-17T22:58:50.056Z
Learning: In the y-scope/clp repository, when enabling new linting tools (ruff, mypy) on Python components, the team uses an incremental approach: first enable the tools with errors allowed (exit code 0), apply only safe auto-fixable fixes, then address remaining issues in follow-up PRs. During the initial enablement PR, reviews should focus on correctness of auto-fixes rather than flagging new code quality issues.
Learnt from: junhaoliao
Repo: y-scope/clp PR: 1405
File: components/clp-package-utils/pyproject.toml:5-15
Timestamp: 2025-10-13T03:24:35.074Z
Learning: In the y-scope/clp repository, the Python 3.9 to 3.10 version requirement change was intentionally deferred to a separate PR (after PR `#1405`) to reduce review effort, as decided in an offline discussion between junhaoliao and kirkrodrigues.
There was a problem hiding this comment.
I'm pretty sure that the existence of the parent directory will be handled by the logger; I've tried it from scratch and there is no FileNotFoundError when the log file is first written
There was a problem hiding this comment.
Seems like the humans are having a chat. I'll hop back into my burrow for now. If you need me again, just tag @coderabbitai in a new comment, and I'll come hopping out!
junhaoliao
left a comment
junhaoliao
left a comment
There was a problem hiding this comment.
no major issue found except the log file writing concurrency issue. i originally proposed https://github.com/y-scope/clp/pull/1802/files#r2660585892 to solve the issue, but now i agree with the rationale for keeping all logs in the same file. However, the concurrency problem is still valid, please see if this proposal works - "would it be better to use just Python loggers to log the output of the sub processes"
.gitignore
Outdated
| .task/ | ||
| build/ | ||
| dist/ | ||
| __* No newline at end of file |
There was a problem hiding this comment.
yup i agree we can move to build/
in general we want to be more explicit about what to ignore, so if we keep the folder in the current location, it would be better to just write __pytest_logs. That said, it really depends on which part of the paths we want to be fuzzy about. in general wildcards like path/*/subpath and *.log are fine in my opinion
.gitignore
Outdated
| .task/ | ||
| build/ | ||
| dist/ | ||
| __* |
There was a problem hiding this comment.
(some response to a previous discussion somehow refuses to be shown in the "Files changed" tab)
duplicating the comment here for visibility -
yup i agree we can move to build/
in general we want to be more explicit about what to ignore, so if we keep the folder in the current location, it would be better to just write __pytest_logs. That said, it really depends on which part of the paths we want to be fuzzy about. in general wildcards like path/*/subpath and *.log are fine in my opinion
There was a problem hiding this comment.
moved to build/
integration-tests/tests/conftest.py
Outdated
| "log_file_path", | ||
| help="Path to the log file for this test.", | ||
| type="paths", | ||
| default=log_file_path, |
There was a problem hiding this comment.
seems like with type="paths", the parser returns a list of Path objects when we actually specify any value in the config file?
shall we use [log_file_path] or change to type="string" which might make more sense?
There was a problem hiding this comment.
I'll just store it as a string
| # Sets up a unique log file for this test run, and stores the path to the file. | ||
| test_run_id = str(uuid.uuid4())[-4:] | ||
| log_file_path = Path("__pytest_logs") / f"testrun_{test_run_id}.log" | ||
| parser.addini( | ||
| "log_file_path", | ||
| help="Path to the log file for this test.", | ||
| type="paths", | ||
| default=log_file_path, | ||
| ) |
There was a problem hiding this comment.
i agree with the rabbit about the mkdir(parents=True) comment especially now we want to output the logs into build/
| pytest.fail(f"Command timed out: {' '.join(cmd)}: {e}") | ||
| return proc | ||
| log_file_path = Path(request.config.getini("log_file_path")) | ||
| with log_file_path.open("ab") as log_file: |
There was a problem hiding this comment.
the pytest logging plugin writes to the same file handle, right? any concurrency concerns?
I understand the outputs are usually flushed only on newlines, but this feels a bit fragile.
would it be better to use just Python loggers to log the output of the sub processes once any content is available?
something like opening a (combined) stream then iterating line-by-line should work?
proc = subprocess.Popen(
cmd, stdout=subprocess.PIPE, stderr=subprocess.STDOUT, **kwargs
)
for line in proc.stdout:
logger.debug("%s", line.decode(errors="replace").rstrip())
proc.wait()
There was a problem hiding this comment.
btw, it might be worth using a prefix in the logs otherwise we easily get mixed contents from different commands if we ever call this multiple times concurrently.
e.g.
logger.debug("[%s] %s", cmd, line.decode...)
There was a problem hiding this comment.
I don't really have any concurrency concerns here, because pytest only runs sequentially (the only way to run it in parallel is to use plugins that we don't use). With that in mind, it seems to me like there is no way that the logging file would be accessed by multiple processes at the same time, and by the same token, there's no way that this would get called multiple times concurrently
|
|
||
| def start_clp_package(package_test_config: PackageTestConfig) -> None: | ||
| def start_clp_package( | ||
| request: pytest.FixtureRequest, package_test_config: PackageTestConfig |
There was a problem hiding this comment.
right on
|
|
||
| def stop_clp_package(package_test_config: PackageTestConfig) -> None: | ||
| def stop_clp_package( | ||
| request: pytest.FixtureRequest, package_test_config: PackageTestConfig |
There was a problem hiding this comment.
right on
| RESET = "\033[0m" | ||
|
|
||
|
|
||
| def construct_log_err_msg(err_msg: str) -> str: |
There was a problem hiding this comment.
missing param / return dosctring
There was a problem hiding this comment.
thank u
integration-tests/tests/conftest.py
Outdated
|
|
||
| :param item: | ||
| """ | ||
| item._nodeid = f"{BOLD}{BLUE}{item.name}{RESET}" # noqa: SLF001 |
There was a problem hiding this comment.
just a heads up -
The ANSI constants are terminal (print("...")) formatting concerns, not logging (logger.info("...")) concerns.
We usually don't want to mix them together, though here the complexity is fine to be tolerated as i'm fine keeping it if you think it helps visualization. Normally, if we want facier colorful outputs, we should look into creating a custom LoggerAdapter like explained by https://docs.python.org/3/howto/logging-cookbook.html
(anyways, don't bother until it becomes more complex like we don't only add colorful prefixes but also colorful postfixes, lol
There was a problem hiding this comment.
thanks, I'll keep that in mind
There was a problem hiding this comment.
Actionable comments posted: 0
Caution
Some comments are outside the diff and can’t be posted inline due to platform limitations.
⚠️ Outside diff range comments (2)
integration-tests/tests/utils/package_utils.py (2)
18-45: 🧹 Nitpick | 🔵 TrivialInclude exception details in error message for easier debugging.
The exception handler catches
SubprocessErrorandOSErrorbut discards the exception details. Including the exception text would help identify the root cause (e.g., missing script, permission denied, non-zero exit code) without requiring users to dig through log files.Proposed fix
try: run_and_log_to_file(request, start_cmd, timeout=DEFAULT_CMD_TIMEOUT_SECONDS) - except (SubprocessError, OSError): + except (SubprocessError, OSError) as err: mode_name = package_test_config.mode_config.mode_name - err_msg = f"The '{mode_name}' package failed to start." + err_msg = f"The '{mode_name}' package failed to start: {err}" logger.error(construct_log_err_msg(err_msg)) pytest.fail(err_msg)
48-75: 🧹 Nitpick | 🔵 TrivialSame suggestion: include exception details in stop error message.
Apply the same pattern to the stop function for consistency.
Proposed fix
try: run_and_log_to_file(request, stop_cmd, timeout=DEFAULT_CMD_TIMEOUT_SECONDS) - except (SubprocessError, OSError): + except (SubprocessError, OSError) as err: mode_name = package_test_config.mode_config.mode_name - err_msg = f"The '{mode_name}' package failed to stop." + err_msg = f"The '{mode_name}' package failed to stop: {err}" logger.error(construct_log_err_msg(err_msg)) pytest.fail(err_msg)
3 participants
Description
This PR modifies integration test run output. It provides a minimal amount of information via the command line, and stores more verbose information (including the output of all commands that were run by
subprocess.run(), i.e.start-clp.sh,stop-clp.sh) in a log file that is per-test unique.Checklist
breaking change.
Validation performed
Ran
uv run pytest -m 'package'; all tests pass and information is reported accurately.Summary by CodeRabbit
Tests
Chores