diff --git a/packages/jumpstarter/jumpstarter/client/lease.py b/packages/jumpstarter/jumpstarter/client/lease.py index 289f5efce..fc61d45f6 100644 --- a/packages/jumpstarter/jumpstarter/client/lease.py +++ b/packages/jumpstarter/jumpstarter/client/lease.py @@ -159,7 +159,7 @@ async def _acquire(self): # lease ready if condition_true(result.conditions, "Ready"): logger.debug("Lease %s acquired", self.name) - spinner.update_status(f"Lease {self.name} acquired successfully!") + spinner.update_status(f"Lease {self.name} acquired successfully!", force=True) self.exporter_name = result.exporter break @@ -332,6 +332,8 @@ def __init__(self, lease_name: str | None = None): self.start_time = None self._should_show_spinner = self._is_terminal_available() and not self._is_non_interactive() self._current_message = None + self._last_log_time = None + self._log_throttle_interval = timedelta(minutes=5) def _is_non_interactive(self) -> bool: """Check if the user desires a NONINTERACTIVE environment.""" @@ -359,8 +361,12 @@ def __exit__(self, exc_type, exc_val, exc_tb): if self.spinner: self.spinner.stop() - def update_status(self, message: str): - """Update the spinner status message.""" + def update_status(self, message: str, force: bool = False): + """Update the spinner status message. + + :param message: The status message to display + :param force: If True, always log the message even when throttling (default: False) + """ if self.spinner and self._should_show_spinner: self._current_message = f"[blue]{message}[/blue]" elapsed = datetime.now() - self.start_time @@ -368,9 +374,19 @@ def update_status(self, message: str): self.spinner.update(f"{self._current_message} [dim]({elapsed_str})[/dim]") else: # Log info message when no console is available - elapsed = datetime.now() - self.start_time - elapsed_str = str(elapsed).split(".")[0] # Remove microseconds - logger.info(f"{message} ({elapsed_str})") + # Throttle updates to at most every 5 minutes unless forced + now = datetime.now() + should_log = ( + force + or self._last_log_time is None + or (now - self._last_log_time) >= self._log_throttle_interval + ) + + if should_log: + elapsed = now - self.start_time + elapsed_str = str(elapsed).split(".")[0] # Remove microseconds + logger.info(f"{message} ({elapsed_str})") + self._last_log_time = now def tick(self): """Update the spinner with current elapsed time without changing the message.""" diff --git a/packages/jumpstarter/jumpstarter/client/lease_test.py b/packages/jumpstarter/jumpstarter/client/lease_test.py index f00d81266..43bb084b9 100644 --- a/packages/jumpstarter/jumpstarter/client/lease_test.py +++ b/packages/jumpstarter/jumpstarter/client/lease_test.py @@ -228,3 +228,103 @@ def test_start_time_initialization_in_context(self): with spinner: assert spinner.start_time is not None assert isinstance(spinner.start_time, datetime) + + def test_throttling_first_update_logged(self, caplog): + """Test that the first update is always logged when console is not available.""" + with patch.object(LeaseAcquisitionSpinner, '_is_terminal_available', return_value=False): + spinner = LeaseAcquisitionSpinner("test-lease") + spinner.start_time = datetime.now() + + with caplog.at_level(logging.INFO): + spinner.update_status("First message") + + assert "First message" in caplog.text + assert spinner._last_log_time is not None + + def test_throttling_second_update_within_interval_not_logged(self, caplog): + """Test that updates within 5 minutes are not logged.""" + with patch.object(LeaseAcquisitionSpinner, '_is_terminal_available', return_value=False): + spinner = LeaseAcquisitionSpinner("test-lease") + spinner.start_time = datetime.now() + spinner._last_log_time = datetime.now() - timedelta(minutes=2) # 2 minutes ago + + with caplog.at_level(logging.INFO): + spinner.update_status("Second message") + + # Should not log because only 2 minutes have passed + assert "Second message" not in caplog.text + + def test_throttling_update_after_interval_logged(self, caplog): + """Test that updates after 5 minutes are logged.""" + with patch.object(LeaseAcquisitionSpinner, '_is_terminal_available', return_value=False): + spinner = LeaseAcquisitionSpinner("test-lease") + spinner.start_time = datetime.now() + spinner._last_log_time = datetime.now() - timedelta(minutes=6) # 6 minutes ago + + with caplog.at_level(logging.INFO): + spinner.update_status("After interval message") + + assert "After interval message" in caplog.text + assert spinner._last_log_time is not None + + def test_throttling_forced_update_always_logged(self, caplog): + """Test that forced updates are always logged regardless of throttle interval.""" + with patch.object(LeaseAcquisitionSpinner, '_is_terminal_available', return_value=False): + spinner = LeaseAcquisitionSpinner("test-lease") + spinner.start_time = datetime.now() + spinner._last_log_time = datetime.now() - timedelta(minutes=1) # 1 minute ago + + with caplog.at_level(logging.INFO): + spinner.update_status("Forced message", force=True) + + assert "Forced message" in caplog.text + assert spinner._last_log_time is not None + + def test_throttling_multiple_updates_only_logs_when_needed(self, caplog): + """Test that multiple rapid updates only log at appropriate intervals.""" + with patch.object(LeaseAcquisitionSpinner, '_is_terminal_available', return_value=False): + spinner = LeaseAcquisitionSpinner("test-lease") + spinner.start_time = datetime.now() + + with caplog.at_level(logging.INFO): + # First update should be logged + spinner.update_status("Message 1") + assert "Message 1" in caplog.text + + # Set last log time to recent + spinner._last_log_time = datetime.now() - timedelta(minutes=1) + + # Second update should not be logged (within interval) + spinner.update_status("Message 2") + assert "Message 2" not in caplog.text + + # Third update should not be logged (within interval) + spinner.update_status("Message 3") + assert "Message 3" not in caplog.text + + # Set last log time to past the interval + spinner._last_log_time = datetime.now() - timedelta(minutes=6) + + # Fourth update should be logged (past interval) + spinner.update_status("Message 4") + assert "Message 4" in caplog.text + + def test_throttling_not_applied_when_console_available(self): + """Test that throttling is not applied when console is available.""" + with patch.object(LeaseAcquisitionSpinner, '_is_terminal_available', return_value=True): + spinner = LeaseAcquisitionSpinner("test-lease") + spinner.start_time = datetime.now() + + mock_spinner = Mock() + spinner.spinner = mock_spinner + + # Multiple updates should all call update() regardless of throttle + spinner.update_status("Message 1") + spinner.update_status("Message 2") + spinner.update_status("Message 3") + + # All should be called even if we set a recent last_log_time + spinner._last_log_time = datetime.now() - timedelta(minutes=1) + spinner.update_status("Message 4") + + assert mock_spinner.update.call_count == 4