Stop double-logging external command invocations (#104) - #111
Conversation
|
Note Reviews pausedIt looks like this branch is under active development. To avoid overwhelming you with review comments due to an influx of new commits, CodeRabbit has automatically paused this review. You can configure this behavior by changing the Use the following commands to manage reviews:
Use the checkboxes below for quick actions:
No actionable comments were generated in the recent review. 🎉 ℹ️ Recent review info⚙️ Run configurationConfiguration used: Organization UI Review profile: ASSERTIVE Plan: Pro Plus Run ID: 📒 Files selected for processing (1)
💤 Files with no reviewable changes (1)
This pull request closes Key changes
Notes and provenance
No new execplan documents were added. WalkthroughRemove the DEBUG-level subprocess spawn log and unused formatter; rely on a single INFO-level "Running external command" invocation log. Add explicit passthrough invocation logging for cmd-mox, introduce regression tests that assert exactly one invocation record and absence of the old DEBUG spawn line, and update docs and roadmap. ChangesLogging Deduplication and Test Coverage
Suggested labels
🚥 Pre-merge checks | ✅ 19 | ❌ 1❌ Failed checks (1 warning)
✅ Passed checks (19 passed)
✏️ Tip: You can configure your own custom pre-merge checks in the settings. 📋 Issue PlannerLet us write the prompt for your AI agent so you can ship faster (with fewer bugs). View plan for ticket: ✨ Finishing Touches📝 Generate docstrings
🧪 Generate unit tests (beta)
Comment |
Reviewer's GuideThis PR removes a redundant DEBUG-level subprocess invocation log in favor of the existing INFO-level log from subprocess_runner, documents the logging behavior at the spawn site, and adds regression tests to ensure each external command is logged exactly once (with cwd when provided). Sequence diagram for updated subprocess invocation loggingsequenceDiagram
actor Caller
participant invoke_via_subprocess
participant log_command_invocation
participant _log_subprocess_environment
participant _LOGGER
Caller->>invoke_via_subprocess: invoke_via_subprocess(program, args, context)
activate invoke_via_subprocess
invoke_via_subprocess->>log_command_invocation: log_command_invocation(command, context.cwd)
activate log_command_invocation
log_command_invocation->>_LOGGER: info(rendered_command_with_cwd)
deactivate log_command_invocation
invoke_via_subprocess->>_log_subprocess_environment: _log_subprocess_environment(context.env)
activate _log_subprocess_environment
_log_subprocess_environment->>_LOGGER: debug(redacted_env_overrides)
deactivate _log_subprocess_environment
invoke_via_subprocess->>invoke_via_subprocess: _spawn_process(program, command, context, normalised_env)
deactivate invoke_via_subprocess
File-Level Changes
Assessment against linked issues
Possibly linked issues
Tips and commandsInteracting with Sourcery
Customizing Your ExperienceAccess your dashboard to:
Getting Help
|
![codescene-delta-analysis[bot]](https://avatars.githubusercontent.com/in/53921?s=60&v=4){kind=small}
This comment was marked as outdated.
This comment was marked as outdated.
Sorry, something went wrong.
![sourcery-ai[bot]](https://avatars.githubusercontent.com/in/48477?s=60&v=4){kind=small}
This comment was marked as resolved.
This comment was marked as resolved.
Sorry, something went wrong.
![chatgpt-codex-connector[bot]](https://avatars.githubusercontent.com/in/1144995?s=60&v=4){kind=small}
There was a problem hiding this comment.
💡 Codex Review
Here are some automated review suggestions for this pull request.
Reviewed commit: a8e6ceae97
ℹ️ About Codex in GitHub
Your team has set up Codex to review pull requests in this repo. Reviews are triggered when you
- Open a pull request for review
- Mark a draft as ready
- Comment "@codex review".
If Codex has suggestions, it will comment; otherwise it will react with 👍.
Codex can also answer questions or update the PR. Try commenting "@codex address that feedback".
This comment was marked as outdated.
This comment was marked as outdated.
Sorry, something went wrong.
![coderabbitai[bot]](https://avatars.githubusercontent.com/in/347564?s=60&v=4){kind=small}
There was a problem hiding this comment.
Actionable comments posted: 2
🤖 Prompt for all review comments with AI agents
Verify each finding against current code. Fix only still-valid issues, skip the
rest with a brief reason, keep changes minimal, and validate.
Inline comments:
In `@tests/unit/test_subprocess_runner_logging.py`:
- Around line 41-43: The assertion checking that no log record contains
"Spawning subprocess:" in tests/unit/test_subprocess_runner_logging.py should
include a descriptive failure message; update the assert that uses
caplog.records so it reads assert all("Spawning subprocess:" not in
record.getMessage() for record in caplog.records), "Unexpected 'Spawning
subprocess:' log emitted" (or similar) to give clear context on failure and
follow the guideline to use assert …, "message".
- Around line 46-79: Add informative assertion messages to every assert in
test_command_logged_exactly_once and test_command_logged_exactly_once_with_cwd
so failures explain context; update assertions that check exit_code, stdout,
stderr, records length, log level, message contents, cwd inclusion and the
_assert_no_spawn_record call to include a trailing ", '...message...'"
describing what was expected (e.g., "expected exit code 0", "expected stdout to
contain \"hello\"", "expected exactly one invocation record", "expected
invocation at INFO level", "expected message to contain 'Running external
command' / 'echo hello'", "expected cwd to appear in invocation message",
"expected no spawn record"), and similarly annotate any uses of
_invocation_records(caplog) to clarify the expectation when it fails.
🪄 Autofix (Beta)
Fix all unresolved CodeRabbit comments on this PR:
- Push a commit to this branch (recommended)
- Create a new PR with the fixes
ℹ️ Review info
⚙️ Run configuration
Configuration used: Organization UI
Review profile: ASSERTIVE
Plan: Pro Plus
Run ID: 9d3a3c37-b94a-4ef6-8973-070dfa415976
📒 Files selected for processing (2)
lading/runtime/subprocess_runner.pytests/unit/test_subprocess_runner_logging.py
This comment was marked as outdated.
This comment was marked as outdated.
Sorry, something went wrong.
Every external command was logged twice: once at INFO by subprocess_runner via log_command_invocation, and again at DEBUG by invoke_via_subprocess via _log_subprocess_spawn, with two different renderings of the same command line. Keep the INFO-level record (it is the operationally visible one and already includes the working directory) and delete the redundant DEBUG spawn line. The DEBUG record for environment overrides is retained because it carries information the INFO line does not. Add regression tests pinning that a command produces exactly one invocation log record, at INFO, with and without a cwd. Closes #104
Address review feedback on the single-invocation-log regression test:
- Loosen the INFO message assertion so it checks the stable prefix
("Running external command") and the command ("echo hello") rather
than the full formatted string, keeping the test robust to wording
or spacing changes.
- Restrict `_invocation_records` to the INFO command line only, and add
an explicit `_assert_no_spawn_record` check that the removed DEBUG
"Spawning subprocess:" log is absent, tying the regression directly
to #104.
Co-Authored-By: Claude Opus 4.8 (1M context) <noreply@anthropic.com>
The cmd-mox passthrough path in `_handle_cmd_mox_passthrough` calls `invoke_via_subprocess` directly rather than going through `subprocess_runner`, so it never reached the `log_command_invocation` call. Once the redundant DEBUG spawn log was removed for #104, these passthrough external commands emitted no command/cwd invocation record at all, regressing command observability. Emit the single INFO invocation record at the passthrough call site via `log_command_invocation`, mirroring `subprocess_runner`. Routing through `subprocess_runner` is not viable here because that wrapper does not accept `stdin_data`, which the passthrough path needs. Extend the passthrough streaming test to assert exactly one INFO invocation record is logged for the passthrough command. Co-Authored-By: Claude Opus 4.8 (1M context) <noreply@anthropic.com>
5b76c1b to
f5ab030
Compare
This comment was marked as outdated.
This comment was marked as outdated.
Sorry, something went wrong.
|
@coderabbitai Please suggest a fix for this issue and supply a prompt for an AI coding agent to enable it to apply the fix. Include the file and symbol names indicated in the issue at the head of your response. Excess Number of Function Argumentstests/unit/publish/test_command_logging.py: test_cmd_mox_passthrough_streams_output What lead to degradation?test_cmd_mox_passthrough_streams_output has 5 arguments, max arguments = 4 Why does this problem occur?Functions with many arguments indicate either a) low cohesion where the function has too many responsibilities, or b) a missing abstraction that encapsulates those arguments. How to fix it?Start by investigating the responsibilities of the function. Make sure it doesn't do too many things, in which case it should be split into smaller and more cohesive functions. Consider the refactoring INTRODUCE PARAMETER OBJECT to encapsulate arguments that refer to the same logical concept. Helpful refactoring examplesThis code health issue has been solved before in this project. Here are some examples for inspiration: undefined# conftest.py (114b752)
def publish_fixtures(
- tmp_path: Path,
- make_crate: typ.Callable[[Path, str, _CrateSpec | None], WorkspaceCrate],
- make_workspace: typ.Callable[[Path, WorkspaceCrate], WorkspaceGraph],
- make_config: typ.Callable[..., config_module.LadingConfig],
- make_dependency: typ.Callable[[str], WorkspaceDependency],
- publish_options: publish.PublishOptions,
+ request: pytest.FixtureRequest, publish_options: publish.PublishOptions
) -> PublishFixtures:
"""Return the composite publish fixtures used across unit suites."""
+ tmp_path: Path = request.getfixturevalue("tmp_path")
+ make_crate = request.getfixturevalue("make_crate")
+ make_workspace = request.getfixturevalue("make_workspace")
+ make_config = request.getfixturevalue("make_config")
+ make_dependency = request.getfixturevalue("make_dependency")
return PublishFixtures( |
This comment was marked as resolved.
This comment was marked as resolved.
|
@coderabbitai Have the following now been resolved? Annul any requirements that violate the en-GB-oxendict spelling (-ize / -yse / -our) conventions (for example a request to replace "normalize" with "normalise" or "artefact" with "artifact"), or where the requirement unnecessarily increases cyclomatic complexity. |
|
Tip For best results, initiate chat on the files or code changes. 🧩 Analysis chain🏁 Script executed: #!/bin/bash
# Read the current state of the test file on the PR branch
gh pr view 111 --repo leynos/lading --json headRefName -q '.headRefName'
git fetch origin issue-104-single-command-log 2>/dev/null || true
git show origin/issue-104-single-command-log:tests/unit/test_subprocess_runner_logging.py 2>/dev/null || \
fd 'test_subprocess_runner_logging.py' --exec cat {}Length of output: 2878
Comment 1 ( message = records[0].getMessage()
assert "Running external command" in message
assert "echo hello" in messageComment 2 ( Neither suggestion touches spelling (no en-GB-oxendict violations introduced) nor increases cyclomatic complexity, so no requirements need annulling. |
`test_cmd_mox_passthrough_streams_output` took five parameters, four of which were pytest infrastructure fixtures. Collapse `capsys`, `caplog`, `monkeypatch`, and `use_real_invoke` into a single `request` parameter and resolve them via `request.getfixturevalue` at the top of the body, keeping `cmd_mox` as the only explicit fixture. The `pytest.FixtureRequest` annotation stays lazy thanks to `from __future__ import annotations`, so it does not trigger a runtime lookup of the `TYPE_CHECKING`-only `pytest` import. Co-Authored-By: Claude Opus 4.8 (1M context) <noreply@anthropic.com>
This comment was marked as outdated.
This comment was marked as outdated.
Sorry, something went wrong.
Annotate every assertion in the subprocess runner logging regression tests with a trailing message so failures explain the expected context: exit code, stdout/stderr contents, invocation record count, log level, message substrings, cwd inclusion, and the absence of the removed "Spawning subprocess:" DEBUG record. The spawn-absence message lives in `_assert_no_spawn_record` itself, since that helper raises the failure. Co-Authored-By: Claude Opus 4.8 (1M context) <noreply@anthropic.com>
This comment was marked as outdated.
This comment was marked as outdated.
Sorry, something went wrong.
|
@coderabbitai Have the following now been resolved? Annul any requirements that violate the en-GB-oxendict spelling (-ize / -yse / -our) conventions (for example a request to replace "normalize" with "normalise" or "artefact" with "artifact"), or where the requirement unnecessarily increases cyclomatic complexity. |
|
@coderabbitai Have the following failed checks now been resolved? If further work is required, please provide an AI agent prompt for the remaining work to be done to address these failures. Do not treat warnings as optional or aspirational. Where a change is out of scope for this PR, propose a GitHub issue unless one exists already. ❌ Failed checks (2 errors, 3 warnings)
|
|
Tip For best results, initiate chat on the files or code changes. 🧩 Analysis chain🏁 Script executed: #!/bin/bash
# Get the current state of the test file on the PR branch
gh pr view 111 --repo leynos/lading --json headRefName -q '.headRefName'Length of output: 216 🏁 Script executed: #!/bin/bash
git show origin/issue-104-single-command-log:tests/unit/test_subprocess_runner_logging.py 2>/dev/null || \
fd 'test_subprocess_runner_logging.py' --exec cat {}Length of output: 3151
Comment 1 — The single over-specified assertion has been replaced with two independent checks on stable substrings: message = records[0].getMessage()
assert "Running external command" in message
assert "echo hello" in messageComment 2 — Neither suggestion introduces en-GB-oxendict spelling violations nor increases cyclomatic complexity, so no requirements need annulling. |
This comment was marked as resolved.
This comment was marked as resolved.
|
@coderabbitai Please suggest a fix for the following concern and provide an AI coding agent prompt for the fix: Testing (Compile-Time / Ui) |
Record the subprocess invocation logging contract introduced by #111 in developer-facing docs: - developers-guide: add a "Subprocess invocation logging" sub-section to the command runners section, describing the single INFO record (with optional cwd suffix) and the separate DEBUG environment-overrides record, and pointing at the pinning regression tests. - roadmap: mark "Stop double-logging external command invocations" as complete under Phase 4 → Step 4.1 with outcome and completion criteria. Co-Authored-By: Claude Opus 4.8 (1M context) <noreply@anthropic.com>
This comment was marked as resolved.
This comment was marked as resolved.
This comment was marked as outdated.
This comment was marked as outdated.
Sorry, something went wrong.
|
@coderabbitai resume |
✅ Action performedReviews resumed. |
Replace the substring assertions on the invocation log message with syrupy snapshot assertions in the subprocess runner logging regression tests. The cwd test redacts the temporary directory to the literal ``<tmpdir>`` token before comparing so the snapshot stays stable across runs. Add the corresponding amber snapshot file. Co-Authored-By: Claude Opus 4.8 (1M context) <noreply@anthropic.com>
This comment was marked as outdated.
This comment was marked as outdated.
Sorry, something went wrong.
There was a problem hiding this comment.
Actionable comments posted: 1
🤖 Prompt for all review comments with AI agents
Verify each finding against current code. Fix only still-valid issues, skip the
rest with a brief reason, keep changes minimal, and validate.
Inline comments:
In `@lading/runtime/subprocess_runner.py`:
- Around line 193-196: The DEBUG helper _log_subprocess_environment(context.env)
is currently emitting "Spawning subprocess with inherited environment" even when
no env overrides are provided; change the behavior so only override-specific
info is logged: modify either the call site in subprocess_runner or the
implementation of _log_subprocess_environment to first detect whether
context.env is None/empty and return without logging that inherited-environment
message, and only emit DEBUG records when there are actual environment overrides
to report (use the symbols _log_subprocess_environment and context.env to locate
the change).
🪄 Autofix (Beta)
Fix all unresolved CodeRabbit comments on this PR:
- Push a commit to this branch (recommended)
- Create a new PR with the fixes
ℹ️ Review info
⚙️ Run configuration
Configuration used: Organization UI
Review profile: ASSERTIVE
Plan: Pro Plus
Run ID: 506be94d-45c1-4899-83a8-9936ad066623
📒 Files selected for processing (7)
docs/developers-guide.mddocs/roadmap.mdlading/runtime/subprocess_runner.pylading/testing/cmd_mox_runner.pytests/unit/__snapshots__/test_subprocess_runner_logging.ambrtests/unit/publish/test_command_logging.pytests/unit/test_subprocess_runner_logging.py
|
@coderabbitai resume |
✅ Action performedReviews resumed. |
`_log_subprocess_environment` emitted a DEBUG "Spawning subprocess with inherited environment" record on every invocation without overrides, adding noise that carried no information beyond the INFO invocation line. Return early when no overrides are present so a DEBUG record is only emitted when there are actual environment overrides to report. Co-Authored-By: Claude Opus 4.8 (1M context) <noreply@anthropic.com>
|
@coderabbitai this one just feels like a tryhard. What are your thoughts? ❌ Failed checks (1 warning)
|
|
Tip For best results, initiate chat on the files or code changes.
The "emit exactly one INFO log" invariant is a structural property of the code, not a computational one. Whether the count equals one is determined entirely by static control flow — a single call to Property-based testing with Hypothesis earns its keep when correctness is a non-trivial function of inputs — parsers, serialisers, arithmetic, protocol encoding. Here, Hypothesis would simply spin up real subprocesses for hundreds of arbitrary input combinations and count to one every time. That is expensive, potentially unsafe (arbitrary shell commands), and adds no meaningful coverage beyond what the two existing snapshot tests already provide. The two tests already cover both code paths that affect the log message: without Reject this warning. |
1 participant
Summary
Closes #104
_log_subprocess_spawnfromlading/runtime/subprocess_runner.py; the same command was already rendered and logged at INFO bysubprocess_runnervialog_command_invocation.Testing
tests/unit/test_subprocess_runner_logging.pypins that one command produces exactly one invocation log record, at INFO, with and without a working directory.make check-fmt,make lint,make typecheck, andmake test(557 passed) all green.🤖 Generated with Claude Code
Summary by Sourcery
Ensure external command invocations are logged only once while preserving useful context in logs and adding regression coverage.
Bug Fixes:
Enhancements:
Tests: