From bf0dafede9e5a205ead812edac5f0b6f6e0c0718 Mon Sep 17 00:00:00 2001 From: Kai-Hsun Chen Date: Mon, 2 Dec 2024 11:36:14 -0800 Subject: [PATCH] [core] Ray Core / Ray Data logging configuration leads to unexpected behavior (#48958) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit ### Issue In the Ray codebase, [logging.config.dictConfig](https://docs.python.org/3/library/logging.config.html#logging.config.dictConfig) may be called multiple times. However, we found that if a logger’s child loggers are set before the logger is set via `dictConfig`, it may cause issues. * [Example1](https://gist.github.com/kevin85421/24849e06c61f221fd95063a4ce81ca8f) (incremental: False): The logger `Ray.data` loses its original handler and uses the `Ray` logger’s handler after the Ray logger is set via `dictConfig`. ``` 2024-11-27 04:32:06,213 - Ray.data - INFO - This is an INFO log from Ray.data. 2024-11-27 04:32:06,213 - Ray.data - WARNING - This is a WARNING log from Ray.data. 2024-11-27 04:32:06,213 - Ray.data - INFO - Ray data propagate False abc Ray - DEBUG - This is a DEBUG log from Ray. abc Ray - ERROR - This is an ERROR log from Ray. abc Ray.data - INFO - Another INFO log from Ray.data. abc Ray.data - INFO - Ray data propagate True ``` * [Example2](https://gist.github.com/kevin85421/9cf6ee70ceec42be3de888174d0c8e6a) (incremental: True): It looks like `Ray.data`’s handlers are removed after the `Ray` logger is set via `dictConfig`. ``` 2024-11-27 04:35:25,379 - Ray.data - INFO - This is an INFO log from Ray.data. 2024-11-27 04:35:25,379 - Ray.data - WARNING - This is a WARNING log from Ray.data. 2024-11-27 04:35:25,379 - Ray.data - INFO - Ray data propagate False This is an ERROR log from Ray. 2024-11-27 04:35:25,379 - Ray.data - INFO - Another INFO log from Ray.data. 2024-11-27 04:35:25,379 - Ray.data - INFO - Ray data propagate False ``` * CPython implementation * Case 1: `incremental` is `False` * If an existing logger is also a child logger of a new logger, the child logger’s handlers will be reset, and its `propagate` attribute will be set to true. * In [Example1](https://gist.github.com/kevin85421/24849e06c61f221fd95063a4ce81ca8f), `Ray.data` is not only an existing logger but also a child logger of Ray. Therefore, its handlers will be reset, and propagate will be set to true. * See the function for more details: https://github.com/python/cpython/blob/71ede1142ddad2d31cc966b8fe4a5aff664f4d53/Lib/logging/config.py#L193-L196 * Case 2: `incremental` is `True` * No handlers & filters will be added to the new logger. * See the function for more details: https://github.com/python/cpython/blob/71ede1142ddad2d31cc966b8fe4a5aff664f4d53/Lib/logging/config.py#L906-L915 ### Solution Instead of using `dictConfig` to set the root logger and the Ray logger, call other functions to set the loggers explicitly. ## Related issue number Closes #48732 ## Checks * Test 1 ```python import ray import logging import ray.data ray.init(logging_config=ray.LoggingConfig(encoding="TEXT", log_level="INFO")) root_logger = logging.getLogger() root_logger.info("root logger") ray_logger = logging.getLogger("ray") ray_logger.info("ray logger") ray_data_logger = logging.getLogger("ray.data") ray_data_logger.info("ray data logger") @ray.remote def f(): root_logger = logging.getLogger() root_logger.info("root logger") ray_data_logger = logging.getLogger("ray.data") ray_data_logger.info("ray data logger") ray.get(f.remote()) ``` image * Test 2 ```python import ray import logging def report_logger(logger): # Collect this logger and its parents loggers = [] current_logger = logger while current_logger: loggers.append(current_logger) if not current_logger.parent or current_logger.parent == current_logger: break current_logger = current_logger.parent # Report the configuration of each logger in the hierarchy print(f"Logging configuration for '{logger.name}' and its hierarchy:") for log in reversed(loggers): # Start from the root and go down to the given logger print(f"\nLogger: {log.name or 'root'} (Level: {logging.getLevelName(log.level)})") if log.handlers: print(" Handlers:") for handler in log.handlers: print(f" - {handler.__class__.__name__} (Level: {logging.getLevelName(handler.level)})") else: print(" No handlers configured") print("BEFORE") report_logger(logging.getLogger("ray.data")) print() import ray.data ray.init(logging_config=ray.LoggingConfig(encoding="TEXT", log_level="INFO")) print("AFTER:") report_logger(logging.getLogger("ray.data")) ``` image Signed-off-by: kaihsun Signed-off-by: Kai-Hsun Chen Co-authored-by: Jiajun Yao Signed-off-by: ujjawal-khare --- python/ray/_private/log.py | 56 ++++-------- python/ray/_private/ray_logging/__init__.py | 1 + .../ray/_private/ray_logging/default_impl.py | 6 +- .../_private/ray_logging/logging_config.py | 90 +++++++------------ python/ray/tests/test_logging_2.py | 35 +++++--- 5 files changed, 76 insertions(+), 112 deletions(-) diff --git a/python/ray/_private/log.py b/python/ray/_private/log.py index 73ce2d3ef3292..69242c7222334 100644 --- a/python/ray/_private/log.py +++ b/python/ray/_private/log.py @@ -1,5 +1,4 @@ import logging -from logging.config import dictConfig import threading from typing import Union @@ -74,44 +73,19 @@ def generate_logging_config(): return logger_initialized = True - formatters = { - "plain": { - "format": ( - "%(asctime)s\t%(levelname)s %(filename)s:%(lineno)s -- %(message)s" - ), - }, - } - - handlers = { - "default": { - "()": PlainRayHandler, - "formatter": "plain", - } - } - - loggers = { - # Default ray logger; any log message that gets propagated here will be - # logged to the console. Disable propagation, as many users will use - # basicConfig to set up a default handler. If so, logs will be - # printed twice unless we prevent propagation here. - "ray": { - "level": "INFO", - "handlers": ["default"], - "propagate": False, - }, - # Special handling for ray.rllib: only warning-level messages passed through - # See https://github.com/ray-project/ray/pull/31858 for related PR - "ray.rllib": { - "level": "WARN", - }, - } - - dictConfig( - { - "version": 1, - "formatters": formatters, - "handlers": handlers, - "loggers": loggers, - "disable_existing_loggers": False, - } + plain_formatter = logging.Formatter( + "%(asctime)s\t%(levelname)s %(filename)s:%(lineno)s -- %(message)s" ) + + default_handler = PlainRayHandler() + default_handler.setFormatter(plain_formatter) + + ray_logger = logging.getLogger("ray") + ray_logger.setLevel(logging.INFO) + ray_logger.addHandler(default_handler) + ray_logger.propagate = False + + # Special handling for ray.rllib: only warning-level messages passed through + # See https://github.com/ray-project/ray/pull/31858 for related PR + rllib_logger = logging.getLogger("ray.rllib") + rllib_logger.setLevel(logging.WARN) diff --git a/python/ray/_private/ray_logging/__init__.py b/python/ray/_private/ray_logging/__init__.py index 5699251e31ced..768bc716c7c30 100644 --- a/python/ray/_private/ray_logging/__init__.py +++ b/python/ray/_private/ray_logging/__init__.py @@ -1,6 +1,7 @@ import colorama from dataclasses import dataclass import logging +import logging.handlers import os import re import sys diff --git a/python/ray/_private/ray_logging/default_impl.py b/python/ray/_private/ray_logging/default_impl.py index 2d50673c28512..3901baaa956f3 100644 --- a/python/ray/_private/ray_logging/default_impl.py +++ b/python/ray/_private/ray_logging/default_impl.py @@ -1,4 +1,4 @@ -def get_dict_config_provider(): - from ray._private.ray_logging.logging_config import DefaultDictConfigProvider +def get_logging_configurator(): + from ray._private.ray_logging.logging_config import DefaultLoggingConfigurator - return DefaultDictConfigProvider() + return DefaultLoggingConfigurator() diff --git a/python/ray/_private/ray_logging/logging_config.py b/python/ray/_private/ray_logging/logging_config.py index 6788571f9e6aa..87cf819abbcf1 100644 --- a/python/ray/_private/ray_logging/logging_config.py +++ b/python/ray/_private/ray_logging/logging_config.py @@ -12,68 +12,47 @@ import time -class DictConfigProvider(ABC): +class LoggingConfigurator(ABC): @abstractmethod def get_supported_encodings(self) -> Set[str]: raise NotImplementedError @abstractmethod - def get_dict_config(self, encoding: str, log_level: str) -> dict: + def configure_logging(self, encoding: str, log_level: str): raise NotImplementedError -class DefaultDictConfigProvider(DictConfigProvider): +class DefaultLoggingConfigurator(LoggingConfigurator): def __init__(self): - self._dict_configs = { - "TEXT": lambda log_level: { - "version": 1, - "disable_existing_loggers": False, - "formatters": { - "text": { - "()": ( - f"{TextFormatter.__module__}." - f"{TextFormatter.__qualname__}" - ), - }, - }, - "filters": { - "core_context": { - "()": ( - f"{CoreContextFilter.__module__}." - f"{CoreContextFilter.__qualname__}" - ), - }, - }, - "handlers": { - "console": { - "level": log_level, - "class": "logging.StreamHandler", - "formatter": "text", - "filters": ["core_context"], - }, - }, - "root": { - "level": log_level, - "handlers": ["console"], - }, - "loggers": { - "ray": { - "level": log_level, - "handlers": ["console"], - "propagate": False, - } - }, - } + self._encoding_to_formatter = { + "TEXT": TextFormatter(), } def get_supported_encodings(self) -> Set[str]: - return self._dict_configs.keys() + return self._encoding_to_formatter.keys() - def get_dict_config(self, encoding: str, log_level: str) -> dict: - return self._dict_configs[encoding](log_level) + def configure_logging(self, encoding: str, log_level: str): + formatter = self._encoding_to_formatter[encoding] + core_context_filter = CoreContextFilter() + handler = logging.StreamHandler() + handler.setLevel(log_level) + handler.setFormatter(formatter) + handler.addFilter(core_context_filter) + root_logger = logging.getLogger() + root_logger.setLevel(log_level) + root_logger.addHandler(handler) -_dict_config_provider: DictConfigProvider = default_impl.get_dict_config_provider() + ray_logger = logging.getLogger("ray") + ray_logger.setLevel(log_level) + # Remove all existing handlers added by `ray/__init__.py`. + for h in ray_logger.handlers[:]: + ray_logger.removeHandler(h) + ray_logger.addHandler(handler) + ray_logger.propagate = False + + +_logging_configurator: LoggingConfigurator = default_impl.get_logging_configurator() @PublicAPI(stability="alpha") @@ -84,19 +63,16 @@ class LoggingConfig: log_level: str = "INFO" def __post_init__(self): - if self.encoding not in _dict_config_provider.get_supported_encodings(): + if self.encoding not in _logging_configurator.get_supported_encodings(): raise ValueError( f"Invalid encoding type: {self.encoding}. " "Valid encoding types are: " - f"{list(_dict_config_provider.get_supported_encodings())}" + f"{list(_logging_configurator.get_supported_encodings())}" ) - def _get_dict_config(self) -> dict: - """Get the logging configuration based on the encoding type. - Returns: - dict: The logging configuration. - """ - return _dict_config_provider.get_dict_config(self.encoding, self.log_level) + def _configure_logging(self): + """Set up the logging configuration for the current process.""" + _logging_configurator.configure_logging(self.encoding, self.log_level) def _setup_log_record_factory(self): old_factory = logging.getLogRecordFactory() @@ -121,7 +97,7 @@ def record_factory(*args, **kwargs): def _apply(self): """Set up both the LogRecord factory and the logging configuration.""" self._setup_log_record_factory() - logging.config.dictConfig(self._get_dict_config()) + self._configure_logging() LoggingConfig.__doc__ = f""" @@ -153,7 +129,7 @@ def f(): Args: encoding: Encoding type for the logs. The valid values are - {list(_dict_config_provider.get_supported_encodings())} + {list(_logging_configurator.get_supported_encodings())} log_level: Log level for the logs. Defaults to 'INFO'. You can set it to 'DEBUG' to receive more detailed debug logs. """ # noqa: E501 diff --git a/python/ray/tests/test_logging_2.py b/python/ray/tests/test_logging_2.py index 9d5be165f9ac5..988ed482e2bcc 100644 --- a/python/ray/tests/test_logging_2.py +++ b/python/ray/tests/test_logging_2.py @@ -207,17 +207,9 @@ def test_record_with_exception(self): assert s in formatted -class TestLoggingConfig: - def test_log_level(self): - log_level = "DEBUG" - logging_config = LoggingConfig(log_level=log_level) - dict_config = logging_config._get_dict_config() - assert dict_config["handlers"]["console"]["level"] == log_level - assert dict_config["root"]["level"] == log_level - - def test_invalid_dict_config(self): - with pytest.raises(ValueError): - LoggingConfig(encoding="INVALID")._get_dict_config() +def test_invalid_encoding(): + with pytest.raises(ValueError): + LoggingConfig(encoding="INVALID") class TestTextModeE2E: @@ -477,6 +469,27 @@ def print_message(self): assert "(MyActor pid=" not in stderr +def test_configure_both_structured_logging_and_lib_logging(shutdown_only): + """ + Configure the `ray.test` logger. Then, configure the `root` and `ray` + loggers in `ray.init()`. Ensure that the `ray.test` logger is not affected. + """ + script = """ +import ray +import logging + +old_test_logger = logging.getLogger("ray.test") +assert old_test_logger.getEffectiveLevel() != logging.DEBUG +old_test_logger.setLevel(logging.DEBUG) + +ray.init(logging_config=ray.LoggingConfig(encoding="TEXT", log_level="INFO")) + +new_test_logger = logging.getLogger("ray.test") +assert old_test_logger.getEffectiveLevel() == logging.DEBUG +""" + run_string_as_driver(script) + + if __name__ == "__main__": if os.environ.get("PARALLEL_CI"): sys.exit(pytest.main(["-n", "auto", "--boxed", "-vs", __file__]))