add additional_log_standard_attrs to serve logging config (#51144)

### Changes Introduced
1. **Consistent Logging Configuration**  
- Added `additional_log_standard_attrs` to Serve's `LoggingConfig`,
aligning it with Ray's logging configuration.

2. **Refactored `ServeFormatter`**  
   - `ServeFormatter` now inherits from Ray’s `TextFormatter`.

3. **Fixed Potential Bug in `_proto_to_dict`**  
- Previously, `_proto_to_dict` retained the data type for repeated
fields as
`google.protobuf.internal.containers.RepeatedScalarFieldContainer`
instead of converting it to a Python `list`.
   - This caused validation failures in Pydantic.  
- The issue did not surface earlier because
`DeploymentConfig.user_configured_option_names` (the only prior repeated
attribute user) explicitly disabled data type validation.

4. schema change to `src/ray/protobuf/serve.proto`

### Discussion & Feedback Needed
- If we don’t modify `_proto_to_dict`, alternative approaches include:  
  1. Disabling type checking for Serve’s `LoggingConfig`.  
  2. Performing type casting in `from_proto`.  
- Seeking input from reviewers on the preferred approach.


### How do i know this works

1. updated unit tests
2. Manual test

sample code

```python
import logging
from ray import serve
import requests
import starlette

logger = logging.getLogger("ray.serve")
logging_config = {
    "additional_log_standard_attrs": ["name"],
}

@serve.deployment(logging_config=logging_config)
class Model:
    def __call__(self, req: starlette.requests.Request):
        logger.info("This is a test log")
        return 1

serve.run(Model.bind())

resp = requests.get("http://127.0.0.1:8000/")
assert resp.status_code == 200
resp = resp.json()
```

results from changes in this PR
```zsh
(myenv) ➜  serve_apps python app1.py
2025-03-07 15:07:18,712	INFO worker.py:1839 -- Started a local Ray instance. View the dashboard at 127.0.0.1:8265
(ProxyActor pid=85544) INFO 2025-03-07 15:07:20,223 proxy 127.0.0.1 -- Proxy starting on node 799527b99924c6f2084364a36726a6874d28bfba171c5a06d619bdb2 (HTTP port: 8000).
INFO 2025-03-07 15:07:20,301 serve 85513 -- Started Serve in namespace "serve".
(ProxyActor pid=85544) INFO 2025-03-07 15:07:20,252 proxy 127.0.0.1 -- Got updated endpoints: {}.
(ServeController pid=85545) INFO 2025-03-07 15:07:20,403 controller 85545 -- Deploying new version of Deployment(name='Model', app='default') (initial target replicas: 1).
(ProxyActor pid=85544) INFO 2025-03-07 15:07:20,405 proxy 127.0.0.1 -- Got updated endpoints: {Deployment(name='Model', app='default'): EndpointInfo(route='/', app_is_cross_language=False)}.
(ProxyActor pid=85544) INFO 2025-03-07 15:07:20,408 proxy 127.0.0.1 -- Started <ray.serve._private.router.SharedRouterLongPollClient object at 0x12c068b80>.
(ServeController pid=85545) INFO 2025-03-07 15:07:20,505 controller 85545 -- Adding 1 replica to Deployment(name='Model', app='default').
INFO 2025-03-07 15:07:21,417 serve 85513 -- Application 'default' is ready at http://127.0.0.1:8000/.
(ServeReplica:default:Model pid=85549) /Users/abrar/pg/ray/python/ray/serve/_private/replica.py:1320: UserWarning: Calling sync method '__call__' directly on the asyncio loop. In a future version, sync methods will be run in a threadpool by default. Ensure your sync methods are thread safe or keep the existing behavior by making them `async def`. Opt into the new behavior by setting RAY_SERVE_RUN_SYNC_IN_THREADPOOL=1.
(ServeReplica:default:Model pid=85549)   warnings.warn(
(ServeReplica:default:Model pid=85549) INFO 2025-03-07 15:07:21,434 default_Model pd962afl 4e386730-546d-4693-abb4-72e107cfe87f ray.serve -- This is a test log
(ServeReplica:default:Model pid=85549) INFO 2025-03-07 15:07:21,435 default_Model pd962afl 4e386730-546d-4693-abb4-72e107cfe87f ray.serve -- GET / 200 4.1ms
```

results from code from master
```zsh
(myenv) ➜  serve_apps python app1.py
2025-03-07 10:01:31,875 INFO worker.py:1839 -- Started a local Ray instance. View the dashboard at 127.0.0.1:8265 
(ProxyActor pid=41050) INFO 2025-03-07 10:01:33,414 proxy 127.0.0.1 -- Proxy starting on node 2194f00eb1063128758f6d7e6d5a56f7425845ac6492ca35cf04ab15 (HTTP port: 8000).
(ProxyActor pid=41050) INFO 2025-03-07 10:01:33,442 proxy 127.0.0.1 -- Got updated endpoints: {}.
INFO 2025-03-07 10:01:33,461 serve 41018 -- Started Serve in namespace "serve".
(ServeController pid=41052) INFO 2025-03-07 10:01:33,472 controller 41052 -- Deploying new version of Deployment(name='Model', app='default') (initial target replicas: 1).
(ProxyActor pid=41050) INFO 2025-03-07 10:01:33,474 proxy 127.0.0.1 -- Got updated endpoints: {Deployment(name='Model', app='default'): EndpointInfo(route='/', app_is_cross_language=False)}.
(ProxyActor pid=41050) INFO 2025-03-07 10:01:33,478 proxy 127.0.0.1 -- Started <ray.serve._private.router.SharedRouterLongPollClient object at 0x1289f14f0>.
(ServeController pid=41052) INFO 2025-03-07 10:01:33,575 controller 41052 -- Adding 1 replica to Deployment(name='Model', app='default').
INFO 2025-03-07 10:01:34,574 serve 41018 -- Application 'default' is ready at http://127.0.0.1:8000/.
(ServeReplica:default:Model pid=41056) /Users/abrar/pg/ray/python/ray/serve/_private/replica.py:1320: UserWarning: Calling sync method '__call__' directly on the asyncio loop. In a future version, sync methods will be run in a threadpool by default. Ensure your sync methods are thread safe or keep the existing behavior by making them `async def`. Opt into the new behavior by setting RAY_SERVE_RUN_SYNC_IN_THREADPOOL=1.
(ServeReplica:default:Model pid=41056)   warnings.warn(
(ServeReplica:default:Model pid=41056) INFO 2025-03-07 10:01:34,582 default_Model 8e8rohb4 72547bda-8287-4767-910a-0763dbabf96b -- This is a test log
(ServeReplica:default:Model pid=41056) INFO 2025-03-07 10:01:34,582 default_Model 8e8rohb4 72547bda-8287-4767-910a-0763dbabf96b -- GET / 200 3.0ms
```

---------

Signed-off-by: Abrar Sheikh <[email protected]>

Author: abrarsheikh

python/ray/_private/ray_logging/formatters.py

@@ -41,6 +41,10 @@ def set_additional_log_standard_attrs(
     ) -> None:
         self._additional_log_standard_attrs = additional_log_standard_attrs
 
+    @property
+    def additional_log_standard_attrs(self) -> List[str]:
+        return self._additional_log_standard_attrs
+
     def generate_record_format_attrs(
         self,
         record: logging.LogRecord,

python/ray/serve/_private/config.py

@@ -60,8 +60,19 @@ def _proto_to_dict(proto: Message) -> Dict:
     data = {}
     # Fill data with non-empty fields.
     for field, value in proto.ListFields():
+        # Handle repeated fields
+        if field.label == FieldDescriptor.LABEL_REPEATED:
+            # if we dont do this block the repeated field will be a list of
+            # `google.protobuf.internal.containers.RepeatedScalarFieldContainer
+            # Explicitly convert to list
+            if field.type == FieldDescriptor.TYPE_MESSAGE:
+                data[field.name] = [
+                    _proto_to_dict(v) for v in value
+                ]  # Convert each item
+            else:
+                data[field.name] = list(value)  # Convert to list directly
         # Recursively call if the field is another protobuf.
-        if field.type == FieldDescriptor.TYPE_MESSAGE:
+        elif field.type == FieldDescriptor.TYPE_MESSAGE:
             data[field.name] = _proto_to_dict(value)
         else:
             data[field.name] = value
@@ -74,7 +85,6 @@ def _proto_to_dict(proto: Message) -> Dict:
             and not field.containing_oneof  # skip optional fields
         ):
             data[field.name] = field.default_value
-
     return data
 
 
@@ -198,7 +208,6 @@ def logging_config_valid(cls, v):
         from ray.serve.schema import LoggingConfig
 
         v = LoggingConfig(**v).dict()
-
         return v
 
     @validator("max_queued_requests", always=True)

python/ray/serve/_private/logging_utils.py

@@ -8,7 +8,7 @@
 import ray
 from ray._private.ray_constants import LOGGING_ROTATE_BACKUP_COUNT, LOGGING_ROTATE_BYTES
 from ray._private.ray_logging.filters import CoreContextFilter
-from ray._private.ray_logging.formatters import JSONFormatter
+from ray._private.ray_logging.formatters import JSONFormatter, TextFormatter
 from ray.serve._private.common import ServeComponentType
 from ray.serve._private.constants import (
     RAY_SERVE_ENABLE_CPU_PROFILING,
@@ -111,7 +111,7 @@ def filter(self, record):
         return True
 
 
-class ServeFormatter(logging.Formatter):
+class ServeFormatter(TextFormatter):
     """Serve Logging Formatter
 
     The formatter will generate the log format on the fly based on the field of record.
@@ -123,7 +123,12 @@ def __init__(
         self,
         component_name: str,
         component_id: str,
+        fmt: Optional[str] = None,
+        datefmt: Optional[str] = None,
+        style: str = "%",
+        validate: bool = True,
     ):
+        super().__init__(fmt, datefmt, style, validate)
         self.component_log_fmt = ServeFormatter.COMPONENT_LOG_FMT.format(
             component_name=component_name, component_id=component_id
         )
@@ -133,17 +138,18 @@ def format(self, record: logging.LogRecord) -> str:
 
         Args:
             record: The log record to be formatted.
-
             Returns:
                 The formatted log record in string format.
         """
         record_format = self.component_log_fmt
         record_formats_attrs = []
         if SERVE_LOG_REQUEST_ID in record.__dict__:
             record_formats_attrs.append(SERVE_LOG_RECORD_FORMAT[SERVE_LOG_REQUEST_ID])
+        record_formats_attrs.extend(
+            [f"%({k})s" for k in self.additional_log_standard_attrs]
+        )
         record_formats_attrs.append(SERVE_LOG_RECORD_FORMAT[SERVE_LOG_MESSAGE])
         record_format += " ".join(record_formats_attrs)
-
         # create a formatter using the format string
         formatter = logging.Formatter(record_format)
 
@@ -291,11 +297,21 @@ def configure_component_logger(
     logger.setLevel(logging_config.log_level)
     logger.handlers.clear()
 
+    serve_formatter = ServeFormatter(component_name, component_id)
+    json_formatter = JSONFormatter()
+    if logging_config.additional_log_standard_attrs:
+        json_formatter.set_additional_log_standard_attrs(
+            logging_config.additional_log_standard_attrs
+        )
+        serve_formatter.set_additional_log_standard_attrs(
+            logging_config.additional_log_standard_attrs
+        )
+
     # Only add stream handler if RAY_SERVE_LOG_TO_STDERR is True or if
     # `stream_handler_only` is set to True.
     if RAY_SERVE_LOG_TO_STDERR or stream_handler_only:
         stream_handler = logging.StreamHandler()
-        stream_handler.setFormatter(ServeFormatter(component_name, component_id))
+        stream_handler.setFormatter(serve_formatter)
         stream_handler.addFilter(log_to_stderr_filter)
         stream_handler.addFilter(ServeContextFilter())
         logger.addHandler(stream_handler)
@@ -341,9 +357,9 @@ def configure_component_logger(
         file_handler.addFilter(
             ServeComponentFilter(component_name, component_id, component_type)
         )
-        file_handler.setFormatter(JSONFormatter())
+        file_handler.setFormatter(json_formatter)
     else:
-        file_handler.setFormatter(ServeFormatter(component_name, component_id))
+        file_handler.setFormatter(serve_formatter)
 
     if logging_config.enable_access_log is False:
         file_handler.addFilter(log_access_log_filter)

python/ray/serve/schema.py

@@ -15,6 +15,7 @@
     root_validator,
     validator,
 )
+from ray._private.ray_logging.constants import LOGRECORD_STANDARD_ATTRS
 from ray._private.runtime_env.packaging import parse_uri
 from ray.serve._private.common import (
     DeploymentStatus,
@@ -140,6 +141,15 @@ class Config:
             "Whether to enable access logs for each request. Default to True."
         ),
     )
+    additional_log_standard_attrs: List[str] = Field(
+        default_factory=list,
+        description=(
+            "Default attributes from the Python standard logger that will be "
+            "added to all log records. "
+            "See https://docs.python.org/3/library/logging.html#logrecord-attributes "
+            "for a list of available attributes."
+        ),
+    )
 
     @validator("encoding")
     def valid_encoding_format(cls, v):
@@ -168,6 +178,16 @@ def valid_log_level(cls, v):
             )
         return v
 
+    @validator("additional_log_standard_attrs")
+    def valid_additional_log_standard_attrs(cls, v):
+        for attr in v:
+            if attr not in LOGRECORD_STANDARD_ATTRS:
+                raise ValueError(
+                    f"Unknown attribute '{attr}'. "
+                    f"Additional log standard attributes must be one of {LOGRECORD_STANDARD_ATTRS}."
+                )
+        return list(set(v))
+
     def _compute_hash(self) -> int:
         return crc32(
             (

python/ray/serve/tests/test_logging.py

@@ -597,11 +597,19 @@ def __call__(self, req: starlette.requests.Request):
         paths[-1] = "new_dir"
         new_log_dir = "/".join(paths)
 
-        serve.run(Model.options(logging_config={"logs_dir": new_log_dir}).bind())
+        serve.run(
+            Model.options(
+                logging_config={
+                    "logs_dir": new_log_dir,
+                    "additional_log_standard_attrs": ["name"],
+                }
+            ).bind()
+        )
         resp = requests.get("http://127.0.0.1:8000/").json()
         assert "new_dir" in resp["logs_path"]
 
         check_log_file(resp["logs_path"], [".*model_info_level.*"])
+        check_log_file(resp["logs_path"], ["ray.serve"], check_contains=True)
 
     @pytest.mark.parametrize("enable_access_log", [True, False])
     @pytest.mark.parametrize("encoding_type", ["TEXT", "JSON"])
@@ -636,6 +644,35 @@ def __call__(self, req: starlette.requests.Request):
             with pytest.raises(AssertionError):
                 check_log_file(resp["logs_path"], [".*model_not_show.*"])
 
+    @pytest.mark.parametrize("encoding_type", ["TEXT", "JSON"])
+    def test_additional_log_standard_attrs(self, serve_and_ray_shutdown, encoding_type):
+        """Test additional log standard attrs"""
+        logger = logging.getLogger("ray.serve")
+        logging_config = {
+            "enable_access_log": True,
+            "encoding": encoding_type,
+            "additional_log_standard_attrs": ["name"],
+        }
+
+        @serve.deployment(logging_config=logging_config)
+        class Model:
+            def __call__(self, req: starlette.requests.Request):
+                logger.info("model_info_level")
+                logger.info("model_not_show", extra={"serve_access_log": True})
+                return {
+                    "logs_path": logger.handlers[1].baseFilename,
+                }
+
+        serve.run(Model.bind())
+
+        resp = requests.get("http://127.0.0.1:8000/")
+        assert resp.status_code == 200
+        resp = resp.json()
+        if encoding_type == "JSON":
+            check_log_file(resp["logs_path"], ["name"], check_contains=True)
+        else:
+            check_log_file(resp["logs_path"], ["ray.serve"], check_contains=True)
+
     def test_application_logging_overwrite(self, serve_and_ray_shutdown):
         @serve.deployment
         class Model:

python/ray/serve/tests/unit/test_config.py

@@ -769,13 +769,17 @@ def test_nested_protobufs(self):
     def test_repeated_field(self):
         """Test _proto_to_dict() to deserialize protobuf with repeated field"""
         user_configured_option_names = ["foo", "bar"]
-        proto = DeploymentConfigProto(
+        config = DeploymentConfig.from_default(
             user_configured_option_names=user_configured_option_names,
         )
+        proto_bytes = config.to_proto_bytes()
+        proto = DeploymentConfigProto.FromString(proto_bytes)
         result = _proto_to_dict(proto)
-
         # Repeated field is filled correctly as list.
-        assert result["user_configured_option_names"] == user_configured_option_names
+        assert set(result["user_configured_option_names"]) == set(
+            user_configured_option_names
+        )
+        assert isinstance(result["user_configured_option_names"], list)
 
     def test_enum_field(self):
         """Test _proto_to_dict() to deserialize protobuf with enum field"""

python/ray/serve/tests/unit/test_schema.py

@@ -688,6 +688,7 @@ def test_parse_dict(self):
         assert schema.encoding == "JSON"
         assert schema.logs_dir == "/my_dir"
         assert schema.enable_access_log
+        assert schema.additional_log_standard_attrs == []
 
         # Test string values for log_level.
         schema = LoggingConfig.parse_obj(
@@ -714,6 +715,22 @@ def test_default_values(self):
         assert schema.encoding == "TEXT"
         assert schema.logs_dir is None
         assert schema.enable_access_log
+        assert schema.additional_log_standard_attrs == []
+
+    def test_additional_log_standard_attrs_type(self):
+        schema = LoggingConfig.parse_obj({"additional_log_standard_attrs": ["name"]})
+        assert isinstance(schema.additional_log_standard_attrs, list)
+        assert schema.additional_log_standard_attrs == ["name"]
+
+    def test_additional_log_standard_attrs_type_error(self):
+        with pytest.raises(ValidationError):
+            LoggingConfig.parse_obj({"additional_log_standard_attrs": "name"})
+
+    def test_additional_log_standard_attrs_deduplicate(self):
+        schema = LoggingConfig.parse_obj(
+            {"additional_log_standard_attrs": ["name", "name"]}
+        )
+        assert schema.additional_log_standard_attrs == ["name"]
 
 
 # This function is defined globally to be accessible via import path

src/ray/protobuf/serve.proto

@@ -86,6 +86,7 @@ message LoggingConfig {
   string log_level = 2;
   string logs_dir = 3;
   bool enable_access_log = 4;
+  repeated string additional_log_standard_attrs = 5;
 }
 
 //[End] Logging Config