[core] Ray Core / Ray Data logging configuration leads to unexpected behavior

[kevin85421]

Why are these changes needed?

Issue

In the Ray codebase, 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 (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 (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, 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

  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())

  

• Test 2

  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"))

  

• I've signed off every commit(by using the -s flag, i.e., git commit -s) in this PR.
• I've run scripts/format.sh to lint the changes in this PR.
• I've included any doc changes needed for https://docs.ray.io/en/master/.
  • I've added any new APIs to the API Reference. For example, if I added a
    method in Tune, I've added it in doc/source/tune/api/ under the
    corresponding .rst file.
• I've made sure the tests are passing. Note that there might be a few flaky tests, see the recent failures at https://flakey-tests.ray.io/
• Testing Strategy
  • Unit tests
  • Release tests
  • This PR is not tested :(

[kevin85421]

I don't know the expected behavior for the ray.data logger inside a Ray task. @omatthew98, would you mind sharing the expected behavior and confirming whether "Test 1" aligns with it?

[jjyao]

LG.

Need to change python/ray/_private/log.py as well since there is old dictConfig call there.

[kevin85421]

Need to change python/ray/_private/log.py as well since there is old dictConfig call there.

log.generate_logging_config() is called inside ray/__init__.py, which is executed before ray/data/__init__.py. I believe the order is guaranteed. If you prefer to minimize the use of dictConfig, it makes sense to rewrite it with explicit function calls.

[jjyao]

yea let's rewrite to avoid any surprises in the future.

[kevin85421]

The upper one is without import logging.config, and the lower one is with import logging.config.

[jjyao]

Let's spend some time figuring out why.

[kevin85421]

ray_logging/__init__.py contains a function setup_component_logger, which uses logging.handlers.RotatingFileHandler. However, the file doesn't import logging.handlers.

Instead, log.py imports logging.config, which implicitly imports logging.handlers.

When the runtime environment agent calls setup_component_logger, it fails, causing the Raylet to also terminate.

[kevin85421]

Solution: import logging.handlers in ray_logging/__init__.py directly.

[jjyao]

Let's spend some time figuring out why.

[jjyao]

so with dictConfig, log level will also be cleared not just handlers?

[kevin85421]

Yes, see https://github.com/python/cpython/blob/71ede1142ddad2d31cc966b8fe4a5aff664f4d53/Lib/logging/config.py#L193-L196 for more details.

Child logger's level will be set to NOTSET.