[Serve] fix logging error on passing traceback object into exc_info (#…

…46105)

<!-- Thank you for your contribution! Please review
https://github.com/ray-project/ray/blob/master/CONTRIBUTING.rst before
opening a pull request. -->

<!-- Please add a reviewer to the assignee section when you create a PR.
If you don't have the access to it, we will shortly find a reviewer and
assign them to your PR. -->

## Why are these changes needed?

The root cause for the logging error we saw was due to the client
passing traceback object into `exc_info` during logging. In serve logger
we do a deepcopy on the log record's `__dict__` attribute which was
unable to pickle the traceback for the deep copy. This PR removed the
deepcopy completely since we do not modify to the copied __dict__ at
all. Also added a test to ensure the regression doesn't happen.

## Related issue number

Closes #45912

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

---------

Signed-off-by: Gene Su <[email protected]>

python/ray/serve/_private/logging_utils.py

@@ -100,23 +100,22 @@ def format(self, record: logging.LogRecord) -> str:
  The formatted log record in json format.
  """
  record_format = copy.deepcopy(self.component_log_fmt)
- record_attributes = copy.deepcopy(record.__dict__)
  record_format[SERVE_LOG_LEVEL_NAME] = record.levelname
  record_format[SERVE_LOG_TIME] = self.asctime_formatter.format(record)
 
  for field in ServeJSONFormatter.ADD_IF_EXIST_FIELDS:
- if field in record_attributes:
- record_format[field] = record_attributes[field]
+ if field in record.__dict__:
+ record_format[field] = record.__dict__[field]
 
  record_format[SERVE_LOG_MESSAGE] = self.message_formatter.format(record)
 
- if SERVE_LOG_EXTRA_FIELDS in record_attributes:
- if not isinstance(record_attributes[SERVE_LOG_EXTRA_FIELDS], dict):
+ if SERVE_LOG_EXTRA_FIELDS in record.__dict__:
+ if not isinstance(record.__dict__[SERVE_LOG_EXTRA_FIELDS], dict):
  raise ValueError(
  f"Expected a dictionary passing into {SERVE_LOG_EXTRA_FIELDS}, "
- f"but got {type(record_attributes[SERVE_LOG_EXTRA_FIELDS])}"
+ f"but got {type(record.__dict__[SERVE_LOG_EXTRA_FIELDS])}"
  )
- for k, v in record_attributes[SERVE_LOG_EXTRA_FIELDS].items():
+ for k, v in record.__dict__[SERVE_LOG_EXTRA_FIELDS].items():
  if k in record_format:
  raise KeyError(f"Found duplicated key in the log record: {k}")
  record_format[k] = v

python/ray/serve/schema.py

@@ -99,12 +99,12 @@ class LoggingConfig(BaseModel):
  from ray import serve
  from ray.serve.schema import LoggingConfig
  # Set log level for the deployment.
- @serve.deployment(LoggingConfig(log_level="DEBUG")
+ @serve.deployment(LoggingConfig(log_level="DEBUG"))
  class MyDeployment:
  def __call__(self) -> str:
  return "Hello world!"
  # Set log directory for the deployment.
- @serve.deployment(LoggingConfig(logs_dir="/my_dir")
+ @serve.deployment(LoggingConfig(logs_dir="/my_dir"))
  class MyDeployment:
  def __call__(self) -> str:
  return "Hello world!"

python/ray/serve/tests/test_logging.py

@@ -832,5 +832,45 @@ def test_stream_to_logger():
  stream_to_logger.i_dont_exist
 
 
+@pytest.mark.skipif(sys.platform == "win32", reason="Fail to create temp dir.")
+@pytest.mark.parametrize(
+ "ray_instance",
+ [
+ {"RAY_SERVE_LOG_TO_STDERR": "0"},
+ ],
+ indirect=True,
+)
+def test_json_logging_with_unpickleable_exc_info(
+ serve_and_ray_shutdown, ray_instance, tmp_dir
+):
+ """Test the json logging with unpickleable exc_info.
+
+ exc_info field is often used to log the exception stack trace. However, we had issue
+ where deepcopy is applied to traceback object from exc_info which is not pickleable
+ and caused logging error.
+
+ See: https://github.com/ray-project/ray/issues/45912
+ """
+ logs_dir = Path(tmp_dir)
+ logging_config = LoggingConfig(encoding="JSON", logs_dir=str(logs_dir))
+ logger = logging.getLogger("ray.serve")
+
+ @serve.deployment(logging_config=logging_config)
+ class App:
+ def __call__(self):
+ try:
+ raise Exception("fake_exception")
+ except Exception as e:
+ logger.info("log message", exc_info=e)
+ return "foo"
+
+ serve.run(App.bind())
+ requests.get("https://127.0.0.1:8000/")
+ for log_file in os.listdir(logs_dir):
+ with open(logs_dir / log_file) as f:
+ assert "Logging error" not in f.read()
+ assert "cannot pickle" not in f.read()
+
+
 if __name__ == "__main__":
  sys.exit(pytest.main(["-v", "-s", __file__]))