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

Important

Review skipped

Draft detected.

Please check the settings in the CodeRabbit UI or the .coderabbit.yaml file in this repository. To trigger a single review, invoke the @coderabbitai review command.

⚙️ Run configuration

Configuration used: Organization UI

Review profile: CHILL

Plan: Pro

Run ID: 0366f4dd-f3c2-4e5b-adfa-8b3b7bce5a86

You can disable this status message by setting the reviews.review_status to false in the CodeRabbit configuration file.

Use the checkbox below for a quick retry:

🔍 Trigger review

✨ 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...

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

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>

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

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

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

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

mangelajo reviewed Apr 17, 2026

View reviewed changes

raballew and others added 5 commits April 17, 2026 12:35

style: apply ruff format to hooks_test.py

0b29666

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 3115da2 to 559e05c Compare April 17, 2026 10:45

raballew commented Apr 20, 2026

View reviewed changes

raballew added 3 commits April 20, 2026 16:18

raballew commented Apr 20, 2026

View reviewed changes

		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!

Review skipped

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!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

2 participants

coderabbitai Bot commented Apr 17, 2026 •

edited

Loading