feat: add log_context param for labeled outcome logs#253
Conversation
Summary by CodeRabbit
WalkthroughThis PR adds Changeslog_context logging behavior
Estimated code review effort: 3 (Moderate) | ~25 minutes Suggested labels: Suggested reviewers: 🚥 Pre-merge checks | ✅ 5✅ Passed checks (5 passed)
✨ Finishing Touches🧪 Generate unit tests (beta)
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 |
|
Report bugs in Issues Welcome! 🎉This pull request will be automatically processed with the following features: 🔄 Automatic Actions
📋 Available CommandsPR Status Management
Review & Approval
Testing & Validation
Cherry-pick Operations
Branch Management
Label Management
✅ Merge RequirementsThis PR will be automatically approved when the following conditions are met:
📊 Review ProcessApprovers and ReviewersApprovers:
Reviewers:
Available Labels
AI Features
Security Checks
💡 Tips
For more information, please refer to the project documentation or contact the maintainers. |
![coderabbitai[bot]](https://avatars.githubusercontent.com/in/347564?s=60&v=4){kind=small}
There was a problem hiding this comment.
Actionable comments posted: 1
🧹 Nitpick comments (1)
timeout_sampler/__init__.py (1)
300-304: 📐 Maintainability & Code Quality | 🔵 Trivial | ⚡ Quick winChain the re-raised exception (
raise ... from last_exp).Raising
TimeoutExpiredErrorinside theexceptblock withoutfromobscures the original cause in tracebacks. Ruff (B904) flags this.♻️ Proposed change
- raise TimeoutExpiredError( - self._get_exception_log(exp=last_exp), - last_exp=last_exp, - elapsed_time=elapsed_time if not (self.print_log and self.log_context) else None, - ) + raise TimeoutExpiredError( + self._get_exception_log(exp=last_exp), + last_exp=last_exp, + elapsed_time=elapsed_time if not (self.print_log and self.log_context) else None, + ) from last_exp🤖 Prompt for 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. In `@timeout_sampler/__init__.py` around lines 300 - 304, The TimeoutExpiredError re-raise in the timeout handling path is missing explicit exception chaining, which obscures the original cause in tracebacks. Update the raise inside the except block in the timeout sampler logic to chain from last_exp using Python’s exception chaining syntax, keeping the existing TimeoutExpiredError construction and _get_exception_log / elapsed_time handling unchanged.Source: Linters/SAST tools
🤖 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 `@timeout_sampler/__init__.py`:
- Around line 288-291: In TimeoutSampler.__iter__ and the GeneratorExit
handling, the success log is too broad and also drops valid 0.0s timings. Update
the logging condition so it only records success for actual accepted samples,
not merely when the generator is closed, and change the elapsed_time check to
use an explicit None test instead of relying on truthiness. Keep the fix
localized to the GeneratorExit block and the TimeoutSampler logic that sets or
logs elapsed_time.
---
Nitpick comments:
In `@timeout_sampler/__init__.py`:
- Around line 300-304: The TimeoutExpiredError re-raise in the timeout handling
path is missing explicit exception chaining, which obscures the original cause
in tracebacks. Update the raise inside the except block in the timeout sampler
logic to chain from last_exp using Python’s exception chaining syntax, keeping
the existing TimeoutExpiredError construction and _get_exception_log /
elapsed_time handling unchanged.
🪄 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: CHILL
Plan: Pro
Run ID: e1be0983-d1cf-4c26-a897-6e6b23a4d052
📒 Files selected for processing (2)
tests/test_timeout_sampler.pytimeout_sampler/__init__.py
myakove
left a comment
myakove
left a comment
There was a problem hiding this comment.
Code Review
Found 4 issue(s) in this PR:
💡 Suggestions (4)
| File | Line | Issue |
|---|---|---|
timeout_sampler/__init__.py |
128 | To clarify this suggestion: the idea is to change the type to str with default |
timeout_sampler/__init__.py |
103 | [CRITICAL] Missing README.md documentation for log_context |
tests/test_timeout_sampler.py |
177 | [WARNING] wait_timeout=5 exceeds recommended test timeout |
tests/test_timeout_sampler.py |
168 | [SUGGESTION] No test for retry decorator with log_context |
Review generated by pi
myakove
left a comment
myakove
left a comment
There was a problem hiding this comment.
Code Review
Found 1 issue(s) in this PR:
💡 Suggestions (1)
| File | Line | Issue |
|---|---|---|
timeout_sampler/__init__.py |
128 | Good point — you're right that str = "" would change the legacy log format for |
Review generated by pi
Logs "<log_context> succeeded/failed/timed out after Xs" at the three terminal exits of the sampling loop. Retries stay silent & behavior is same when log_context is unset. Signed-off-by: Geetika Kapoor <gkapoor@redhat.com>
geetikakay
force-pushed
the
log_context_callers
branch
from
0e45a3f to
c227a3b
Compare
There was a problem hiding this comment.
Actionable comments posted: 1
🧹 Nitpick comments (2)
tests/test_timeout_sampler.py (1)
196-212: 📐 Maintainability & Code Quality | 🔵 Trivial | ⚡ Quick winBrittle mock: exact-count
side_effectlist couples test to internal call count.
side_effect = [2.0, 2.0]will raiseStopIterationifTimeoutWatch.remaining_time()is called more than twice by the implementation. Since both values are identical,return_value=2.0achieves the same elapsed_time=0.0 result without hardcoding call counts, making the test resilient to internal implementation changes.♻️ Proposed simplification
mock_watch = MagicMock() - mock_watch.remaining_time.side_effect = [2.0, 2.0] + mock_watch.remaining_time.return_value = 2.0🤖 Prompt for 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. In `@tests/test_timeout_sampler.py` around lines 196 - 212, The test in TimeoutSampler is over-constrained by using a fixed two-item side_effect on TimeoutWatch.remaining_time, which ties it to the current call count. Update the mock setup in test_log_context_logs_success_when_elapsed_time_is_zero to use a stable return value instead of an exact-count sequence, so the elapsed-time assertion still works even if TimeoutSampler or TimeoutWatch calls remaining_time more times. Keep the assertion on the success log text unchanged and reference TimeoutWatch and TimeoutSampler when adjusting the mock.timeout_sampler/__init__.py (1)
313-317: 📐 Maintainability & Code Quality | 🔵 Trivial | 💤 Low valueChain the re-raised
TimeoutExpiredErrorto preserve the original cause.Ruff flags B904 here. Raising from within the
exceptblock withoutfromobscures the underlying exception in tracebacks.♻️ Proposed change
raise TimeoutExpiredError( self._get_exception_log(exp=last_exp), last_exp=last_exp, elapsed_time=elapsed_time if not (self.print_log and self.log_context) else None, - ) + ) from last_exp🤖 Prompt for 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. In `@timeout_sampler/__init__.py` around lines 313 - 317, The TimeoutExpiredError raised in the exception-handling path should be explicitly chained to preserve the original cause and satisfy Ruff B904. Update the raise in the retry/timeout flow around TimeoutExpiredError so it uses exception chaining from the caught exception or last_exp, keeping the context clear in tracebacks while retaining the existing log message and elapsed_time behavior.Source: Linters/SAST tools
🤖 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 `@timeout_sampler/__init__.py`:
- Around line 256-269: The non-retried failure log in _log_outcome currently
records only the outcome and elapsed time, but it must also include the
exception detail from the TimeoutExpiredError to match the documented
"{log_context} failed after {N.N}s: {exception}" format. Update _log_outcome so
the "failed" branch accepts and logs the exception text, and adjust the call
site that raises or handles TimeoutExpiredError to pass that exception
information into _log_outcome while keeping the succeeded and no-context paths
unchanged.
---
Nitpick comments:
In `@tests/test_timeout_sampler.py`:
- Around line 196-212: The test in TimeoutSampler is over-constrained by using a
fixed two-item side_effect on TimeoutWatch.remaining_time, which ties it to the
current call count. Update the mock setup in
test_log_context_logs_success_when_elapsed_time_is_zero to use a stable return
value instead of an exact-count sequence, so the elapsed-time assertion still
works even if TimeoutSampler or TimeoutWatch calls remaining_time more times.
Keep the assertion on the success log text unchanged and reference TimeoutWatch
and TimeoutSampler when adjusting the mock.
In `@timeout_sampler/__init__.py`:
- Around line 313-317: The TimeoutExpiredError raised in the exception-handling
path should be explicitly chained to preserve the original cause and satisfy
Ruff B904. Update the raise in the retry/timeout flow around TimeoutExpiredError
so it uses exception chaining from the caught exception or last_exp, keeping the
context clear in tracebacks while retaining the existing log message and
elapsed_time behavior.
🪄 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: CHILL
Plan: Pro
Run ID: 60f3a572-d48e-4ae4-b12d-56d138ab25ef
📒 Files selected for processing (3)
README.mdtests/test_timeout_sampler.pytimeout_sampler/__init__.py
✅ Files skipped from review due to trivial changes (1)
- README.md
myakove
left a comment
myakove
left a comment
There was a problem hiding this comment.
Code Review
Found 1 issue(s) in this PR:
💡 Suggestions (1)
| File | Line | Issue |
|---|---|---|
timeout_sampler/__init__.py |
256 | [CRITICAL] **Simplification request — prepend [log_context] to existing logs i |
Review generated by pi
Assisted-by: PI (claude-opus-4-6-1m)
| _func_name = self._get_func_info(_func=self.func, type_="__name__") | ||
| return f"Function: {_func_module}.{_func_name} {_func_args} {_func_kwargs}".strip() | ||
|
|
||
| def _log_outcome(self, elapsed_time: float, outcome: str | None = None) -> None: |
There was a problem hiding this comment.
[CRITICAL] Simplification request — prepend [log_context] to existing logs instead of introducing new log formats
The current implementation adds significant complexity:
_log_outcome()helper method (13 lines)GeneratorExithandler for success loggingelapsed_time=Nonesuppression to avoid duplicate log lines- Complex ternary in
TimeoutExpiredError - Multiple conditional branches
All of this stems from introducing new log formats (succeeded after, failed after, timed out after) that conflict with the existing Elapsed time: format.
Simpler approach: just prepend [log_context] to the existing log lines. No new formats, no suppression, no GeneratorExit handler:
# Without log_context (unchanged):
# Elapsed time: 1.5 [0:00:01.500000]
# With log_context:
# [SSH connectivity to test-vm] Elapsed time: 1.5 [0:00:01.500000]This means:
- No
_log_outcome()method — delete it entirely - No
GeneratorExithandler — not needed - No
elapsed_time=None— always preserved inTimeoutExpiredError - No new log format — just a prefix on the existing format
- Fully backward compatible — identical output when
log_contextis not set - Grep-friendly —
grep "SSH connectivity"catches all related logs - Much simpler diff — the change becomes a few lines in
_elapsed_time_logor the log call sites
The prefix also appears on retry logs, which actually helps in CI — you can see which sampler is retrying.
The only tradeoff is losing the explicit "succeeded/failed/timed out" wording, but that's inferrable from context (no exception = success, TimeoutExpiredError = timeout/failure).
Assisted-by: PI (claude-opus-4-6-1m)
There was a problem hiding this comment.
Goal for keeping log_context was to reduce log noise for humans and AI-assisted triage. Each wait should end with one short, labeled sentence that answers what was waited on and how it ended, without parsing retry spam, Elapsed time: fragments, or full TimeoutExpiredError blocks.
example:
SSH connectivity to test-vm succeeded after 12.3s.
SSH connectivity to test-vm failed after 3.1s.
SSH connectivity to test-vm timed out after 60.0s.
Why prefix-only doesn't meet that goal
| Outcome lines (this PR) | [context] prefix on Elapsed time: |
|
|---|---|---|
| Lines per wait | One, when the wait finishes | One per logged iteration |
| Outcome | Explicit: succeeded / failed / timed out |
Inferred from context |
| Retries | Silent (by design) | Logged with prefix |
| Timeout / non-retried failure in LOGGER | Dedicated outcome line | No line exists to prefix — info stays inside TimeoutExpiredError |
| Token cost for AI/human scan | Low | Higher — same retry volume, longer lines |
Prefix helps grep which sampler logged. It doesn't compress how the wait ended into one line.
There was a problem hiding this comment.
Good points, but the "no line exists to prefix" claim isn't accurate.
The finally block fires Elapsed time: on every path — including the last iteration before timeout and before non-retried exception propagation. With the prefix approach + log level differentiation:
- Success:
LOGGER.success("[SSH connectivity to my-vm] Elapsed time: 12.3 [0:00:12.300000]") - Timeout:
LOGGER.error("[SSH connectivity to my-vm] Elapsed time: 60.0 [0:01:00]")→ thenTimeoutExpiredError - Non-retried exception:
LOGGER.error("[SSH connectivity to my-vm] Elapsed time: 3.1 [0:00:03.100000]")→ thenTimeoutExpiredError
The outcome is clear from the log level (success vs error) and context (exception follows or not). The prefix gives you grep-ability and outcome distinction without a parallel logging system.
The current approach adds ~30 lines of complexity (_log_outcome, GeneratorExit handler, elapsed_time=None suppression, conditional ternary) to produce one line that could instead be a small change to the existing log call sites.
Assisted-by: PI (claude-opus-4-6-1m)
There was a problem hiding this comment.
reason for this style is, it consumes lesser token and faster triage as AI reads verbs better .
my understanding is prefix + logger is lesser code but tokens will cost more. Whatever you think is better we can go with that.
I tried experimenting around both approaches with real agent
- SSH connectivity to test-vm succeeded after 12.3s.
- ERROR [SSH connectivity to my-vm] Elapsed time: 60.0 [0:01:00]
Format 1: SSH connectivity to test-vm succeeded after 12.3s.
- Single unambiguous signal: succeeded
- VM name and duration inline, natural language, easy to extract with a simple pattern
- An agent reads this in one pass — success, vm=test-vm, duration=12.3s
Format 2: ERROR ... [SSH connectivity to my-vm] Elapsed time: 60.0 [0:01:00]
- Failure signal is the ERROR prefix — but the reason is implicit (60s = timeout threshold, not stated)
- VM name is buried inside brackets alongside the action description
- Time is duplicated in two formats (60.0 seconds and [0:01:00]) — an agent has to reconcile these or pick one
The core problem: Format 2 requires the agent to infer that 60s means timeout — that's only meaningful if the agent already knows the timeout
value. Format 1 is self-describing.
Two components:
- Raw token count (small but real)
┌────────────────────────────────────────────────────────────────────┬───────────────┐
│ │ Approx tokens │
├────────────────────────────────────────────────────────────────────┼───────────────┤
│ SSH connectivity to test-vm succeeded after 12.3s. │ ~11 │
├────────────────────────────────────────────────────────────────────┼───────────────┤
│ ERROR ... [SSH connectivity to my-vm] Elapsed time: 60.0 [0:01:00] │ ~18 │
└────────────────────────────────────────────────────────────────────┴───────────────┘
Format 2 is ~60% more tokens per line. Multiplied across thousands of log lines in a test run, this adds up.
- Reasoning tokens (the bigger cost)
Format 1 — agent extracts in one pass, no reasoning needed.
Format 2 — agent must:
- Parse ERROR → look for cause
- Extract VM name from inside mixed-content brackets
- Reconcile two time representations
- Infer 60s = timeout (requires knowing the threshold — if that's not in context, agent makes an extra tool call to find it)
That inference step is where cost spikes. If the timeout value isn't already in the agent's context, it triggers a tool call — reading a config
file or AGENTS.md — adding potentially hundreds of tokens just to interpret one log line.
Summary: The raw token difference is minor. The real cost is the reasoning overhead and the potential extra tool call to resolve implicit
meaning. Format 1 is self-describing — zero extra reasoning, zero extra calls.
Note : with multiple elapsed line in logs i think it will be more expensive operation
There was a problem hiding this comment.
Thanks for the detailed analysis — I traced through every exit path in __iter__ to verify both approaches, and I want to share the full picture.
The 4 exit paths
| # | Path | How it exits |
|---|---|---|
| 1 | Success | Caller breaks out of for sample in sampler → GeneratorExit |
| 2 | Non-retried exception | _should_ignore_exception returns False → TimeoutExpiredError |
| 3 | Timeout (with retried exceptions) | while loop ends → TimeoutExpiredError after the loop |
| 4 | Timeout (func returned falsy) | Same as #3 |
Your approach (current PR) — what logs on each path
| Path | Log output | Level |
|---|---|---|
| ✅ Success (GeneratorExit) | SSH connectivity succeeded after 12.3s. |
LOGGER.info |
| ❌ Non-retried exception | SSH connectivity failed after 3.1s: {exp} |
LOGGER.error |
| ⏰ Timeout | SSH connectivity timed out after 60.0s. |
LOGGER.error |
| 🔄 Each retry | Nothing (suppressed) | — |
This works, but requires: _log_outcome() helper, GeneratorExit handler, elapsed_time=None suppression in TimeoutExpiredError, and conditional ternary (~30 lines of new code).
Prefix approach — tracing the gap you identified
You're right that the finally block doesn't fire on timeout — here's why:
# In the finally block (inside the while loop):
if self.print_log and elapsed_time and not self.log_context:
LOGGER.info(_elapsed_time_log(elapsed_time=elapsed_time))elapsed_time is set before yield, then reset to None after time.sleep(). On the last retry iteration, it gets cleared. When the while condition fails, the loop exits — the finally already ran and cleared. The timeout raise happens after the loop, outside try/finally.
| Path | elapsed_time in finally? |
Logs? |
|---|---|---|
| ✅ Success (caller breaks) | ✅ Set before yield, never cleared | ✅ Yes |
| ❌ Non-retried exception | ✅ Set in except block | ✅ Yes |
| 🔄 Retry iteration | ❌ Cleared after sleep | ❌ Correct — no log |
| ⏰ Timeout | ❌ Cleared on last retry | ❌ No log |
So the gap is real — but the fix is trivial. The timeout section after the loop already exists:
timeout_elapsed = self.wait_timeout - timeout_watch.remaining_time()
# Just add the prefix here:
if self.print_log:
_log = _elapsed_time_log(elapsed_time=timeout_elapsed)
if self.log_context:
_log = f"[{self.log_context}] {_log}"
LOGGER.error(_log)
raise TimeoutExpiredError(...)Prefix approach — result (all 3 paths covered)
| Path | Log output | Level |
|---|---|---|
| ✅ Success | [SSH connectivity] Elapsed time: 12.3 [0:00:12.300000] |
LOGGER.success |
| ❌ Non-retried exception | [SSH connectivity] Elapsed time: 3.1 [0:00:03.100000] |
LOGGER.error |
| ⏰ Timeout | [SSH connectivity] Elapsed time: 60.0 [0:01:00.000000] |
LOGGER.error |
| 🔄 Each retry | Nothing (same as your approach) | — |
What changes are needed
- Modify
_elapsed_time_log(or the call sites) to prepend[log_context]when set - Change
LOGGER.info→LOGGER.successon the success path infinally - Add prefix to the post-loop timeout log (already exists, just needs prefix)
No _log_outcome(), no GeneratorExit handler, no elapsed_time=None suppression.
Agent-friendliness
The log level (SUCCESS/ERROR) is the verb. Any agent parsing structured logs reads the level first — that's the outcome signal. The difference between:
SUCCESS [SSH connectivity] Elapsed time: 12.3 [...]SSH connectivity succeeded after 12.3s.
is one inference step that costs near-zero tokens. Both are greppable, both are one line per outcome, both suppress retries.
The key tradeoff: your approach produces slightly more natural-language output, but at ~30 lines of added complexity. The prefix approach achieves the same goals (one outcome line, context label, retry suppression) with minimal code changes.
Let's go with the prefix approach — it covers all paths and keeps the code simple.
Assisted-by: PI (claude-opus-4-6-1m)
myakove
left a comment
myakove
left a comment
There was a problem hiding this comment.
Code Review
Found 1 issue(s) in this PR:
💡 Suggestions (1)
| File | Line | Issue |
|---|---|---|
tests/test_timeout_sampler.py |
181 | sleep=0 is fine for unit tests — no reason to add artificial delay when we're |
Review generated by pi
Assisted-by: PI (claude-opus-4-6-1m)
6 participants
Add optional log_context to TimeoutSampler for grep-friendly outcome lines in CI logs. Giving agents and users more accurate data.Generic Elapsed time: lines are hard to tie to a specific VM or callers.
When log_context is set, the sampler logs once at terminal exit:
INFO: {log_context} succeeded after {N.N}s.
ERROR: {log_context} failed after {N.N}s: {exception} (non-retried exception)
ERROR: {log_context} timed out after {N.N}s.
Retries are not logged (ignored exceptions stay silent by design).
if not set, we continue to see same elapsed logs and is backward compatable.