Ray Logging Configuration (#3691)

* fix logging for autoscaler

* module logging

* try this for logging

* yapf

* fix

* Initial logging setup

* momery

* ok

* remove basicconfig

* catch

* remove package logging

* print

* fix

* try_fix

* fix 1

* revert rllib

* logging level

* flake8

* fix

* fix

* Remove vestigal TODO

python/ray/log_monitor.py

@@ -14,8 +14,8 @@ from ray.services import get_port
 import ray.utils
 
 # Logger for this module. It should be configured at the entry point
-# into the program using Ray. Ray configures it by default automatically
-# using logging.basicConfig in its entry/init points.
+# into the program using Ray. Ray provides a default configuration at
+# entry/init points.
 logger = logging.getLogger(__name__)
 
 
@@ -154,9 +154,7 @@ if __name__ == "__main__":
         default=ray_constants.LOGGER_FORMAT,
         help=ray_constants.LOGGER_FORMAT_HELP)
     args = parser.parse_args()
-    logging.basicConfig(
-        level=logging.getLevelName(args.logging_level.upper()),
-        format=args.logging_format)
+    ray.utils.setup_logger(args.logging_level, args.logging_format)
 
     redis_ip_address = get_ip_address(args.redis_address)
     redis_port = get_port(args.redis_address)

python/ray/memory_monitor.py

@@ -55,11 +55,10 @@ class MemoryMonitor(object):
         self.last_checked = time.time()
         self.error_threshold = error_threshold
         if not psutil:
-            logger.warning(
-                "WARNING: Not monitoring node memory since `psutil` is not "
-                "installed. Install this with `pip install psutil` "
-                "(or ray[debug]) to enable debugging of memory-related "
-                "crashes.")
+            print("WARNING: Not monitoring node memory since `psutil` is not "
+                  "installed. Install this with `pip install psutil` "
+                  "(or ray[debug]) to enable debugging of memory-related "
+                  "crashes.")
 
     def raise_if_low_memory(self):
         if not psutil:

python/ray/monitor.py

@@ -17,7 +17,8 @@ import ray.gcs_utils
 import ray.utils
 import ray.ray_constants as ray_constants
 from ray.services import get_ip_address, get_port
-from ray.utils import binary_to_hex, binary_to_object_id, hex_to_binary
+from ray.utils import (binary_to_hex, binary_to_object_id, hex_to_binary,
+                       setup_logger)
 
 # Set up logging.
 logger = logging.getLogger(__name__)
@@ -358,8 +359,7 @@ if __name__ == "__main__":
         default=ray_constants.LOGGER_FORMAT,
         help=ray_constants.LOGGER_FORMAT_HELP)
     args = parser.parse_args()
-    level = logging.getLevelName(args.logging_level.upper())
-    logging.basicConfig(level=level, format=args.logging_format)
+    setup_logger(args.logging_level, args.logging_format)
 
     redis_ip_address = get_ip_address(args.redis_address)
     redis_port = get_port(args.redis_address)

python/ray/parameter.py

@@ -57,6 +57,9 @@ class RayParams(object):
             Store with hugetlbfs support. Requires plasma_directory.
         include_webui: Boolean flag indicating whether to start the web
             UI, which is a Jupyter notebook.
+        logging_level: Logging level, default will be logging.INFO.
+        logging_format: Logging format, default contains a timestamp,
+            filename, line number, and message. See ray_constants.py.
         plasma_store_socket_name (str): If provided, it will specify the socket
             name used by the plasma store.
         raylet_socket_name (str): If provided, it will specify the socket path

python/ray/ray_constants.py

@@ -78,9 +78,9 @@ AUTOSCALER_HEARTBEAT_TIMEOUT_S = env_integer("AUTOSCALER_HEARTBEAT_TIMEOUT_S",
 # Max number of retries to AWS (default is 5, time increases exponentially)
 BOTO_MAX_RETRIES = env_integer("BOTO_MAX_RETRIES", 12)
 
-# Default logger format: only contains the message.
-LOGGER_FORMAT = "%(message)s"
-LOGGER_FORMAT_HELP = "The logging format. default='%(message)s'"
+LOGGER_FORMAT = (
+    "%(asctime)s\t%(levelname)s %(filename)s:%(lineno)s -- %(message)s")
+LOGGER_FORMAT_HELP = "The logging format. default='{}'".format(LOGGER_FORMAT)
 LOGGER_LEVEL = "info"
 LOGGER_LEVEL_CHOICES = ['debug', 'info', 'warning', 'error', 'critical']
 LOGGER_LEVEL_HELP = ("The logging level threshold, choices=['debug', 'info',"

python/ray/scripts/scripts.py

@@ -57,8 +57,7 @@ def check_no_existing_redis_clients(node_ip_address, redis_client):
     help=ray_constants.LOGGER_FORMAT_HELP)
 def cli(logging_level, logging_format):
     level = logging.getLevelName(logging_level.upper())
-    logging.basicConfig(level=level, format=logging_format)
-    logger.setLevel(level)
+    ray.utils.setup_logger(level, logging_format)
 
 
 @cli.command()

python/ray/services.py

@@ -55,8 +55,8 @@ RAYLET_EXECUTABLE = os.path.join(
     os.path.abspath(os.path.dirname(__file__)), "core/src/ray/raylet/raylet")
 
 # Logger for this module. It should be configured at the entry point
-# into the program using Ray. Ray configures it by default automatically
-# using logging.basicConfig in its entry/init points.
+# into the program using Ray. Ray provides a default configuration at
+# entry/init points.
 logger = logging.getLogger(__name__)
 
 ProcessInfo = collections.namedtuple("ProcessInfo", [
@@ -849,9 +849,9 @@ def start_ui(redis_address, stdout_file=None, stderr_file=None):
         logger.warning("Failed to start the UI, you may need to run "
                        "'pip install jupyter'.")
     else:
-        logger.info("\n" + "=" * 70)
-        logger.info("View the web UI at {}".format(webui_url))
-        logger.info("=" * 70 + "\n")
+        print("\n" + "=" * 70)
+        print("View the web UI at {}".format(webui_url))
+        print("=" * 70 + "\n")
         return webui_url, process_info
     return None, None
 

python/ray/signature.py

@@ -10,8 +10,8 @@ import logging
 from ray.utils import is_cython
 
 # Logger for this module. It should be configured at the entry point
-# into the program using Ray. Ray configures it by default automatically
-# using logging.basicConfig in its entry/init points.
+# into the program using Ray. Ray provides a default configuration at
+# entry/init points.
 logger = logging.getLogger(__name__)
 
 FunctionSignature = namedtuple("FunctionSignature", [

python/ray/tune/__init__.py

@@ -2,8 +2,6 @@ from __future__ import absolute_import
 from __future__ import division
 from __future__ import print_function
 
-import logging
-
 from ray.tune.error import TuneError
 from ray.tune.tune import run_experiments
 from ray.tune.experiment import Experiment
@@ -11,20 +9,6 @@ from ray.tune.registry import register_env, register_trainable
 from ray.tune.trainable import Trainable
 from ray.tune.suggest import grid_search, function, sample_from
 
-
-def _setup_logger():
-    logger = logging.getLogger("ray.tune")
-    handler = logging.StreamHandler()
-    handler.setFormatter(
-        logging.Formatter(
-            "%(asctime)s\t%(levelname)s %(filename)s:%(lineno)s -- %(message)s"
-        ))
-    logger.addHandler(handler)
-    logger.propagate = False
-
-
-_setup_logger()
-
 __all__ = [
     "Trainable",
     "TuneError",

python/ray/utils.py

@@ -6,6 +6,7 @@ import binascii
 import functools
 import hashlib
 import inspect
+import logging
 import numpy as np
 import os
 import subprocess
@@ -276,6 +277,33 @@ def resources_from_resource_arguments(default_num_cpus, default_num_gpus,
     return resources
 
 
+_default_handler = None
+
+
+def setup_logger(logging_level, logging_format):
+    """Setup default logging for ray."""
+    logger = logging.getLogger("ray")
+    if type(logging_level) is str:
+        logging_level = logging.getLevelName(logging_level.upper())
+    logger.setLevel(logging_level)
+    global _default_handler
+    _default_handler = logging.StreamHandler()
+    _default_handler.setFormatter(logging.Formatter(logging_format))
+    logger.addHandler(_default_handler)
+    logger.propagate = False
+
+
+def try_update_handler(new_stream):
+    global _default_handler
+    logger = logging.getLogger("ray")
+    if _default_handler:
+        new_handler = logging.StreamHandler(stream=new_stream)
+        new_handler.setFormatter(_default_handler.formatter)
+        _default_handler.close()
+        _default_handler = new_handler
+        logger.addHandler(_default_handler)
+
+
 # This function is copied and modified from
 # https://github.com/giampaolo/psutil/blob/5bd44f8afcecbfb0db479ce230c790fc2c56569a/psutil/tests/test_linux.py#L132-L138  # noqa: E501
 def vmstat(stat):

python/ray/worker.py

@@ -38,12 +38,8 @@ from ray import ObjectID, DriverID, ActorID, ActorHandleID, ClientID, TaskID
 from ray import profiling
 from ray.function_manager import (FunctionActorManager, FunctionDescriptor)
 import ray.parameter
-from ray.utils import (
-    check_oversized_pickle,
-    is_cython,
-    random_string,
-    thread_safe_client,
-)
+from ray.utils import (check_oversized_pickle, is_cython, random_string,
+                       thread_safe_client, setup_logger, try_update_handler)
 
 SCRIPT_MODE = 0
 WORKER_MODE = 1
@@ -62,8 +58,8 @@ DEFAULT_ACTOR_METHOD_CPUS_SPECIFIED_CASE = 0
 DEFAULT_ACTOR_CREATION_CPUS_SPECIFIED_CASE = 1
 
 # Logger for this module. It should be configured at the entry point
-# into the program using Ray. Ray configures it by default automatically
-# using logging.basicConfig in its entry/init points.
+# into the program using Ray. Ray provides a default configuration at
+# entry/init points.
 logger = logging.getLogger(__name__)
 
 try:
@@ -1347,8 +1343,8 @@ def init(redis_address=None,
         configure_logging: True if allow the logging cofiguration here.
             Otherwise, the users may want to configure it by their own.
         logging_level: Logging level, default will be logging.INFO.
-        logging_format: Logging format, default will be "%(message)s"
-            which means only contains the message.
+        logging_format: Logging format, default contains a timestamp,
+            filename, line number, and message. See ray_constants.py.
         plasma_store_socket_name (str): If provided, it will specify the socket
             name used by the plasma store.
         raylet_socket_name (str): If provided, it will specify the socket path
@@ -1367,7 +1363,7 @@ def init(redis_address=None,
     """
 
     if configure_logging:
-        logging.basicConfig(level=logging_level, format=logging_format)
+        setup_logger(logging_level, logging_format)
 
     # Add the use_raylet option for backwards compatibility.
     if use_raylet is not None:
@@ -1837,6 +1833,7 @@ def connect(info,
                     worker.worker_id))
             sys.stdout = log_stdout_file
             sys.stderr = log_stderr_file
+            try_update_handler(sys.stderr)
             services.record_log_files_in_redis(
                 info["redis_address"],
                 info["node_ip_address"], [log_stdout_file, log_stderr_file],

python/ray/workers/default_worker.py

@@ -3,13 +3,13 @@ from __future__ import division
 from __future__ import print_function
 
 import argparse
-import logging
 import traceback
 
 import ray
 import ray.actor
 import ray.ray_constants as ray_constants
 import ray.tempfile_services as tempfile_services
+import ray.utils
 
 parser = argparse.ArgumentParser(
     description=("Parse addresses for the worker "
@@ -68,9 +68,7 @@ if __name__ == "__main__":
         "raylet_socket_name": args.raylet_name,
     }
 
-    logging.basicConfig(
-        level=logging.getLevelName(args.logging_level.upper()),
-        format=args.logging_format)
+    ray.utils.setup_logger(args.logging_level, args.logging_format)
 
     # Override the temporary directory.
     tempfile_services.set_temp_root(args.temp_dir)