From dee87b4ceb387f5fd13ee35a046e700e28b973db Mon Sep 17 00:00:00 2001 From: Paul Wallrabe Date: Thu, 16 Apr 2026 20:49:54 +0200 Subject: [PATCH 1/9] fix: demote hook infrastructure logs from INFO to DEBUG 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 #240 Generated-By: Forge/20260416_202053_681470_c94294b7_i240 Co-Authored-By: Claude Opus 4.6 --- .../jumpstarter/jumpstarter/exporter/hooks.py | 14 ++-- .../jumpstarter/exporter/hooks_test.py | 67 +++++++++++++++++++ 2 files changed, 74 insertions(+), 7 deletions(-) diff --git a/python/packages/jumpstarter/jumpstarter/exporter/hooks.py b/python/packages/jumpstarter/jumpstarter/exporter/hooks.py index 9563506f6..124a0a19a 100644 --- a/python/packages/jumpstarter/jumpstarter/exporter/hooks.py +++ b/python/packages/jumpstarter/jumpstarter/exporter/hooks.py @@ -103,7 +103,7 @@ def _create_hook_env(self, lease_scope: "LeaseContext") -> dict[str, str]: # Falls back to main socket if hook socket not available (backward compatibility) socket_path = lease_scope.hook_socket_path or lease_scope.socket_path if lease_scope.hook_socket_path: - logger.info( + logger.debug( "Using dedicated hook socket: %s (main socket: %s)", lease_scope.hook_socket_path, lease_scope.socket_path, @@ -531,7 +531,7 @@ async def execute_before_lease_hook(self, lease_scope: "LeaseContext") -> str | logger.debug("No before-lease hook configured") return None - 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) return await self._execute_hook( self.config.before_lease, lease_scope, @@ -554,7 +554,7 @@ async def execute_after_lease_hook(self, lease_scope: "LeaseContext") -> str | N logger.debug("No after-lease hook configured") 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) return await self._execute_hook( self.config.after_lease, lease_scope, @@ -608,7 +608,7 @@ async def run_before_lease_hook( await report_status(ExporterStatus.BEFORE_LEASE_HOOK, "Running beforeLease hook") # 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) warning = await self._execute_hook( self.config.before_lease, lease_scope, @@ -620,7 +620,7 @@ async def run_before_lease_hook( else: msg = "Ready for commands" await report_status(ExporterStatus.LEASE_READY, msg) - logger.info("beforeLease hook completed successfully") + logger.debug("beforeLease hook completed successfully") except HookExecutionError as e: if e.should_shutdown_exporter(): @@ -699,7 +699,7 @@ async def run_after_lease_hook( await report_status(ExporterStatus.AFTER_LEASE_HOOK, "Running afterLease hooks") # 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) warning = await self._execute_hook( self.config.after_lease, lease_scope, @@ -711,7 +711,7 @@ async def run_after_lease_hook( else: msg = "Available for new lease" await report_status(ExporterStatus.AVAILABLE, msg) - logger.info("afterLease hook completed successfully") + logger.debug("afterLease hook completed successfully") except HookExecutionError as e: if e.should_shutdown_exporter(): diff --git a/python/packages/jumpstarter/jumpstarter/exporter/hooks_test.py b/python/packages/jumpstarter/jumpstarter/exporter/hooks_test.py index ab31d81c5..4e5bfc99b 100644 --- a/python/packages/jumpstarter/jumpstarter/exporter/hooks_test.py +++ b/python/packages/jumpstarter/jumpstarter/exporter/hooks_test.py @@ -1147,6 +1147,73 @@ async def mock_report_status(status, msg): f"Expected AVAILABLE status after warn+afterLease, got: {status_calls}" ) + async def test_hook_socket_message_at_debug_not_info(self, lease_scope) -> None: + """The 'Using dedicated hook socket' message must be at DEBUG, not INFO. + + This message is an internal detail about socket selection and should + not appear in client-visible hook output. + """ + lease_scope.hook_socket_path = "/tmp/hook_socket" + + hook_config = HookConfigV1Alpha1( + before_lease=HookInstanceConfigV1Alpha1(script="echo 'hello'", timeout=10), + ) + executor = HookExecutor(config=hook_config) + + with patch("jumpstarter.exporter.hooks.logger") as mock_logger: + await executor.execute_before_lease_hook(lease_scope) + + debug_calls = [str(call) for call in mock_logger.debug.call_args_list] + info_calls = [str(call) for call in mock_logger.info.call_args_list] + + assert any("Using dedicated hook socket" in call for call in debug_calls), ( + "Expected 'Using dedicated hook socket' at DEBUG level" + ) + assert not any("Using dedicated hook socket" in call for call in info_calls), ( + "'Using dedicated hook socket' should NOT be at INFO level" + ) + + async def test_orchestration_messages_at_debug_not_info(self, lease_scope) -> None: + """Orchestration messages from execute_before/after_lease_hook must be at DEBUG. + + Messages like 'Executing before-lease hook for lease' and + 'beforeLease hook completed successfully' are not inside + context_log_source so they add noise without value to the client. + """ + hook_config = HookConfigV1Alpha1( + before_lease=HookInstanceConfigV1Alpha1(script="echo 'hello'", timeout=10), + ) + executor = HookExecutor(config=hook_config) + + status_calls = [] + + async def mock_report_status(status, msg): + status_calls.append((status, msg)) + + mock_shutdown = MagicMock() + + with patch("jumpstarter.exporter.hooks.logger") as mock_logger: + await executor.run_before_lease_hook( + lease_scope, + mock_report_status, + mock_shutdown, + ) + + debug_calls = [str(call) for call in mock_logger.debug.call_args_list] + info_calls = [str(call) for call in mock_logger.info.call_args_list] + + orchestration_messages = [ + "Executing before-lease hook for lease", + "beforeLease hook completed successfully", + ] + for msg in orchestration_messages: + assert any(msg in call for call in debug_calls), ( + f"Expected '{msg}' at DEBUG level, not found in debug calls" + ) + assert not any(msg in call for call in info_calls), ( + f"Orchestration message '{msg}' should NOT be at INFO level" + ) + async def test_after_hook_warn_includes_warning_prefix(self, lease_scope) -> None: """Issue E5b: afterLease hook fail with warn should include HOOK_WARNING_PREFIX. From 0b29666e3fb374b58cb128a51c528be5f811b314 Mon Sep 17 00:00:00 2001 From: Paul Wallrabe Date: Thu, 16 Apr 2026 20:59:18 +0200 Subject: [PATCH 2/9] style: apply ruff format to hooks_test.py Generated-By: Forge/20260416_202053_681470_c94294b7_i240 Co-Authored-By: Claude Opus 4.6 --- .../jumpstarter/exporter/hooks_test.py | 35 +++++-------------- 1 file changed, 9 insertions(+), 26 deletions(-) diff --git a/python/packages/jumpstarter/jumpstarter/exporter/hooks_test.py b/python/packages/jumpstarter/jumpstarter/exporter/hooks_test.py index 4e5bfc99b..01f673709 100644 --- a/python/packages/jumpstarter/jumpstarter/exporter/hooks_test.py +++ b/python/packages/jumpstarter/jumpstarter/exporter/hooks_test.py @@ -853,8 +853,7 @@ async def mock_report_status(status, msg): # Should have reported LEASE_READY assert any( - status == ExporterStatus.LEASE_READY and msg == "Ready for commands" - for status, msg in status_calls + status == ExporterStatus.LEASE_READY and msg == "Ready for commands" for status, msg in status_calls ), f"Expected LEASE_READY status, got: {status_calls}" async def test_skip_after_lease_prevents_after_hook_execution(self, lease_scope) -> None: @@ -929,15 +928,11 @@ async def mock_report_status(status, msg): # Last status should be OFFLINE (reported before shutdown to prevent new leases) last_status, _ = status_calls[-1] - assert last_status == ExporterStatus.OFFLINE, ( - f"Expected last status to be OFFLINE, got {last_status}" - ) + assert last_status == ExporterStatus.OFFLINE, f"Expected last status to be OFFLINE, got {last_status}" # BEFORE_LEASE_HOOK_FAILED should also be present (reported before OFFLINE) failed_statuses = [s for s, _ in status_calls if s == ExporterStatus.BEFORE_LEASE_HOOK_FAILED] - 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}" # AVAILABLE should never have been reported available_statuses = [s for s, _ in status_calls if s == ExporterStatus.AVAILABLE] @@ -978,9 +973,7 @@ async def mock_report_status(status, msg): # AFTER_LEASE_HOOK_FAILED should be in statuses failed_statuses = [s for s, _ in status_calls if s == ExporterStatus.AFTER_LEASE_HOOK_FAILED] - 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}" # AVAILABLE should NOT be in statuses available_statuses = [s for s, _ in status_calls if s == ExporterStatus.AVAILABLE] @@ -1051,12 +1044,8 @@ def mock_shutdown(**kwargs): mock_shutdown, ) - 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}" - ) + 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}" assert shutdown_called_at_index is not None, "shutdown was never called" assert offline_indices[0] < shutdown_called_at_index, ( f"OFFLINE (index {offline_indices[0]}) must be reported before " @@ -1090,12 +1079,8 @@ def mock_shutdown(**kwargs): mock_request_release, ) - 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}" - ) + 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}" assert shutdown_called_at_index is not None, "shutdown was never called" assert offline_indices[0] < shutdown_called_at_index, ( f"OFFLINE (index {offline_indices[0]}) must be reported before " @@ -1143,9 +1128,7 @@ async def mock_report_status(status, msg): # afterLease hook should run and transition to AVAILABLE 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}" async def test_hook_socket_message_at_debug_not_info(self, lease_scope) -> None: """The 'Using dedicated hook socket' message must be at DEBUG, not INFO. From dd67d682fc44f181c3925d052c3dd3aadf049fce Mon Sep 17 00:00:00 2001 From: Paul Wallrabe Date: Thu, 16 Apr 2026 21:20:58 +0200 Subject: [PATCH 3/9] fix: prepend source tag to log messages in client-side log_stream_async 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 --- .../jumpstarter/jumpstarter/client/core.py | 4 +- .../jumpstarter/client/core_test.py | 226 +++++++++++++++++- 2 files changed, 227 insertions(+), 3 deletions(-) diff --git a/python/packages/jumpstarter/jumpstarter/client/core.py b/python/packages/jumpstarter/jumpstarter/client/core.py index 0612792be..32115b1cb 100644 --- a/python/packages/jumpstarter/jumpstarter/client/core.py +++ b/python/packages/jumpstarter/jumpstarter/client/core.py @@ -505,9 +505,9 @@ async def log_stream(): # noqa: C901 else: # SYSTEM logger_name = "exporter:system" - # Log through logger for RichHandler formatting source_logger = logging.getLogger(logger_name) - source_logger.log(log_level, response.message) + tagged_message = f"[{logger_name}] {response.message}" + source_logger.log(log_level, tagged_message) # Stream ended normally (server closed it) self.logger.debug("Log stream ended normally, attempting reconnect...") diff --git a/python/packages/jumpstarter/jumpstarter/client/core_test.py b/python/packages/jumpstarter/jumpstarter/client/core_test.py index 60b6fb622..55b1cd585 100644 --- a/python/packages/jumpstarter/jumpstarter/client/core_test.py +++ b/python/packages/jumpstarter/jumpstarter/client/core_test.py @@ -1,5 +1,6 @@ """Tests for AsyncDriverClient async status methods.""" +import logging from dataclasses import dataclass from unittest.mock import AsyncMock, MagicMock from uuid import uuid4 @@ -8,7 +9,7 @@ from grpc import StatusCode from grpc.aio import AioRpcError -from jumpstarter.common import ExporterStatus, Metadata +from jumpstarter.common import ExporterStatus, LogSource, Metadata pytestmark = pytest.mark.anyio @@ -293,3 +294,226 @@ async def test_wait_for_hook_status_unimplemented_returns_true(self) -> None: # Should return True (backward compatibility - assume hook complete) assert result is True + + +def create_log_stream_response(message: str, severity: str = "INFO", source=None): + """Create a mock LogStreamResponse.""" + response = MagicMock() + response.message = message + response.severity = severity + if source is not None: + response.HasField = lambda field: field == "source" + response.source = source.to_proto() + else: + response.HasField = lambda field: False + response.source = None + return response + + +class LogCapture(logging.Handler): + """Captures log records for assertion in tests.""" + + def __init__(self): + super().__init__() + self.records: list[logging.LogRecord] = [] + + def emit(self, record): + self.records.append(record) + + +SOURCE_LOGGER_NAMES = [ + "exporter:beforeLease", + "exporter:afterLease", + "exporter:driver", + "exporter:system", +] + + +def setup_log_stream_client(responses, show_all_logs=True): + """Set up a mock client with LogStream responses and capturing loggers. + + Returns (client, captures) where captures is a dict + mapping logger name to LogCapture handler. + + The mock LogStream yields all responses once and then raises + CANCELLED on subsequent calls to prevent reconnect loops. + """ + from jumpstarter.client.core import AsyncDriverClient + + call_count = 0 + + async def mock_log_stream(_): + nonlocal call_count + call_count += 1 + if call_count > 1: + raise create_mock_rpc_error(StatusCode.CANCELLED) + for r in responses: + yield r + + stub = MagicMock() + stub.LogStream = mock_log_stream + + client = MagicMock(spec=AsyncDriverClient) + client.stub = stub + client.logger = logging.getLogger("test_log_stream_client") + client.log_stream_async = AsyncDriverClient.log_stream_async.__get__(client) + + captures = {} + for name in SOURCE_LOGGER_NAMES: + logger = logging.getLogger(name) + logger.setLevel(logging.DEBUG) + logger.handlers.clear() + capture = LogCapture() + logger.addHandler(capture) + captures[name] = capture + + return client, captures + + +@pytest.fixture(autouse=True) +def _clean_source_loggers(): + """Remove handlers from source loggers after each test.""" + yield + for name in SOURCE_LOGGER_NAMES: + logger = logging.getLogger(name) + logger.handlers.clear() + + +class TestLogStreamSourceTagPlacement: + async def test_hook_log_message_prepends_source_tag(self) -> None: + """F001: Source tag must appear at the beginning of each log message, not at the end.""" + responses = [ + create_log_stream_response( + "hook output line", + severity="INFO", + source=LogSource.BEFORE_LEASE_HOOK, + ), + ] + + client, captures = setup_log_stream_client(responses) + + async with client.log_stream_async(show_all_logs=True): + import anyio + await anyio.sleep(0.1) + + records = captures["exporter:beforeLease"].records + assert len(records) == 1 + assert records[0].getMessage().startswith("[exporter:beforeLease]"), ( + f"Expected message to start with '[exporter:beforeLease]', " + f"got: '{records[0].getMessage()}'" + ) + + async def test_after_lease_hook_log_prepends_source_tag(self) -> None: + """Source tag for afterLease hook must appear at the beginning.""" + responses = [ + create_log_stream_response( + "cleanup output", + severity="INFO", + source=LogSource.AFTER_LEASE_HOOK, + ), + ] + + client, captures = setup_log_stream_client(responses) + + async with client.log_stream_async(show_all_logs=True): + import anyio + await anyio.sleep(0.1) + + records = captures["exporter:afterLease"].records + assert len(records) == 1 + assert records[0].getMessage().startswith("[exporter:afterLease]"), ( + f"Expected message to start with '[exporter:afterLease]', " + f"got: '{records[0].getMessage()}'" + ) + + +class TestLogStreamFiltering: + async def test_show_all_logs_false_filters_system_logs(self) -> None: + """F041: With show_all_logs=False, system/debug logs must be filtered out.""" + responses = [ + create_log_stream_response( + "debug system message", + severity="DEBUG", + source=LogSource.SYSTEM, + ), + create_log_stream_response( + "hook output line", + severity="INFO", + source=LogSource.BEFORE_LEASE_HOOK, + ), + ] + + client, captures = setup_log_stream_client(responses, show_all_logs=False) + + async with client.log_stream_async(show_all_logs=False): + import anyio + await anyio.sleep(0.1) + + system_records = captures["exporter:system"].records + hook_records = captures["exporter:beforeLease"].records + assert len(system_records) == 0, ( + f"Expected 0 system log records with show_all_logs=False, got {len(system_records)}" + ) + assert len(hook_records) == 1, ( + f"Expected 1 hook log record, got {len(hook_records)}" + ) + + async def test_show_all_logs_false_shows_hook_logs(self) -> None: + """With show_all_logs=False, hook logs must still be displayed.""" + responses = [ + create_log_stream_response( + "before hook output", + severity="INFO", + source=LogSource.BEFORE_LEASE_HOOK, + ), + create_log_stream_response( + "after hook output", + severity="INFO", + source=LogSource.AFTER_LEASE_HOOK, + ), + ] + + client, captures = setup_log_stream_client(responses, show_all_logs=False) + + async with client.log_stream_async(show_all_logs=False): + import anyio + await anyio.sleep(0.1) + + before_records = captures["exporter:beforeLease"].records + after_records = captures["exporter:afterLease"].records + assert len(before_records) == 1, ( + f"Expected 1 beforeLease log record, got {len(before_records)}" + ) + assert len(after_records) == 1, ( + f"Expected 1 afterLease log record, got {len(after_records)}" + ) + + async def test_show_all_logs_true_shows_system_logs(self) -> None: + """With show_all_logs=True (default), system logs must be displayed.""" + responses = [ + create_log_stream_response( + "system message", + severity="INFO", + source=LogSource.SYSTEM, + ), + create_log_stream_response( + "hook output line", + severity="INFO", + source=LogSource.BEFORE_LEASE_HOOK, + ), + ] + + client, captures = setup_log_stream_client(responses, show_all_logs=True) + + async with client.log_stream_async(show_all_logs=True): + import anyio + await anyio.sleep(0.1) + + system_records = captures["exporter:system"].records + hook_records = captures["exporter:beforeLease"].records + assert len(system_records) == 1, ( + f"Expected 1 system log record, got {len(system_records)}" + ) + assert len(hook_records) == 1, ( + f"Expected 1 hook log record, got {len(hook_records)}" + ) From 306fc0801e0b3c21535b1173b475a767fb0c7813 Mon Sep 17 00:00:00 2001 From: Paul Wallrabe Date: Thu, 16 Apr 2026 21:34:44 +0200 Subject: [PATCH 4/9] fix: remove double-tagging of source in client log_stream_async 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 --- .../jumpstarter/jumpstarter/client/core.py | 3 +- .../jumpstarter/client/core_test.py | 48 +++++++++++++++---- 2 files changed, 41 insertions(+), 10 deletions(-) diff --git a/python/packages/jumpstarter/jumpstarter/client/core.py b/python/packages/jumpstarter/jumpstarter/client/core.py index 32115b1cb..33b672a93 100644 --- a/python/packages/jumpstarter/jumpstarter/client/core.py +++ b/python/packages/jumpstarter/jumpstarter/client/core.py @@ -506,8 +506,7 @@ async def log_stream(): # noqa: C901 logger_name = "exporter:system" source_logger = logging.getLogger(logger_name) - tagged_message = f"[{logger_name}] {response.message}" - source_logger.log(log_level, tagged_message) + source_logger.log(log_level, response.message) # Stream ended normally (server closed it) self.logger.debug("Log stream ended normally, attempting reconnect...") diff --git a/python/packages/jumpstarter/jumpstarter/client/core_test.py b/python/packages/jumpstarter/jumpstarter/client/core_test.py index 55b1cd585..dcf92d546 100644 --- a/python/packages/jumpstarter/jumpstarter/client/core_test.py +++ b/python/packages/jumpstarter/jumpstarter/client/core_test.py @@ -380,8 +380,8 @@ def _clean_source_loggers(): class TestLogStreamSourceTagPlacement: - async def test_hook_log_message_prepends_source_tag(self) -> None: - """F001: Source tag must appear at the beginning of each log message, not at the end.""" + async def test_hook_log_delegates_tagging_to_formatter(self) -> None: + """F050: core.py must NOT prepend source tags -- SourcePrefixFormatter handles that.""" responses = [ create_log_stream_response( "hook output line", @@ -398,13 +398,14 @@ async def test_hook_log_message_prepends_source_tag(self) -> None: records = captures["exporter:beforeLease"].records assert len(records) == 1 - assert records[0].getMessage().startswith("[exporter:beforeLease]"), ( - f"Expected message to start with '[exporter:beforeLease]', " + assert records[0].getMessage() == "hook output line", ( + f"Expected raw message without tag prefix, " f"got: '{records[0].getMessage()}'" ) + assert records[0].name == "exporter:beforeLease" - async def test_after_lease_hook_log_prepends_source_tag(self) -> None: - """Source tag for afterLease hook must appear at the beginning.""" + async def test_after_lease_hook_log_delegates_tagging_to_formatter(self) -> None: + """F050: afterLease source tag must come from formatter, not from core.py.""" responses = [ create_log_stream_response( "cleanup output", @@ -421,10 +422,41 @@ async def test_after_lease_hook_log_prepends_source_tag(self) -> None: records = captures["exporter:afterLease"].records assert len(records) == 1 - assert records[0].getMessage().startswith("[exporter:afterLease]"), ( - f"Expected message to start with '[exporter:afterLease]', " + assert records[0].getMessage() == "cleanup output", ( + f"Expected raw message without tag prefix, " f"got: '{records[0].getMessage()}'" ) + assert records[0].name == "exporter:afterLease" + + async def test_logger_name_carries_source_for_formatter(self) -> None: + """F050: source_logger.name must carry the source tag so formatters can use it.""" + responses = [ + create_log_stream_response( + "line one", + severity="INFO", + source=LogSource.BEFORE_LEASE_HOOK, + ), + create_log_stream_response( + "line two", + severity="INFO", + source=LogSource.AFTER_LEASE_HOOK, + ), + ] + + client, captures = setup_log_stream_client(responses) + + async with client.log_stream_async(show_all_logs=True): + import anyio + await anyio.sleep(0.1) + + before_records = captures["exporter:beforeLease"].records + after_records = captures["exporter:afterLease"].records + assert len(before_records) == 1 + assert before_records[0].name == "exporter:beforeLease" + assert before_records[0].getMessage() == "line one" + assert len(after_records) == 1 + assert after_records[0].name == "exporter:afterLease" + assert after_records[0].getMessage() == "line two" class TestLogStreamFiltering: From 559e05ca54dbed4651057aa972860217ad0dfc5d Mon Sep 17 00:00:00 2001 From: Paul Wallrabe Date: Fri, 17 Apr 2026 12:38:07 +0200 Subject: [PATCH 5/9] fix: address review feedback on log levels and formatting 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 --- .../jumpstarter/jumpstarter/client/core.py | 1 + .../jumpstarter/jumpstarter/exporter/hooks.py | 8 +-- .../jumpstarter/exporter/hooks_test.py | 66 ++++++++++++------- 3 files changed, 46 insertions(+), 29 deletions(-) diff --git a/python/packages/jumpstarter/jumpstarter/client/core.py b/python/packages/jumpstarter/jumpstarter/client/core.py index 33b672a93..0612792be 100644 --- a/python/packages/jumpstarter/jumpstarter/client/core.py +++ b/python/packages/jumpstarter/jumpstarter/client/core.py @@ -505,6 +505,7 @@ async def log_stream(): # noqa: C901 else: # SYSTEM logger_name = "exporter:system" + # Log through logger for RichHandler formatting source_logger = logging.getLogger(logger_name) source_logger.log(log_level, response.message) diff --git a/python/packages/jumpstarter/jumpstarter/exporter/hooks.py b/python/packages/jumpstarter/jumpstarter/exporter/hooks.py index 124a0a19a..dda80f2a5 100644 --- a/python/packages/jumpstarter/jumpstarter/exporter/hooks.py +++ b/python/packages/jumpstarter/jumpstarter/exporter/hooks.py @@ -531,7 +531,7 @@ async def execute_before_lease_hook(self, lease_scope: "LeaseContext") -> str | logger.debug("No before-lease hook configured") return None - logger.debug("Executing before-lease hook for lease %s", lease_scope.lease_name) + logger.info("Executing before-lease hook for lease %s", lease_scope.lease_name) return await self._execute_hook( self.config.before_lease, lease_scope, @@ -554,7 +554,7 @@ async def execute_after_lease_hook(self, lease_scope: "LeaseContext") -> str | N logger.debug("No after-lease hook configured") return None - logger.debug("Executing after-lease hook for lease %s", lease_scope.lease_name) + logger.info("Executing after-lease hook for lease %s", lease_scope.lease_name) return await self._execute_hook( self.config.after_lease, lease_scope, @@ -608,7 +608,7 @@ async def run_before_lease_hook( await report_status(ExporterStatus.BEFORE_LEASE_HOOK, "Running beforeLease hook") # Execute hook with lease scope - logger.debug("Executing before-lease hook for lease %s", lease_scope.lease_name) + logger.info("Executing before-lease hook for lease %s", lease_scope.lease_name) warning = await self._execute_hook( self.config.before_lease, lease_scope, @@ -699,7 +699,7 @@ async def run_after_lease_hook( await report_status(ExporterStatus.AFTER_LEASE_HOOK, "Running afterLease hooks") # Execute hook with lease scope - logger.debug("Executing after-lease hook for lease %s", lease_scope.lease_name) + logger.info("Executing after-lease hook for lease %s", lease_scope.lease_name) warning = await self._execute_hook( self.config.after_lease, lease_scope, diff --git a/python/packages/jumpstarter/jumpstarter/exporter/hooks_test.py b/python/packages/jumpstarter/jumpstarter/exporter/hooks_test.py index 01f673709..0ffac8e10 100644 --- a/python/packages/jumpstarter/jumpstarter/exporter/hooks_test.py +++ b/python/packages/jumpstarter/jumpstarter/exporter/hooks_test.py @@ -853,7 +853,8 @@ async def mock_report_status(status, msg): # Should have reported LEASE_READY assert any( - status == ExporterStatus.LEASE_READY and msg == "Ready for commands" for status, msg in status_calls + status == ExporterStatus.LEASE_READY and msg == "Ready for commands" + for status, msg in status_calls ), f"Expected LEASE_READY status, got: {status_calls}" async def test_skip_after_lease_prevents_after_hook_execution(self, lease_scope) -> None: @@ -928,11 +929,15 @@ async def mock_report_status(status, msg): # Last status should be OFFLINE (reported before shutdown to prevent new leases) last_status, _ = status_calls[-1] - assert last_status == ExporterStatus.OFFLINE, f"Expected last status to be OFFLINE, got {last_status}" + assert last_status == ExporterStatus.OFFLINE, ( + f"Expected last status to be OFFLINE, got {last_status}" + ) # BEFORE_LEASE_HOOK_FAILED should also be present (reported before OFFLINE) failed_statuses = [s for s, _ in status_calls if s == ExporterStatus.BEFORE_LEASE_HOOK_FAILED] - 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}" + ) # AVAILABLE should never have been reported available_statuses = [s for s, _ in status_calls if s == ExporterStatus.AVAILABLE] @@ -973,7 +978,9 @@ async def mock_report_status(status, msg): # AFTER_LEASE_HOOK_FAILED should be in statuses failed_statuses = [s for s, _ in status_calls if s == ExporterStatus.AFTER_LEASE_HOOK_FAILED] - 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}" + ) # AVAILABLE should NOT be in statuses available_statuses = [s for s, _ in status_calls if s == ExporterStatus.AVAILABLE] @@ -1044,8 +1051,12 @@ def mock_shutdown(**kwargs): mock_shutdown, ) - 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}" + 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}" + ) assert shutdown_called_at_index is not None, "shutdown was never called" assert offline_indices[0] < shutdown_called_at_index, ( f"OFFLINE (index {offline_indices[0]}) must be reported before " @@ -1079,8 +1090,12 @@ def mock_shutdown(**kwargs): mock_request_release, ) - 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}" + 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}" + ) assert shutdown_called_at_index is not None, "shutdown was never called" assert offline_indices[0] < shutdown_called_at_index, ( f"OFFLINE (index {offline_indices[0]}) must be reported before " @@ -1128,7 +1143,9 @@ async def mock_report_status(status, msg): # afterLease hook should run and transition to AVAILABLE 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}" + ) async def test_hook_socket_message_at_debug_not_info(self, lease_scope) -> None: """The 'Using dedicated hook socket' message must be at DEBUG, not INFO. @@ -1156,12 +1173,12 @@ async def test_hook_socket_message_at_debug_not_info(self, lease_scope) -> None: "'Using dedicated hook socket' should NOT be at INFO level" ) - async def test_orchestration_messages_at_debug_not_info(self, lease_scope) -> None: - """Orchestration messages from execute_before/after_lease_hook must be at DEBUG. + async def test_completion_messages_at_debug_not_info(self, lease_scope) -> None: + """Hook completion messages must be at DEBUG, not INFO. - Messages like 'Executing before-lease hook for lease' and - 'beforeLease hook completed successfully' are not inside - context_log_source so they add noise without value to the client. + Hook start messages ('Executing before-lease hook') stay at INFO + because they are useful when hooks are slow. Only the completion + messages are demoted to DEBUG. """ hook_config = HookConfigV1Alpha1( before_lease=HookInstanceConfigV1Alpha1(script="echo 'hello'", timeout=10), @@ -1185,17 +1202,16 @@ async def mock_report_status(status, msg): debug_calls = [str(call) for call in mock_logger.debug.call_args_list] info_calls = [str(call) for call in mock_logger.info.call_args_list] - orchestration_messages = [ - "Executing before-lease hook for lease", - "beforeLease hook completed successfully", - ] - for msg in orchestration_messages: - assert any(msg in call for call in debug_calls), ( - f"Expected '{msg}' at DEBUG level, not found in debug calls" - ) - assert not any(msg in call for call in info_calls), ( - f"Orchestration message '{msg}' should NOT be at INFO level" - ) + assert any("beforeLease hook completed successfully" in call for call in debug_calls), ( + "Expected 'beforeLease hook completed successfully' at DEBUG level" + ) + assert not any("beforeLease hook completed successfully" in call for call in info_calls), ( + "'beforeLease hook completed successfully' should NOT be at INFO level" + ) + + assert any("Executing before-lease hook for lease" in call for call in info_calls), ( + "Expected 'Executing before-lease hook' at INFO level" + ) async def test_after_hook_warn_includes_warning_prefix(self, lease_scope) -> None: """Issue E5b: afterLease hook fail with warn should include HOOK_WARNING_PREFIX. From 7abdb3dfe94dd613d99b7cde6c07bec8fedc81a1 Mon Sep 17 00:00:00 2001 From: Paul Wallrabe Date: Fri, 17 Apr 2026 15:58:54 +0200 Subject: [PATCH 6/9] fix: improve test coverage with event-based synchronization 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 --- .../jumpstarter/client/core_test.py | 128 +++++++++--------- 1 file changed, 63 insertions(+), 65 deletions(-) diff --git a/python/packages/jumpstarter/jumpstarter/client/core_test.py b/python/packages/jumpstarter/jumpstarter/client/core_test.py index dcf92d546..e437fe91e 100644 --- a/python/packages/jumpstarter/jumpstarter/client/core_test.py +++ b/python/packages/jumpstarter/jumpstarter/client/core_test.py @@ -5,6 +5,7 @@ from unittest.mock import AsyncMock, MagicMock from uuid import uuid4 +import anyio import pytest from grpc import StatusCode from grpc.aio import AioRpcError @@ -330,25 +331,15 @@ def emit(self, record): def setup_log_stream_client(responses, show_all_logs=True): - """Set up a mock client with LogStream responses and capturing loggers. - - Returns (client, captures) where captures is a dict - mapping logger name to LogCapture handler. - - The mock LogStream yields all responses once and then raises - CANCELLED on subsequent calls to prevent reconnect loops. - """ from jumpstarter.client.core import AsyncDriverClient - call_count = 0 + all_delivered = anyio.Event() async def mock_log_stream(_): - nonlocal call_count - call_count += 1 - if call_count > 1: - raise create_mock_rpc_error(StatusCode.CANCELLED) for r in responses: yield r + all_delivered.set() + await anyio.sleep_forever() stub = MagicMock() stub.LogStream = mock_log_stream @@ -367,21 +358,36 @@ async def mock_log_stream(_): logger.addHandler(capture) captures[name] = capture - return client, captures + return client, captures, all_delivered @pytest.fixture(autouse=True) def _clean_source_loggers(): - """Remove handlers from source loggers after each test.""" yield for name in SOURCE_LOGGER_NAMES: logger = logging.getLogger(name) logger.handlers.clear() +class TestLogStreamResponseFactory: + def test_create_response_without_source(self) -> None: + response = create_log_stream_response("plain message") + assert response.message == "plain message" + assert response.severity == "INFO" + assert response.HasField("source") is False + assert response.source is None + + def test_create_response_with_source(self) -> None: + response = create_log_stream_response( + "hook message", severity="DEBUG", source=LogSource.BEFORE_LEASE_HOOK + ) + assert response.message == "hook message" + assert response.severity == "DEBUG" + assert response.HasField("source") is True + + class TestLogStreamSourceTagPlacement: async def test_hook_log_delegates_tagging_to_formatter(self) -> None: - """F050: core.py must NOT prepend source tags -- SourcePrefixFormatter handles that.""" responses = [ create_log_stream_response( "hook output line", @@ -390,22 +396,18 @@ async def test_hook_log_delegates_tagging_to_formatter(self) -> None: ), ] - client, captures = setup_log_stream_client(responses) + client, captures, delivered = setup_log_stream_client(responses) async with client.log_stream_async(show_all_logs=True): - import anyio - await anyio.sleep(0.1) + with anyio.fail_after(2): + await delivered.wait() records = captures["exporter:beforeLease"].records assert len(records) == 1 - assert records[0].getMessage() == "hook output line", ( - f"Expected raw message without tag prefix, " - f"got: '{records[0].getMessage()}'" - ) + assert records[0].getMessage() == "hook output line" assert records[0].name == "exporter:beforeLease" async def test_after_lease_hook_log_delegates_tagging_to_formatter(self) -> None: - """F050: afterLease source tag must come from formatter, not from core.py.""" responses = [ create_log_stream_response( "cleanup output", @@ -414,22 +416,18 @@ async def test_after_lease_hook_log_delegates_tagging_to_formatter(self) -> None ), ] - client, captures = setup_log_stream_client(responses) + client, captures, delivered = setup_log_stream_client(responses) async with client.log_stream_async(show_all_logs=True): - import anyio - await anyio.sleep(0.1) + with anyio.fail_after(2): + await delivered.wait() records = captures["exporter:afterLease"].records assert len(records) == 1 - assert records[0].getMessage() == "cleanup output", ( - f"Expected raw message without tag prefix, " - f"got: '{records[0].getMessage()}'" - ) + assert records[0].getMessage() == "cleanup output" assert records[0].name == "exporter:afterLease" async def test_logger_name_carries_source_for_formatter(self) -> None: - """F050: source_logger.name must carry the source tag so formatters can use it.""" responses = [ create_log_stream_response( "line one", @@ -443,11 +441,11 @@ async def test_logger_name_carries_source_for_formatter(self) -> None: ), ] - client, captures = setup_log_stream_client(responses) + client, captures, delivered = setup_log_stream_client(responses) async with client.log_stream_async(show_all_logs=True): - import anyio - await anyio.sleep(0.1) + with anyio.fail_after(2): + await delivered.wait() before_records = captures["exporter:beforeLease"].records after_records = captures["exporter:afterLease"].records @@ -461,7 +459,6 @@ async def test_logger_name_carries_source_for_formatter(self) -> None: class TestLogStreamFiltering: async def test_show_all_logs_false_filters_system_logs(self) -> None: - """F041: With show_all_logs=False, system/debug logs must be filtered out.""" responses = [ create_log_stream_response( "debug system message", @@ -475,23 +472,18 @@ async def test_show_all_logs_false_filters_system_logs(self) -> None: ), ] - client, captures = setup_log_stream_client(responses, show_all_logs=False) + client, captures, delivered = setup_log_stream_client(responses, show_all_logs=False) async with client.log_stream_async(show_all_logs=False): - import anyio - await anyio.sleep(0.1) + with anyio.fail_after(2): + await delivered.wait() system_records = captures["exporter:system"].records hook_records = captures["exporter:beforeLease"].records - assert len(system_records) == 0, ( - f"Expected 0 system log records with show_all_logs=False, got {len(system_records)}" - ) - assert len(hook_records) == 1, ( - f"Expected 1 hook log record, got {len(hook_records)}" - ) + assert len(system_records) == 0 + assert len(hook_records) == 1 async def test_show_all_logs_false_shows_hook_logs(self) -> None: - """With show_all_logs=False, hook logs must still be displayed.""" responses = [ create_log_stream_response( "before hook output", @@ -505,23 +497,18 @@ async def test_show_all_logs_false_shows_hook_logs(self) -> None: ), ] - client, captures = setup_log_stream_client(responses, show_all_logs=False) + client, captures, delivered = setup_log_stream_client(responses, show_all_logs=False) async with client.log_stream_async(show_all_logs=False): - import anyio - await anyio.sleep(0.1) + with anyio.fail_after(2): + await delivered.wait() before_records = captures["exporter:beforeLease"].records after_records = captures["exporter:afterLease"].records - assert len(before_records) == 1, ( - f"Expected 1 beforeLease log record, got {len(before_records)}" - ) - assert len(after_records) == 1, ( - f"Expected 1 afterLease log record, got {len(after_records)}" - ) + assert len(before_records) == 1 + assert len(after_records) == 1 async def test_show_all_logs_true_shows_system_logs(self) -> None: - """With show_all_logs=True (default), system logs must be displayed.""" responses = [ create_log_stream_response( "system message", @@ -535,17 +522,28 @@ async def test_show_all_logs_true_shows_system_logs(self) -> None: ), ] - client, captures = setup_log_stream_client(responses, show_all_logs=True) + client, captures, delivered = setup_log_stream_client(responses, show_all_logs=True) async with client.log_stream_async(show_all_logs=True): - import anyio - await anyio.sleep(0.1) + with anyio.fail_after(2): + await delivered.wait() system_records = captures["exporter:system"].records hook_records = captures["exporter:beforeLease"].records - assert len(system_records) == 1, ( - f"Expected 1 system log record, got {len(system_records)}" - ) - assert len(hook_records) == 1, ( - f"Expected 1 hook log record, got {len(hook_records)}" - ) + assert len(system_records) == 1 + assert len(hook_records) == 1 + + async def test_log_without_source_routes_to_system(self) -> None: + responses = [ + create_log_stream_response("no source message"), + ] + + client, captures, delivered = setup_log_stream_client(responses, show_all_logs=True) + + async with client.log_stream_async(show_all_logs=True): + with anyio.fail_after(2): + await delivered.wait() + + system_records = captures["exporter:system"].records + assert len(system_records) == 1 + assert system_records[0].getMessage() == "no source message" From 0c88e7376e409d36b4a344cf30bb623d66e22c66 Mon Sep 17 00:00:00 2001 From: Paul Wallrabe Date: Mon, 20 Apr 2026 16:18:51 +0200 Subject: [PATCH 7/9] fix: remove unused show_all_logs parameter from setup_log_stream_client 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 --- .../jumpstarter/jumpstarter/client/core_test.py | 10 +++++----- 1 file changed, 5 insertions(+), 5 deletions(-) diff --git a/python/packages/jumpstarter/jumpstarter/client/core_test.py b/python/packages/jumpstarter/jumpstarter/client/core_test.py index e437fe91e..f6fd5faee 100644 --- a/python/packages/jumpstarter/jumpstarter/client/core_test.py +++ b/python/packages/jumpstarter/jumpstarter/client/core_test.py @@ -330,7 +330,7 @@ def emit(self, record): ] -def setup_log_stream_client(responses, show_all_logs=True): +def setup_log_stream_client(responses): from jumpstarter.client.core import AsyncDriverClient all_delivered = anyio.Event() @@ -472,7 +472,7 @@ async def test_show_all_logs_false_filters_system_logs(self) -> None: ), ] - client, captures, delivered = setup_log_stream_client(responses, show_all_logs=False) + client, captures, delivered = setup_log_stream_client(responses) async with client.log_stream_async(show_all_logs=False): with anyio.fail_after(2): @@ -497,7 +497,7 @@ async def test_show_all_logs_false_shows_hook_logs(self) -> None: ), ] - client, captures, delivered = setup_log_stream_client(responses, show_all_logs=False) + client, captures, delivered = setup_log_stream_client(responses) async with client.log_stream_async(show_all_logs=False): with anyio.fail_after(2): @@ -522,7 +522,7 @@ async def test_show_all_logs_true_shows_system_logs(self) -> None: ), ] - client, captures, delivered = setup_log_stream_client(responses, show_all_logs=True) + client, captures, delivered = setup_log_stream_client(responses) async with client.log_stream_async(show_all_logs=True): with anyio.fail_after(2): @@ -538,7 +538,7 @@ async def test_log_without_source_routes_to_system(self) -> None: create_log_stream_response("no source message"), ] - client, captures, delivered = setup_log_stream_client(responses, show_all_logs=True) + client, captures, delivered = setup_log_stream_client(responses) async with client.log_stream_async(show_all_logs=True): with anyio.fail_after(2): From 931de858c5b62bc82da94e3215bbeb3f20942ba4 Mon Sep 17 00:00:00 2001 From: Paul Wallrabe Date: Mon, 20 Apr 2026 16:20:07 +0200 Subject: [PATCH 8/9] fix: keep hook completion messages at INFO level for monitoring 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 --- .../jumpstarter/jumpstarter/exporter/hooks.py | 4 ++-- .../jumpstarter/exporter/hooks_test.py | 17 ++++------------- 2 files changed, 6 insertions(+), 15 deletions(-) diff --git a/python/packages/jumpstarter/jumpstarter/exporter/hooks.py b/python/packages/jumpstarter/jumpstarter/exporter/hooks.py index dda80f2a5..3f9fabda6 100644 --- a/python/packages/jumpstarter/jumpstarter/exporter/hooks.py +++ b/python/packages/jumpstarter/jumpstarter/exporter/hooks.py @@ -620,7 +620,7 @@ async def run_before_lease_hook( else: msg = "Ready for commands" await report_status(ExporterStatus.LEASE_READY, msg) - logger.debug("beforeLease hook completed successfully") + logger.info("beforeLease hook completed successfully") except HookExecutionError as e: if e.should_shutdown_exporter(): @@ -711,7 +711,7 @@ async def run_after_lease_hook( else: msg = "Available for new lease" await report_status(ExporterStatus.AVAILABLE, msg) - logger.debug("afterLease hook completed successfully") + logger.info("afterLease hook completed successfully") except HookExecutionError as e: if e.should_shutdown_exporter(): diff --git a/python/packages/jumpstarter/jumpstarter/exporter/hooks_test.py b/python/packages/jumpstarter/jumpstarter/exporter/hooks_test.py index 0ffac8e10..83b268791 100644 --- a/python/packages/jumpstarter/jumpstarter/exporter/hooks_test.py +++ b/python/packages/jumpstarter/jumpstarter/exporter/hooks_test.py @@ -1173,13 +1173,8 @@ async def test_hook_socket_message_at_debug_not_info(self, lease_scope) -> None: "'Using dedicated hook socket' should NOT be at INFO level" ) - async def test_completion_messages_at_debug_not_info(self, lease_scope) -> None: - """Hook completion messages must be at DEBUG, not INFO. - - Hook start messages ('Executing before-lease hook') stay at INFO - because they are useful when hooks are slow. Only the completion - messages are demoted to DEBUG. - """ + async def test_completion_messages_at_info(self, lease_scope) -> None: + """Hook completion messages remain at INFO for monitoring slow hooks.""" hook_config = HookConfigV1Alpha1( before_lease=HookInstanceConfigV1Alpha1(script="echo 'hello'", timeout=10), ) @@ -1199,14 +1194,10 @@ async def mock_report_status(status, msg): mock_shutdown, ) - debug_calls = [str(call) for call in mock_logger.debug.call_args_list] info_calls = [str(call) for call in mock_logger.info.call_args_list] - assert any("beforeLease hook completed successfully" in call for call in debug_calls), ( - "Expected 'beforeLease hook completed successfully' at DEBUG level" - ) - assert not any("beforeLease hook completed successfully" in call for call in info_calls), ( - "'beforeLease hook completed successfully' should NOT be at INFO level" + assert any("beforeLease hook completed successfully" in call for call in info_calls), ( + "Expected 'beforeLease hook completed successfully' at INFO level" ) assert any("Executing before-lease hook for lease" in call for call in info_calls), ( From f047439cb92dd2a594b9280c1e8aa2073ca53ea5 Mon Sep 17 00:00:00 2001 From: Paul Wallrabe Date: Mon, 20 Apr 2026 16:21:01 +0200 Subject: [PATCH 9/9] refactor: extract safety timeout magic numbers into named constants 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 --- .../packages/jumpstarter/jumpstarter/exporter/exporter.py | 7 +++++-- 1 file changed, 5 insertions(+), 2 deletions(-) diff --git a/python/packages/jumpstarter/jumpstarter/exporter/exporter.py b/python/packages/jumpstarter/jumpstarter/exporter/exporter.py index 236651766..2d6cf632d 100644 --- a/python/packages/jumpstarter/jumpstarter/exporter/exporter.py +++ b/python/packages/jumpstarter/jumpstarter/exporter/exporter.py @@ -35,6 +35,9 @@ logger = logging.getLogger(__name__) +DEFAULT_SAFETY_TIMEOUT_SECONDS = 15 +HOOK_TIMEOUT_MARGIN_SECONDS = 30 + async def _standalone_shutdown_waiter(): """Wait forever; used so serve_standalone_tcp can be cancelled by stop().""" @@ -601,12 +604,12 @@ async def _cleanup_after_lease(self, lease_scope: LeaseContext) -> None: # was never set due to a race (e.g. conn_tg cancelled early). # Use the configured hook timeout (+ margin) when available so we # never interrupt a legitimately-running beforeLease hook. - safety_timeout = 15 # generous default for no-hook / unknown cases + safety_timeout = DEFAULT_SAFETY_TIMEOUT_SECONDS if ( self.hook_executor and self.hook_executor.config.before_lease ): - safety_timeout = self.hook_executor.config.before_lease.timeout + 30 + safety_timeout = self.hook_executor.config.before_lease.timeout + HOOK_TIMEOUT_MARGIN_SECONDS with move_on_after(safety_timeout) as timeout_scope: await lease_scope.before_lease_hook.wait() if timeout_scope.cancelled_caught: