diff --git a/src/constants.py b/src/constants.py index cbc3cdd74..140964051 100644 --- a/src/constants.py +++ b/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 diff --git a/src/lightspeed_stack.py b/src/lightspeed_stack.py index 858799c36..7de801080 100644 --- a/src/lightspeed_stack.py +++ b/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__) diff --git a/src/log.py b/src/log.py index 389b32fca..90c4462ba 100644 --- a/src/log.py +++ b/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 diff --git a/src/runners/uvicorn.py b/src/runners/uvicorn.py index 6e217095e..836a0e6c2 100644 --- a/src/runners/uvicorn.py +++ b/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, diff --git a/tests/unit/test_log.py b/tests/unit/test_log.py index 0e47caf9b..a3aa0f417 100644 --- a/tests/unit/test_log.py +++ b/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