fix: demote hook infrastructure logs from INFO to DEBUG by raballew · Pull Request #604 · jumpstarter-dev/jumpstarter

raballew · 2026-04-17T06:22:21Z

Summary

Demote internal implementation messages ("Using dedicated hook socket", "Executing before-lease hook", etc.) from INFO to DEBUG so they don't appear in client-visible hook output
Fix double-tagging of source prefix in client log_stream_async (was producing [exporter:beforeLease] [exporter:beforeLease] output)

Closes #240

Test plan

Verify hook infrastructure logs no longer appear at INFO level
Verify source tag appears exactly once per log line
Run make pkg-test-jumpstarter and make pkg-test-jumpstarter-cli

🤖 Generated with Claude Code

coderabbitai · 2026-04-17T06:22:29Z

No actionable comments were generated in the recent review. 🎉

ℹ️ Recent review info

⚙️ Run configuration

Configuration used: Organization UI

Review profile: CHILL

Plan: Pro

Run ID: eff2d0a6-fe0c-49be-9f0c-2d52de629a89

📥 Commits

Reviewing files that changed from the base of the PR and between 4237897 and b750d35.

📒 Files selected for processing (1)

python/packages/jumpstarter/jumpstarter/client/core_test.py

🚧 Files skipped from review as they are similar to previous changes (1)

python/packages/jumpstarter/jumpstarter/client/core_test.py

📝 Walkthrough

Walkthrough

Replaces hardcoded hook timeout numbers with named constants, demotes an internal hook-socket message from INFO to DEBUG, and adds extensive tests covering log-stream routing, per-source logger emission, severity-to-level mapping, and hook-executor logging expectations.

Changes

Exporter timeout & hook logging

Layer / File(s)	Summary
Data / Constants `python/packages/jumpstarter/jumpstarter/exporter/exporter.py`	Introduce `DEFAULT_SAFETY_TIMEOUT_SECONDS` and `HOOK_TIMEOUT_MARGIN_SECONDS` to replace hardcoded `15` and `+30` used when computing before-lease hook wait/cancel timeouts.
Behavior `python/packages/jumpstarter/jumpstarter/exporter/hooks.py`	Change internal message emission: `"Using dedicated hook socket …"` logged at DEBUG instead of INFO when `lease_scope.hook_socket_path` is present.
Tests `python/packages/jumpstarter/jumpstarter/exporter/hooks_test.py`	Add focused tests asserting the socket-selection message is emitted only at DEBUG and that lifecycle/completion messages remain visible at INFO during before-lease execution.

Log-stream and routing tests

Layer / File(s)	Summary
Test scaffolding / Mocks `python/packages/jumpstarter/jumpstarter/client/core_test.py`	Add `LogStreamResponse` mock factory (conditionally supports `HasField("source")`), `LogCapture` logging.Handler, per-source logger setup, anyio sync primitives, and autouse fixture to clear handlers between tests.
Behavioral tests `python/packages/jumpstarter/jumpstarter/client/core_test.py`	Add async tests for `AsyncDriverClient.log_stream_async` that assert: hook messages route to source-specific loggers (`exporter:beforeLease`, `exporter:afterLease`), `show_all_logs=False` suppresses `exporter:system` while preserving hook logs, `show_all_logs=True` includes system logs, entries without `source` map to `exporter:system`, and `LogSource.DRIVER` maps to `exporter:driver`.
Severity / Formatter assertions `python/packages/jumpstarter/jumpstarter/client/core_test.py`	Add assertions verifying severity-to-logging-level mapping (e.g., WARNING→logging.WARNING, ERROR→logging.ERROR) and that record names/placement match expected source-specific logger formatting.

Estimated code review effort

🎯 3 (Moderate) | ⏱️ ~22 minutes

Possibly related PRs

jumpstarter-dev/jumpstarter#297: Implements AsyncDriverClient.log_stream_async and exporter log forwarding that the new tests exercise.

Suggested reviewers

evakhoni
mangelajo

Poem

🐰
Hopping through logs with a careful paw,
I tuck away noise and cheer what I saw.
Numbers get names, and messages hide,
Tests stand watch by the formatter's side.
A tiny rabbit applauds—soft and spry.

🚥 Pre-merge checks | ✅ 4 | ❌ 1

❌ Failed checks (1 warning)

Check name	Status	Explanation	Resolution
Docstring Coverage	⚠️ Warning	Docstring coverage is 33.33% which is insufficient. The required threshold is 80.00%.	Write docstrings for the functions missing them to satisfy the coverage threshold.

✅ Passed checks (4 passed)

Check name	Status	Explanation
Title check	✅ Passed	The title 'fix: demote hook infrastructure logs from INFO to DEBUG' clearly and concisely summarizes the primary change in the changeset.
Description check	✅ Passed	The description is directly related to the changeset, explaining the main objectives of demoting logs and fixing double-tagging, with reference to issue `#240`.
Linked Issues check	✅ Passed	The PR addresses objectives from issue `#240`: demoting verbose logs to DEBUG level, fixing double-tagging of source prefixes, and supporting streaming hook output with proper log routing.
Out of Scope Changes check	✅ Passed	All changes are directly related to issue `#240` objectives: test coverage for log routing and severity mapping, log level demotion for internal messages, and timeout constant refactoring for consistency.

_{✏️ Tip: You can configure your own custom pre-merge checks in the settings.}

✨ Finishing Touches

🧪 Generate unit tests (beta)

Create PR with unit tests

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.

❤️ Share

_{Comment @coderabbitai help to get the list of available commands and usage tips.}

mangelajo · 2026-04-17T08:10:22Z

                            else:  # SYSTEM
                                logger_name = "exporter:system"

-                            # Log through logger for RichHandler formatting


LLMs lately have a lot of interest in removing comments for some reason...

yep. seen this behavior in #422 (comment) as well

mangelajo · 2026-04-17T08:11:20Z

            logger.debug("No before-lease hook configured")
            return None

-        logger.info("Executing before-lease hook for lease %s", lease_scope.lease_name)


this one I would keep it, if the before-lease is slow... you may want to know what's going on?

mangelajo · 2026-04-17T08:11:33Z

            return None

-        logger.info("Executing after-lease hook for lease %s", lease_scope.lease_name)
+        logger.debug("Executing after-lease hook for lease %s", lease_scope.lease_name)


mangelajo · 2026-04-17T08:12:11Z


            # Execute hook with lease scope
-            logger.info("Executing before-lease hook for lease %s", lease_scope.lease_name)
+            logger.debug("Executing before-lease hook for lease %s", lease_scope.lease_name)


I'd also keep this one.

mangelajo · 2026-04-17T08:12:24Z


            # Execute hook with lease scope
-            logger.info("Executing after-lease hook for lease %s", lease_scope.lease_name)
+            logger.debug("Executing after-lease hook for lease %s", lease_scope.lease_name)


and this one.

mangelajo · 2026-04-17T08:13:15Z

-        assert len(failed_statuses) > 0, (
-            f"Expected BEFORE_LEASE_HOOK_FAILED status, got: {status_calls}"
-        )
+        assert len(failed_statuses) > 0, f"Expected BEFORE_LEASE_HOOK_FAILED status, got: {status_calls}"


unrelated format change

mangelajo · 2026-04-17T08:13:24Z

-        assert len(failed_statuses) > 0, (
-            f"Expected AFTER_LEASE_HOOK_FAILED status, got: {status_calls}"
-        )
+        assert len(failed_statuses) > 0, f"Expected AFTER_LEASE_HOOK_FAILED status, got: {status_calls}"


unrelated format change

mangelajo · 2026-04-17T08:13:39Z

-        assert len(offline_indices) > 0, (
-            f"Expected OFFLINE status before shutdown, got: {status_calls}"
-        )
+        offline_indices = [i for i, (s, _) in enumerate(status_calls) if s == ExporterStatus.OFFLINE]


unrelated format changes

mangelajo · 2026-04-17T08:13:56Z

+        offline_indices = [i for i, (s, _) in enumerate(status_calls) if s == ExporterStatus.OFFLINE]
+        assert len(offline_indices) > 0, f"Expected OFFLINE status before shutdown, got: {status_calls}"


unrelated format change

mangelajo · 2026-04-17T08:14:06Z

        available_calls = [s for s, _ in status_calls if s == ExporterStatus.AVAILABLE]
-        assert len(available_calls) > 0, (
-            f"Expected AVAILABLE status after warn+afterLease, got: {status_calls}"
+        assert len(available_calls) > 0, f"Expected AVAILABLE status after warn+afterLease, got: {status_calls}"


unrelated format change

raballew · 2026-04-20T12:16:15Z

+]
+
+
+def setup_log_stream_client(responses, show_all_logs=True):


[MEDIUM] The setup_log_stream_client helper accepts a show_all_logs parameter but never actually uses it inside the function body. Every caller passes show_all_logs directly to client.log_stream_async() instead, so the parameter on the helper is dead code that falsely suggests the helper configures filtering behavior.

Consider removing show_all_logs from the signature so it becomes just def setup_log_stream_client(responses):.

AI-generated, human reviewed

raballew · 2026-04-20T14:30:59Z

        socket_path = lease_scope.hook_socket_path or lease_scope.socket_path
        if lease_scope.hook_socket_path:
-            logger.info(
+            logger.debug(


test comment

raballew · 2026-04-20T14:31:20Z

        socket_path = lease_scope.hook_socket_path or lease_scope.socket_path
        if lease_scope.hook_socket_path:
-            logger.info(
+            logger.debug(


Looks good -- demoting this socket-selection detail from INFO to DEBUG makes sense since it is purely internal plumbing and should not appear in client-visible output.

AI-generated, human reviewed

this seems redundant, as this specific message was not printing at the client side anyway.

according to claude analysis,

_create_hook_env is called before the PTY subprocess starts, which means it's outside the context_log_source block. That makes the logger tag it as LogSource.SYSTEM. The client's log_stream_async filters SYSTEM logs unless you pass --exporter-logs. So the message was always invisible to the client in normal use.

which explains the observed behavior.

the extensive verbosity mentioned in the original issue was already fixed elsewhere. it seems that the bot didn't checked in code if the issue is still exist, but instead assumed it must be there so tried what it can.

raballew · 2026-04-20T14:31:20Z

                msg = "Ready for commands"
            await report_status(ExporterStatus.LEASE_READY, msg)
-            logger.info("beforeLease hook completed successfully")
+            logger.debug("beforeLease hook completed successfully")


Heads-up: demoting completion messages to DEBUG means operators monitoring slow hooks will no longer see them at INFO level. If that is intentional, all good. The start message ("Executing before-lease hook") staying at INFO still gives visibility into when a hook begins, which is the more useful signal anyway.

AI-generated, human reviewed

raballew · 2026-04-20T14:31:20Z

+
+            assert any("beforeLease hook completed successfully" in call for call in debug_calls), (
+                "Expected 'beforeLease hook completed successfully' at DEBUG level"
+            )


Nice -- checking that completion messages moved to DEBUG and that start messages stayed at INFO is a clean way to verify the log-level contract. Covers the key behavioral change well.

AI-generated, human reviewed

Internal implementation messages like "Using dedicated hook socket", "Executing before-lease hook for lease", and "beforeLease hook completed successfully" are now logged at DEBUG level. This prevents them from appearing in client-visible hook output. Only actual subprocess stdout/stderr lines remain at INFO level. Fixes part of jumpstarter-dev#240 Generated-By: Forge/20260416_202053_681470_c94294b7_i240 Co-Authored-By: Claude Opus 4.6 <noreply@anthropic.com>

Generated-By: Forge/20260416_202053_681470_c94294b7_i240 Co-Authored-By: Claude Opus 4.6 <noreply@anthropic.com>

The RichHandler placed the logger name (source tag) at the end of each log line. Prepend [exporter:beforeLease] / [exporter:afterLease] etc. to the message string so the source tag appears at the beginning. Also adds tests for client-side log filtering with show_all_logs=False to verify that system logs are filtered while hook logs are always shown. Generated-By: Forge/20260416_202053_681470_c94294b7_i240

The iter1 fix for F001 prepended [logger_name] to messages in core.py, but SourcePrefixFormatter already adds this prefix on the first line of each consecutive same-source block. This caused double tags like "[exporter:beforeLease] [exporter:beforeLease] output". Revert to passing the raw message and rely on the existing formatter. Generated-By: Forge/20260416_202053_681470_c94294b7_i240 Co-Authored-By: Claude Opus 4.6 <noreply@anthropic.com>

Keep logger.info for hook execution start messages (useful when hooks are slow). Revert unrelated formatting changes to reduce backport conflicts. Restore deleted RichHandler comment. Co-Authored-By: Claude Opus 4.6 <noreply@anthropic.com>

Replace timing-based anyio.sleep with event-based synchronization to eliminate race conditions and ensure assertions are always reached. Add tests for create_log_stream_response without source argument. Co-Authored-By: Claude Opus 4.6 <noreply@anthropic.com>

The helper accepted a show_all_logs parameter that was never used in the function body. Callers always passed show_all_logs directly to client.log_stream_async() instead. Remove the dead parameter to avoid falsely suggesting the helper configures filtering behavior. Generated-By: Forge/20260420_160310_819241_5043dbb0

Hook completion messages ("beforeLease/afterLease hook completed successfully") are useful for monitoring slow hooks and should remain at INFO level per reviewer feedback and spec FR-004 guidance. Generated-By: Forge/20260420_160310_819241_5043dbb0

Replace magic numbers 15 and 30 in _cleanup_after_lease with named constants DEFAULT_SAFETY_TIMEOUT_SECONDS and HOOK_TIMEOUT_MARGIN_SECONDS to improve clarity of the timeout calculation. Generated-By: Forge/20260420_160310_819241_5043dbb0

Add tests verifying that LogSource.DRIVER routes to "exporter:driver" logger, and that WARNING/ERROR severity strings map to the correct Python logging levels. Generated-By: Forge/20260508_134145_1530795_f655fafc Co-Authored-By: Claude Opus 4.6 (1M context) <noreply@anthropic.com>

evakhoni · 2026-05-12T11:40:17Z

the description makes no sense.

Demote internal implementation messages ("Using dedicated hook socket", "Executing before-lease hook", etc.) from INFO to DEBUG so they don't appear in client-visible hook output

while the only message demoted is one invisible to the client anyway, as explained in #604 (comment)

Fix double-tagging of source prefix in client log_stream_async (was producing [exporter:beforeLease] [exporter:beforeLease] output)

again seems to be a hallucination. there was never a [exporter:beforeLease] [exporter:beforeLease] output in the original issue. the issue was for a multi-line output in the hooks, it was added to each line individually rather than per output. the original issue again no longer reproduces as it seems to be addressed in another earlier PR.

evakhoni · 2026-05-12T11:45:32Z

this PR is set to close #240 however it doesn't fix all the mentioned issues in there. I tried to reproduce the original issues, 3/4 are gone already on main, 1 is not addressed by this PR, making this one pretty much useless. also I have commented in the issue with some more related UI glitches that are worth addressing as well.

raballew · 2026-05-12T12:00:47Z

yeah, its open for a month now and I did not pay attention to it. i will close it so you can fix it in another issue. also note that i kinda used this issue to test comments ;D

mangelajo reviewed Apr 17, 2026

View reviewed changes

raballew force-pushed the 051-hook-log-verbosity branch from 3115da2 to 559e05c Compare April 17, 2026 10:45

raballew commented Apr 20, 2026

View reviewed changes

raballew and others added 9 commits April 28, 2026 10:36

style: apply ruff format to hooks_test.py

91bc2d5

Generated-By: Forge/20260416_202053_681470_c94294b7_i240 Co-Authored-By: Claude Opus 4.6 <noreply@anthropic.com>

raballew force-pushed the 051-hook-log-verbosity branch from f047439 to 4237897 Compare April 28, 2026 08:36

raballew marked this pull request as ready for review April 30, 2026 15:07

raballew closed this May 12, 2026

		offline_indices = [i for i, (s, _) in enumerate(status_calls) if s == ExporterStatus.OFFLINE]
		assert len(offline_indices) > 0, f"Expected OFFLINE status before shutdown, got: {status_calls}"

		]


		def setup_log_stream_client(responses, show_all_logs=True):

Conversation

raballew commented Apr 17, 2026

Summary

Test plan

Uh oh!

coderabbitai Bot commented Apr 17, 2026 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Walkthrough

Changes

Estimated code review effort

Possibly related PRs

Suggested reviewers

Poem

❌ Failed checks (1 warning)

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

evakhoni commented May 12, 2026

Uh oh!

evakhoni commented May 12, 2026 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

raballew commented May 12, 2026

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

3 participants

coderabbitai Bot commented Apr 17, 2026 •

edited

Loading

evakhoni commented May 12, 2026 •

edited

Loading