Unify logging configuration and setup

src/constants.py

@@ -225,10 +225,11 @@
 # Environment variable name for configurable log level
 LIGHTSPEED_STACK_LOG_LEVEL_ENV_VAR: Final[str] = "LIGHTSPEED_STACK_LOG_LEVEL"
 # Default log level when environment variable is not set
+DEFAULT_LOGGER_NAME = "lightspeed_stack"
 DEFAULT_LOG_LEVEL: Final[str] = "INFO"
 # Default log format for plain-text logging in non-TTY environments
 DEFAULT_LOG_FORMAT: Final[str] = (
-    "%(asctime)s %(levelname)-8s %(name)s:%(lineno)d %(message)s"
+    "%(asctime)s.%(msecs)03d %(levelprefix)s %(message)s  [%(name)s:%(lineno)d]"
 )
 # Environment variable to force StreamHandler instead of RichHandler
 # Set to any non-empty value to disable RichHandler

src/lightspeed_stack.py

@@ -6,37 +6,16 @@
 
 import logging
 import os
-import sys
 from argparse import ArgumentParser
 
 from configuration import configuration
 from constants import LIGHTSPEED_STACK_LOG_LEVEL_ENV_VAR
-from log import create_log_handler, get_logger, resolve_log_level
+from log import get_logger, setup_logging
 from runners.quota_scheduler import start_quota_scheduler
 from runners.uvicorn import start_uvicorn
 from utils import schema_dumper
 
-# Resolve log level and handler from centralized logging utilities
-log_level = resolve_log_level()
-
-# Configure root logger. basicConfig(force=True) is intentionally root-logger-specific.
-# RichHandler needs format="%(message)s" to prevent double-formatting by the root Formatter.
-handler = create_log_handler()
-if sys.stderr.isatty():
-    logging.basicConfig(
-        level=log_level,
-        format="%(message)s",
-        datefmt="[%X]",
-        handlers=[handler],
-        force=True,
-    )
-else:
-    logging.basicConfig(
-        level=log_level,
-        handlers=[handler],
-        force=True,
-    )
-
+setup_logging()
 logger = get_logger(__name__)
 
 

src/log.py

@@ -1,14 +1,19 @@
 """Log utilities."""
 
 import logging
+import logging.config
 import os
 import sys
+import typing as t
+from functools import lru_cache
 
-from rich.logging import RichHandler
+import uvicorn.config
+from pydantic.v1.utils import deep_update
 
 from constants import (
     DEFAULT_LOG_FORMAT,
     DEFAULT_LOG_LEVEL,
+    DEFAULT_LOGGER_NAME,
     LIGHTSPEED_STACK_DISABLE_RICH_HANDLER_ENV_VAR,
     LIGHTSPEED_STACK_LOG_LEVEL_ENV_VAR,
 )
@@ -50,62 +55,67 @@ def resolve_log_level() -> int:
     return validated_level
 
 
-def create_log_handler() -> logging.Handler:
-    """
-    Create and return a configured log handler based on TTY availability and environment settings.
-
-    If LIGHTSPEED_STACK_DISABLE_RICH_HANDLER is set to any non-empty value,
-    returns a StreamHandler with plain-text formatting. Otherwise, if stderr
-    is connected to a terminal (TTY), returns a RichHandler for rich-formatted
-    console output. If neither condition is met, returns a StreamHandler with
-    plain-text formatting suitable for non-TTY environments (e.g., containers).
-
-    Returns:
-        logging.Handler: A configured handler instance (RichHandler or StreamHandler).
-    """
-    # Check if RichHandler is explicitly disabled via environment variable
-    if os.environ.get(LIGHTSPEED_STACK_DISABLE_RICH_HANDLER_ENV_VAR):
-        handler = logging.StreamHandler()
-        handler.setFormatter(logging.Formatter(DEFAULT_LOG_FORMAT))
-        return handler
-
-    if sys.stderr.isatty():
-        # RichHandler's columnar layout assumes a real terminal.
-        # RichHandler handles its own formatting, so no formatter is set.
-        return RichHandler()
-
-    # In containers without a TTY, Rich falls back to 80 columns and
-    # the columns consume most of that width, leaving ~40 chars for the actual message.
-    # Tracebacks become nearly unreadable. Use a plain StreamHandler instead.
-    handler = logging.StreamHandler()
-    handler.setFormatter(logging.Formatter(DEFAULT_LOG_FORMAT))
-    return handler
-
-
 def get_logger(name: str) -> logging.Logger:
-    """
-    Get a logger configured for Rich console output.
-
-    The returned logger has its level set based on the LIGHTSPEED_STACK_LOG_LEVEL
-    environment variable (defaults to INFO), its handlers replaced with a single
-    handler (RichHandler for TTY or StreamHandler for non-TTY), and propagation
-    to ancestor loggers disabled.
-
-    Parameters:
-    ----------
-        name (str): Name of the logger to retrieve or create.
-
-    Returns:
-    -------
-        logging.Logger: The configured logger instance.
-    """
-    logger = logging.getLogger(name)
+    """Create a common logger for all modules in this package."""
+    # FIXME: Remove the need for this function.
+    #
+    # Normally this is derived from the package name (__name__).
+    #
+    # Since this program is sometimes called from from the entrypoint and
+    # sometimes called from src/lightspeed_stack.py, the value for __name__
+    # does not contain a consistent root value.
+    #
+    # How the application is installed and run needs to be streamlined so that
+    # __name__ provides the expected value in all cases.
+    return logging.getLogger(f"{DEFAULT_LOGGER_NAME}.{name}")
+
+
+@lru_cache
+def setup_logging() -> dict[t.Any, t.Any]:
+    handler = "default"
+    log_level = resolve_log_level()
+    if sys.stderr.isatty() and not os.environ.get(
+        LIGHTSPEED_STACK_DISABLE_RICH_HANDLER_ENV_VAR
+    ):
+        handler = "rich"
+
+    logging_conf = {
+        "version": 1,
+        "disable_existing_loggers": False,
+        "handlers": {
+            "rich": {
+                "()": "rich.logging.RichHandler",
+                "show_time": True,
+                "log_time_format": "%Y-%m-%d %H:%M:%S.%f",
+                "level": log_level,
+            },
+        },
+        "loggers": {
+            DEFAULT_LOGGER_NAME: {
+                "handlers": [handler],
+                "level": log_level,
+                "propagate": False,
+            },
+            "llama_stack_client": {
+                "handlers": [handler],
+                "level": log_level,
+                "propagate": False,
+            },
+        },
+    }
+
+    merged_config = deep_update(uvicorn.config.LOGGING_CONFIG, logging_conf)
+
+    if handler == "rich":
+        merged_config["loggers"]["uvicorn"]["handlers"] = [handler]
+        merged_config["loggers"]["uvicorn.access"]["handlers"] = [handler]
+    else:
+        merged_config["formatters"]["access"]["fmt"] = (
+            'ACCESS %(asctime)s.%(msecs)03d %(levelprefix)s %(client_addr)s - "%(request_line)s" %(status_code)s'
+        )
+        merged_config["formatters"]["default"]["fmt"] = DEFAULT_LOG_FORMAT
+        merged_config["formatters"]["default"]["datefmt"] = "%Y-%m-%d %H:%M"
 
-    # Skip reconfiguration if logger already has handlers from a prior call
-    if logger.handlers:
-        return logger
+    logging.config.dictConfig(merged_config)
 
-    logger.handlers = [create_log_handler()]
-    logger.propagate = False
-    logger.setLevel(resolve_log_level())
-    return logger
+    return merged_config

src/runners/uvicorn.py

@@ -4,13 +4,16 @@
 
 import uvicorn
 
-from log import get_logger, resolve_log_level
+from log import get_logger, resolve_log_level, setup_logging
 from models.config import ServiceConfiguration
 
 logger = get_logger(__name__)
 
 
-def start_uvicorn(configuration: ServiceConfiguration) -> None:
+def start_uvicorn(
+    configuration: ServiceConfiguration,
+    log_config: dict | None = None,
+) -> None:
     """Start the Uvicorn server using the provided service configuration.
 
     Parameters:
@@ -22,6 +25,8 @@ def start_uvicorn(configuration: ServiceConfiguration) -> None:
     """
     log_level = resolve_log_level()
     logger.info("Starting Uvicorn with log level %s", logging.getLevelName(log_level))
+    if log_config is None:
+        log_config = setup_logging()
 
     # please note:
     # TLS fields can be None, which means we will pass those values as None to uvicorn.run
@@ -30,6 +35,7 @@ def start_uvicorn(configuration: ServiceConfiguration) -> None:
         host=configuration.host,
         port=configuration.port,
         workers=configuration.workers,
+        log_config=log_config,
         log_level=log_level,
         ssl_keyfile=configuration.tls_config.tls_key_path,
         ssl_certfile=configuration.tls_config.tls_certificate_path,

tests/unit/test_log.py

@@ -3,34 +3,38 @@
 import logging
 
 import pytest
-from pytest_mock import MockerFixture
-from rich.logging import RichHandler
 
 from constants import (
-    DEFAULT_LOG_FORMAT,
-    LIGHTSPEED_STACK_DISABLE_RICH_HANDLER_ENV_VAR,
+    DEFAULT_LOGGER_NAME,
     LIGHTSPEED_STACK_LOG_LEVEL_ENV_VAR,
 )
-from log import create_log_handler, get_logger, resolve_log_level
+from log import get_logger, resolve_log_level, setup_logging
+
+
+@pytest.fixture(autouse=True)
+def clear_logging_cache():
+    setup_logging.cache_clear()
 
 
 def test_get_logger() -> None:
     """Check the function to retrieve logger."""
-    logger_name = "foo"
-    logger = get_logger(logger_name)
-    assert logger is not None
-    assert logger.name == logger_name
+    setup_logging()
 
-    # at least one handler need to be set
-    assert len(logger.handlers) >= 1
+    logger = get_logger(__name__)
+
+    assert logger is not None
+    assert logger.name == f"{DEFAULT_LOGGER_NAME}.tests.unit.test_log"
+    assert logger.hasHandlers()
 
 
 def test_get_logger_invalid_env_var_fallback(monkeypatch: pytest.MonkeyPatch) -> None:
     """Test that invalid env var value falls back to INFO level."""
     monkeypatch.setenv(LIGHTSPEED_STACK_LOG_LEVEL_ENV_VAR, "FOOBAR")
 
-    logger = get_logger("test_invalid")
-    assert logger.level == logging.INFO
+    setup_logging()
+
+    logger = get_logger(__name__)
+    assert logger.getEffectiveLevel() == logging.INFO
 
 
 @pytest.mark.parametrize(
@@ -59,16 +63,20 @@ def test_get_logger_log_level(
     """
     monkeypatch.setenv(LIGHTSPEED_STACK_LOG_LEVEL_ENV_VAR, level_name)
 
-    logger = get_logger(f"test_{level_name}")
-    assert logger.level == expected_level
+    setup_logging()
+
+    logger = get_logger(__name__)
+    assert logger.getEffectiveLevel() == expected_level
 
 
 def test_get_logger_default_log_level(monkeypatch: pytest.MonkeyPatch) -> None:
     """Test that get_logger() uses INFO level by default when env var is not set."""
     monkeypatch.delenv(LIGHTSPEED_STACK_LOG_LEVEL_ENV_VAR, raising=False)
 
-    logger = get_logger("test_default")
-    assert logger.level == logging.INFO
+    setup_logging()
+
+    logger = get_logger(__name__)
+    assert logger.getEffectiveLevel() == logging.INFO
 
 
 @pytest.mark.parametrize(
@@ -88,73 +96,25 @@ def test_resolve_log_level(
 ) -> None:
     """Test that resolve_log_level correctly resolves valid level names."""
     monkeypatch.setenv(LIGHTSPEED_STACK_LOG_LEVEL_ENV_VAR, level_name)
+
+    setup_logging()
+
     assert resolve_log_level() == expected_level
 
 
 def test_resolve_log_level_invalid_fallback(monkeypatch: pytest.MonkeyPatch) -> None:
     """Test that resolve_log_level falls back to INFO for invalid values."""
     monkeypatch.setenv(LIGHTSPEED_STACK_LOG_LEVEL_ENV_VAR, "BOGUS")
+
+    setup_logging()
+
     assert resolve_log_level() == logging.INFO
 
 
 def test_resolve_log_level_default(monkeypatch: pytest.MonkeyPatch) -> None:
     """Test that resolve_log_level defaults to INFO when env var is unset."""
     monkeypatch.delenv(LIGHTSPEED_STACK_LOG_LEVEL_ENV_VAR, raising=False)
-    assert resolve_log_level() == logging.INFO
-
 
-def test_create_log_handler_tty(mocker: MockerFixture) -> None:
-    """Test that create_log_handler returns RichHandler when TTY is available."""
-    mocker.patch("sys.stderr.isatty", return_value=True)
-    handler = create_log_handler()
-    assert isinstance(handler, RichHandler)
+    setup_logging()
 
-
-def test_create_log_handler_non_tty(mocker: MockerFixture) -> None:
-    """Test that create_log_handler returns StreamHandler when no TTY."""
-    mocker.patch("sys.stderr.isatty", return_value=False)
-    handler = create_log_handler()
-    assert isinstance(handler, logging.StreamHandler)
-    assert not isinstance(handler, RichHandler)
-
-
-def test_create_log_handler_non_tty_format(mocker: MockerFixture) -> None:
-    """Test that non-TTY handler uses DEFAULT_LOG_FORMAT."""
-    mocker.patch("sys.stderr.isatty", return_value=False)
-    handler = create_log_handler()
-    assert handler.formatter is not None
-    # pylint: disable=protected-access
-    assert handler.formatter._fmt == DEFAULT_LOG_FORMAT
-
-
-def test_create_log_handler_disable_rich_with_tty(
-    mocker: MockerFixture, monkeypatch: pytest.MonkeyPatch
-) -> None:
-    """Test that RichHandler is disabled when env var is set, even with TTY."""
-    mocker.patch("sys.stderr.isatty", return_value=True)
-    monkeypatch.setenv(LIGHTSPEED_STACK_DISABLE_RICH_HANDLER_ENV_VAR, "1")
-    handler = create_log_handler()
-    assert isinstance(handler, logging.StreamHandler)
-    assert not isinstance(handler, RichHandler)
-
-
-def test_create_log_handler_disable_rich_format(
-    mocker: MockerFixture, monkeypatch: pytest.MonkeyPatch
-) -> None:
-    """Test that disabled RichHandler uses DEFAULT_LOG_FORMAT."""
-    mocker.patch("sys.stderr.isatty", return_value=True)
-    monkeypatch.setenv(LIGHTSPEED_STACK_DISABLE_RICH_HANDLER_ENV_VAR, "true")
-    handler = create_log_handler()
-    assert handler.formatter is not None
-    # pylint: disable=protected-access
-    assert handler.formatter._fmt == DEFAULT_LOG_FORMAT
-
-
-def test_create_log_handler_enable_rich_when_env_var_empty(
-    mocker: MockerFixture, monkeypatch: pytest.MonkeyPatch
-) -> None:
-    """Test that RichHandler is used when env var is empty string."""
-    mocker.patch("sys.stderr.isatty", return_value=True)
-    monkeypatch.setenv(LIGHTSPEED_STACK_DISABLE_RICH_HANDLER_ENV_VAR, "")
-    handler = create_log_handler()
-    assert isinstance(handler, RichHandler)
+    assert resolve_log_level() == logging.INFO