Adjust Pulumi message logging

data_safe_haven/infrastructure/project_manager.py

@@ -24,7 +24,7 @@
 )
 from data_safe_haven.external import AzureApi, PulumiAccount
 from data_safe_haven.functions import replace_separators
-from data_safe_haven.logging import get_logger
+from data_safe_haven.logging import from_ansi, get_console_handler, get_logger
 
 from .programs import DeclarativeSHM, DeclarativeSRE
 
@@ -72,10 +72,19 @@ def __init__(
     @property
     def pulumi_extra_args(self) -> dict[str, Any]:
         extra_args: dict[str, Any] = {}
-        if self.logger.isEnabledFor(logging.DEBUG):
+        # Produce verbose Pulumi output if running in verbose mode
+        if get_console_handler().level <= logging.DEBUG:
             extra_args["debug"] = True
             extra_args["log_to_std_err"] = True
             extra_args["log_verbosity"] = 9
+        else:
+            extra_args["debug"] = None
+            extra_args["log_to_std_err"] = None
+            extra_args["log_verbosity"] = None
+
+        extra_args["color"] = "always"
+        extra_args["log_flow"] = True
+        extra_args["on_output"] = self.log_message
         return extra_args
 
     @property
@@ -198,10 +207,6 @@ def destroy(self) -> None:
             while True:
                 try:
                     result = self.stack.destroy(
-                        color="always",
-                        debug=self.logger.isEnabledFor(logging.DEBUG),
-                        log_flow=True,
-                        on_output=self.logger.info,
                         **self.pulumi_extra_args,
                     )
                     self.evaluate(result.summary.result)
@@ -287,6 +292,9 @@ def install_plugins(self) -> None:
             msg = f"Installing Pulumi plugins failed.\n{exc}."
             raise DataSafeHavenPulumiError(msg) from exc
 
+    def log_message(self, message: str) -> None:
+        return from_ansi(self.logger, message)
+
     def output(self, name: str) -> Any:
         """Get a named output value from a stack"""
         if not self.stack_outputs_:
@@ -302,10 +310,7 @@ def preview(self) -> None:
             with suppress(automation.CommandError):
                 # Note that we disable parallelisation which can cause deadlock
                 self.stack.preview(
-                    color="always",
                     diff=True,
-                    log_flow=True,
-                    on_output=self.logger.info,
                     parallel=1,
                     **self.pulumi_extra_args,
                 )
@@ -318,7 +323,7 @@ def refresh(self) -> None:
         try:
             self.logger.info(f"Refreshing stack [green]{self.stack.name}[/].")
             # Note that we disable parallelisation which can cause deadlock
-            self.stack.refresh(color="always", parallel=1)
+            self.stack.refresh(parallel=1, **self.pulumi_extra_args)
         except automation.CommandError as exc:
             msg = f"Pulumi refresh failed.\n{exc}"
             raise DataSafeHavenPulumiError(msg) from exc
@@ -360,9 +365,6 @@ def update(self) -> None:
         try:
             self.logger.info(f"Applying changes to stack [green]{self.stack.name}[/].")
             result = self.stack.up(
-                color="always",
-                log_flow=True,
-                on_output=self.logger.info,
                 **self.pulumi_extra_args,
             )
             self.evaluate(result.summary.result)

data_safe_haven/logging/__init__.py

@@ -1,11 +1,15 @@
 from .logger import (
+    from_ansi,
+    get_console_handler,
     get_logger,
     init_logging,
     set_console_level,
     show_console_level,
 )
 
 __all__ = [
+    "from_ansi",
+    "get_console_handler",
     "get_logger",
     "init_logging",
     "set_console_level",

data_safe_haven/logging/logger.py

@@ -4,12 +4,21 @@
 from datetime import UTC, datetime
 
 from rich.logging import RichHandler
+from rich.text import Text
 
 from data_safe_haven.directories import log_dir
 
 from .plain_file_handler import PlainFileHandler
 
 
+def from_ansi(logger: logging.Logger, text: str) -> None:
+    logger.info(Text.from_ansi(text))
+
+
+def get_console_handler() -> RichHandler:
+    return next(h for h in get_logger().handlers if isinstance(h, RichHandler))
+
+
 def get_logger() -> logging.Logger:
     return logging.getLogger("data_safe_haven")
 
@@ -24,6 +33,10 @@ def init_logging() -> None:
     logger = get_logger()
     logger.setLevel(logging.NOTSET)
 
+    # Clear existing handlers
+    for handler in logger.handlers[:]:
+        logger.removeHandler(handler)
+
     console_handler = RichHandler(
         level=logging.INFO,
         markup=True,
@@ -47,9 +60,7 @@ def init_logging() -> None:
 
     # Add handlers
     logger.addHandler(console_handler)
-    logger.console_handler = console_handler  # type: ignore [attr-defined]
     logger.addHandler(file_handler)
-    logger.file_handler = file_handler  # type: ignore [attr-defined]
 
     # Disable unnecessarily verbose external logging
     logging.getLogger("azure.core.pipeline.policies").setLevel(logging.ERROR)
@@ -64,8 +75,8 @@ def logfile_name() -> str:
 
 
 def set_console_level(level: int | str) -> None:
-    get_logger().console_handler.setLevel(level)  # type: ignore [attr-defined]
+    get_console_handler().setLevel(level)
 
 
 def show_console_level() -> None:
-    get_logger().console_handler._log_render.show_level = True  # type: ignore [attr-defined]
+    get_console_handler()._log_render.show_level = True

data_safe_haven/logging/plain_file_handler.py

@@ -24,5 +24,8 @@ def strip_formatting(input_string: str) -> str:
 
     def emit(self, record: logging.LogRecord) -> None:
         """Emit a record without formatting"""
+        if isinstance(record.msg, Text):
+            # Convert rich.text.Text objects to strings
+            record.msg = str(record.msg)
         record.msg = self.strip_formatting(record.msg)
         super().emit(record)

tests/logging/test_logger.py

@@ -6,16 +6,22 @@
 
 from data_safe_haven.logging.logger import (
     PlainFileHandler,
+    from_ansi,
+    get_console_handler,
     get_logger,
     logfile_name,
     set_console_level,
     show_console_level,
 )
 
 
-class TestPlainFileHandler:
-    def test_strip_formatting(self):
-        assert PlainFileHandler.strip_formatting("[green]hello[/]") == "hello"
+class TestFromAnsi:
+    def test_from_ansi(self, capsys):
+        logger = get_logger()
+        from_ansi(logger, "\033[31;1;4mHello\033[0m")
+        out, _ = capsys.readouterr()
+        assert "Hello" in out
+        assert r"\033" not in out
 
 
 class TestLogFileName:
@@ -26,34 +32,51 @@ def test_logfile_name(self):
         assert datetime.strptime(date, "%Y-%m-%d")  # noqa: DTZ007
 
 
+class TestGetConsoleHandler:
+    def test_get_console_handler(self):
+        handler = get_console_handler()
+        assert isinstance(handler, RichHandler)
+        assert handler.level == logging.INFO
+
+
 class TestGetLogger:
     def test_get_logger(self):
         logger = get_logger()
         assert isinstance(logger, logging.Logger)
         assert logger.name == "data_safe_haven"
-        assert hasattr(logger, "console_handler")
-        assert hasattr(logger, "file_handler")
 
 
 class TestLogger:
     def test_constructor(self, log_directory):
         logger = get_logger()
+        file_handler = next(
+            h for h in logger.handlers if isinstance(h, PlainFileHandler)
+        )
+
+        assert file_handler
+        assert file_handler.level == logging.NOTSET
+        assert file_handler.baseFilename == f"{log_directory}/test.log"
 
-        assert isinstance(logger.file_handler, PlainFileHandler)
-        assert isinstance(logger.console_handler, RichHandler)
+    def test_info(self, capsys):
+        logger = get_logger()
+        file_handler = next(
+            h for h in logger.handlers if isinstance(h, PlainFileHandler)
+        )
+        log_file = Path(file_handler.baseFilename)
 
-        assert logger.file_handler.baseFilename == f"{log_directory}/test.log"
-        log_file = Path(logger.file_handler.baseFilename)
         logger.info("hello")
+        out, _ = capsys.readouterr()
+
+        assert "hello" in out
         assert log_file.is_file()
 
 
 class TestSetConsoleLevel:
     def test_set_console_level(self):
-        logger = get_logger()
-        assert logger.console_handler.level == logging.INFO
+        handler = get_console_handler()
+        assert handler.level == logging.INFO
         set_console_level(logging.DEBUG)
-        assert logger.console_handler.level == logging.DEBUG
+        assert handler.level == logging.DEBUG
 
     def test_set_console_level_stdout(self, capsys):
         logger = get_logger()
@@ -65,10 +88,10 @@ def test_set_console_level_stdout(self, capsys):
 
 class TestShowConsoleLevel:
     def test_show_console_level(self):
-        logger = get_logger()
-        assert not logger.console_handler._log_render.show_level
+        handler = get_console_handler()
+        assert not handler._log_render.show_level
         show_console_level()
-        assert logger.console_handler._log_render.show_level
+        assert handler._log_render.show_level
 
     def test_show_console_level_stdout(self, capsys):
         logger = get_logger()

tests/logging/test_plain_file_handler.py

@@ -0,0 +1,6 @@
+from data_safe_haven.logging.plain_file_handler import PlainFileHandler
+
+
+class TestPlainFileHandler:
+    def test_strip_formatting(self):
+        assert PlainFileHandler.strip_formatting("[green]hello[/]") == "hello"