[Core][2/n] Core structured logging: add Text formatter and pass log config to worker process #45344

kevin85421 · 2024-05-15T01:49:58Z

Why are these changes needed?

Add a TextFormatter. It is a formatter that converts LogRecord into a human-readable message string.
Add a predefined logging configuration. This allows users to easily configure Ray task and actor loggers to use TextFormatter, and to add arbitrary attributes to log messages.

Example

import ray
import sys
import logging
from ray._private.structured_logging.utils import LoggingConfig

ray.init(
    job_config=ray.job_config.JobConfig(py_log_config=LoggingConfig("TEXT"))
)

def init_logger():
    return logging.getLogger()

logger = logging.getLogger("ray")
logger.info("Driver process", extra={"username": "johndoe"})

@ray.remote
def f():
    logger = init_logger()
    logger.info("A Ray task")

@ray.remote
class actor:
    def __init__(self):
        pass
    def print_message(self):
        logger = init_logger()
        logger.info("A Ray actor")

task_obj_ref = f.remote()
ray.get(task_obj_ref)

actor_instance = actor.remote()
ray.get(actor_instance.print_message.remote())

Output

2024-05-21 06:48:06,699 INFO worker.py:1740 -- Started a local Ray instance. View the dashboard at 127.0.0.1:8266
2024-05-21 06:48:07,333 INFO test_logging.py:14 -- Driver process
(f pid=3772046) 2024-05-21 06:48:07,349 INFO test_logging.py:19 -- A Ray task job_id=01000000 worker_id=87cac8ad9f50f185f97d0fc36e05616669c3e00a135bc0f443a709ac node_id=683c682fee5d431f3f4cf25fa992df9a7918b1c32e88943e853ad06b task_id=c8ef45ccd0112571ffffffffffffffffffffffff01000000
(actor pid=3773875) 2024-05-21 06:48:07,870     INFO test_logging.py:27 -- A Ray actor job_id=01000000 worker_id=b362329f5dab902df9e3fc0fe73df6279c661baaa709854e135378aa node_id=683c682fee5d431f3f4cf25fa992df9a7918b1c32e88943e853ad06b actor_id=c4fc669d536be18637fa490201000000 task_id=c2668a65bda616c1c4fc669d536be18637fa490201000000

Related issue number

Checks

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

python/ray/tests/test_structured_logging.py

kevin85421 · 2024-05-15T07:20:19Z

python/ray/_private/structured_logging/utils.py

+        },
+        "handlers": {
+            "console": {
+                "level": "INFO",


The default log level is Ray Serve is INFO.

https://sourcegraph.com/github.com/ray-project/ray@a1590725a8cc8a47734ee8676da4e6a8fbb5548a/-/blob/python/ray/serve/schema.py?L125

kevin85421 · 2024-05-15T07:21:55Z

python/ray/_private/structured_logging/utils.py

+        },
+        "filters": {
+            "core_context": {
+                "()": CoreContextFilter,


"The key '()' has been used as the special key because it is not a valid keyword parameter name, and so will not clash with the names of the keyword arguments used in the call. The '()' also serves as a mnemonic that the corresponding value is a callable."

Ref: https://docs.python.org/3/library/logging.config.html#logging-config-dictschema

python/ray/_private/structured_logging/utils.py

python/ray/tests/test_structured_logging.py

python/ray/_private/structured_logging/formatters.py

jjyao · 2024-05-20T04:06:01Z

python/ray/job_config.py

@@ -50,6 +51,7 @@ def __init__(
        ray_namespace: Optional[str] = None,
        default_actor_lifetime: str = "non_detached",
        _py_driver_sys_path: Optional[List[str]] = None,
+        py_log_config: Optional[Union[dict, str]] = None,


Let's create a LoggingConfig class

class LoggingConfig: dict_config: Union[dict, str] = "TEXT" log_level: int = INFO

Is there any reason to create a LoggingConfig class? With LoggingConfig, user's code will look like:

ray.init(job_config=ray.job_config.JobConfig(py_log_config=ray.xxx.yyy.zzz.LoggingConfig("TEXT")))

Is there any reason to create a LoggingConfig class?

Maybe this is because we might add new fields to the LoggingConfig in the future?

Updated bba3b09

kevin85421 · 2024-05-21T00:06:12Z

python/ray/_private/structured_logging/utils.py

+# A dictionary to map encoding types to their corresponding logging configurations.
+LOG_MODE_DICT = {
+    "TEXT": {
+        "version": 1,


"version - to be set to an integer value representing the schema version. The only valid value at present is 1, but having this key allows the schema to evolve while still preserving backwards compatibility."

https://docs.python.org/3/library/logging.config.html

kevin85421 · 2024-05-21T00:10:50Z

python/ray/_private/structured_logging/formatters.py

+def generate_record_format_attrs(
+    formatter: logging.Formatter,
+    record: logging.LogRecord,
+    exclude_standard_attrs=False,


I have decided to use exclude_standard_attrs instead of include_standard_attrs or include_extra_attrs because I think exclude_standard_attrs is more accurate.

include_standard_attrs: This function doesn't include all standard LogRecrod attributes.

include_extra_attrs: This function not only include attributes specified by logger.info(..., extra={...}) but also Ray context.

kevin85421 · 2024-05-21T06:35:46Z

python/ray/_private/structured_logging/utils.py

+LOG_MODE_DICT = {
+    "TEXT": {
+        "version": 1,
+        "disable_existing_loggers": False,


disable_existing_loggers – If specified as False, loggers which exist when this call is made are left enabled. The default is True because this enables old behaviour in a backward-compatible way. This behaviour is to disable any existing non-root loggers unless they or their ancestors are explicitly named in the logging configuration.

https://docs.python.org/3/library/logging.config.html

python/ray/_private/structured_logging/formatters.py

python/ray/job_config.py

jjyao · 2024-05-22T04:53:37Z

python/ray/job_config.py

@@ -226,4 +233,5 @@ def from_json(cls, job_config_json):
            ray_namespace=job_config_json.get("ray_namespace", None),
            _client_job=job_config_json.get("client_job", False),
            _py_driver_sys_path=job_config_json.get("py_driver_sys_path", None),
+            py_log_config=job_config_json.get("py_log_config", None),


what we get from job_config_json won't have type LoggingConfig. I think we don't need to support json for now.

jjyao · 2024-05-22T05:38:42Z

python/ray/_private/structured_logging/utils.py

+class LoggingConfig:
+    def __init__(self, log_config: Union[dict, str]):
+        if isinstance(log_config, str):
+            assert log_config in LOG_MODE_DICT, (


should raise ValueError to the user instead of check fail

Updated a38ec10

jjyao · 2024-05-22T05:53:01Z

python/ray/_private/structured_logging/utils.py

+
+
+class LoggingConfig:
+    def __init__(self, log_config: Union[dict, str]):


As we discussed, let's do

class LoggingConfig: dict_config: Union[dict, str] = "TEXT" # Only effective if dict_config is not a dict log_level: int = INFO

Updated a38ec10

python/ray/_private/structured_logging/utils.py

Signed-off-by: kaihsun <kaihsun@anyscale.com>

jjyao

lg

python/ray/_private/structured_logging/utils.py

jjyao · 2024-05-24T21:39:12Z

@rkooo567 can you also check the API to see if it makes sense?

Signed-off-by: kaihsun <kaihsun@anyscale.com>

jjyao · 2024-05-28T04:22:16Z

python/ray/_private/structured_logging/utils.py

+from ray._private.structured_logging.formatters import TextFormatter
+from ray._private.structured_logging.filters import CoreContextFilter
+
+LOG_MODE_DICT = {


nit: I think we can just define this in the constants.py?

Moving to constants.py will cause a circular import.

LOG_MODE_DICT requires TextFormatter and CoreContextFilter from formatters.py and filters.py.

Both filters.py and formatters.py also import constants.py.

Updated 2ec1b4f

jjyao · 2024-05-28T04:29:14Z

python/ray/job_config.py

 from ray.util.annotations import PublicAPI

 if TYPE_CHECKING:
    from ray.runtime_env import RuntimeEnv


+@PublicAPI(stability="alpha")
+class LoggingConfig:
+    def __init__(self, log_config: Union[dict, str] = "TEXT", log_level: str = "INFO"):


log_config -> dict_config? to make it clear that we use python dictConfig to configure the logging.

Updated d9e63aa

jjyao · 2024-05-28T04:32:31Z

python/ray/_raylet.pyx

+            py_logging_config = pickle.loads(serialized_py_logging_config)
+            log_config_dict = py_logging_config.get_dict_config()
+        if log_config_dict:
+            logging.config.dictConfig(log_config_dict)


I think we need to try catch. See

if worker_process_setup_hook_key: error = load_and_execute_setup_hook(worker_process_setup_hook_key) if error is not None: worker.core_worker.drain_and_exit_worker("system", error)

Updated d9e63aa

Signed-off-by: kaihsun <kaihsun@anyscale.com>

kevin85421 · 2024-05-28T06:58:59Z

python/ray/_raylet.pyx

+            except Exception as e:
+                backtrace = \
+                    "".join(traceback.format_exception(type(e), e, e.__traceback__))
+                print(backtrace)


If we don't add print here, users can't see any error message from the driver process. The following screenshot is an example of backtrace.

import ray import logging from ray.job_config import LoggingConfig ray.init( job_config=ray.job_config.JobConfig(py_logging_config=LoggingConfig({"abc": "123"})) ) def init_logger(): return logging.getLogger() logger = logging.getLogger("ray") logger.info("Driver process", extra={"username": "johndoe"}) @ray.remote def f(): logger = init_logger() logger.info("A Ray task") task_obj_ref = f.remote() ray.get(task_obj_ref)

kevin85421 · 2024-05-28T17:50:20Z

Case 1: pb.serialized_py_logging_config is 428 bytes.

log_dict_config = {
    "version": 1,
    "disable_existing_loggers": False,
    "formatters": {
        "text": {
            "()": "ray._private.structured_logging.formatters.TextFormatter",
        },
    },
    "filters": {
        "core_context": {
            "()": "ray._private.structured_logging.filters.CoreContextFilter",
        },
    },
    "handlers": {
        "console": {
            "level": "INFO",
            "class": "logging.StreamHandler",
            "formatter": "text",
            "filters": ["core_context"],
        },
    },
    "root": {
        "level": "INFO",
        "handlers": ["console"],
    },
}
ray.init(
     job_config=ray.job_config.JobConfig(py_logging_config=LoggingConfig(dict_config))
)

Case 2: pb.serialized_py_logging_config is 95 bytes.

ray.init(
     job_config=ray.job_config.JobConfig(py_logging_config=LoggingConfig("TEXT"))
)

Signed-off-by: kaihsun <kaihsun@anyscale.com>

kevin85421 requested review from ericl, pcmoritz, raulchen and a team as code owners May 15, 2024 01:49

kevin85421 changed the title ~~[Core][2/n] Core structured logging: add logfmt formatter and passing log config to worker process~~ [Core][2/n] Core structured logging: add logfmt formatter and pass log config to worker process May 15, 2024

kevin85421 marked this pull request as draft May 15, 2024 01:50

kevin85421 changed the title ~~[Core][2/n] Core structured logging: add logfmt formatter and pass log config to worker process~~ [WIP][Core][2/n] Core structured logging: add logfmt formatter and pass log config to worker process May 15, 2024

kevin85421 commented May 15, 2024

View reviewed changes

jjyao reviewed May 20, 2024

View reviewed changes

kevin85421 commented May 21, 2024

View reviewed changes

kevin85421 changed the title ~~[WIP][Core][2/n] Core structured logging: add logfmt formatter and pass log config to worker process~~ [Core][2/n] Core structured logging: add logfmt formatter and pass log config to worker process May 21, 2024

kevin85421 changed the title ~~[Core][2/n] Core structured logging: add logfmt formatter and pass log config to worker process~~ [Core][2/n] Core structured logging: add Text formatter and pass log config to worker process May 21, 2024

kevin85421 marked this pull request as ready for review May 21, 2024 06:50

kevin85421 added the go Trigger full test run on premerge label May 21, 2024

jjyao reviewed May 22, 2024

View reviewed changes

kevin85421 added 10 commits May 23, 2024 15:38

update

99024ee

Signed-off-by: kaihsun <kaihsun@anyscale.com>

update

b380e9a

Signed-off-by: kaihsun <kaihsun@anyscale.com>

update

6e78f48

Signed-off-by: kaihsun <kaihsun@anyscale.com>

update

9113d25

Signed-off-by: kaihsun <kaihsun@anyscale.com>

update

9218481

Signed-off-by: kaihsun <kaihsun@anyscale.com>

update

def7635

Signed-off-by: kaihsun <kaihsun@anyscale.com>

update

a16f762

Signed-off-by: kaihsun <kaihsun@anyscale.com>

update

571e2bc

Signed-off-by: kaihsun <kaihsun@anyscale.com>

update

8ec3107

Signed-off-by: kaihsun <kaihsun@anyscale.com>

update

1b37390

Signed-off-by: kaihsun <kaihsun@anyscale.com>

kevin85421 force-pushed the structured-logging-2 branch from 9ba4e95 to 1b37390 Compare May 23, 2024 15:39

jjyao reviewed May 24, 2024

View reviewed changes

python/ray/_private/structured_logging/utils.py Outdated Show resolved Hide resolved

python/ray/_private/structured_logging/utils.py Outdated Show resolved Hide resolved

python/ray/_private/structured_logging/utils.py Outdated Show resolved Hide resolved

jjyao assigned rkooo567 May 24, 2024

kevin85421 added 2 commits May 24, 2024 22:19

update

dc62d5c

Signed-off-by: kaihsun <kaihsun@anyscale.com>

update

69f8b57

Signed-off-by: kaihsun <kaihsun@anyscale.com>

jjyao reviewed May 28, 2024

View reviewed changes

update

d9e63aa

Signed-off-by: kaihsun <kaihsun@anyscale.com>

kevin85421 commented May 28, 2024

View reviewed changes

kevin85421 added 2 commits May 28, 2024 17:53

update

2ec1b4f

Signed-off-by: kaihsun <kaihsun@anyscale.com>

update

9ef1eee

Signed-off-by: kaihsun <kaihsun@anyscale.com>

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

[Core][2/n] Core structured logging: add Text formatter and pass log config to worker process #45344

[Core][2/n] Core structured logging: add Text formatter and pass log config to worker process #45344

kevin85421 commented May 15, 2024 •

edited

kevin85421 May 15, 2024

kevin85421 May 15, 2024

jjyao May 20, 2024

kevin85421 May 20, 2024

kevin85421 May 21, 2024

kevin85421 May 21, 2024

kevin85421 May 21, 2024

kevin85421 May 21, 2024

kevin85421 May 21, 2024

kevin85421 May 21, 2024

jjyao May 22, 2024

kevin85421 May 23, 2024

jjyao May 22, 2024

kevin85421 May 23, 2024

jjyao May 22, 2024

kevin85421 May 23, 2024

jjyao left a comment

jjyao commented May 24, 2024

jjyao May 28, 2024

kevin85421 May 28, 2024

kevin85421 May 28, 2024

jjyao May 28, 2024

kevin85421 May 28, 2024

jjyao May 28, 2024

kevin85421 May 28, 2024

kevin85421 May 28, 2024

kevin85421 commented May 28, 2024



		class LoggingConfig:
		def __init__(self, log_config: Union[dict, str]):

[Core][2/n] Core structured logging: add Text formatter and pass log config to worker process #45344

Are you sure you want to change the base?

[Core][2/n] Core structured logging: add Text formatter and pass log config to worker process #45344

Conversation

kevin85421 commented May 15, 2024 • edited

Why are these changes needed?

Related issue number

Checks

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

jjyao left a comment

Choose a reason for hiding this comment

jjyao commented May 24, 2024

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

kevin85421 commented May 28, 2024

kevin85421 commented May 15, 2024 •

edited