Logging configuration with Ray Serve

Hey,

I’ve been browsing through documentation and the python ray codebase, but can’t seem to find a solution.

I’m using ray serve (in the CLI, so ray serve my_script:my_model ) and I want all my logs to be fully in JSON format, unfortunately that seems a lot harder than expected. Whenever any of Ray’s functionality internally calls configure_component_logger, I don’t manage to undo some of the streamhandler’s prefixes.

Small toy example:

@serve.deployment
@serve.ingress(app)
class MyModel:
    def __init__(self):
         pass

    @app.get(
        "/health",
        summary="Health Check",
        description="Check whether the service is up and running.",
    )
    async def health(self):
        # Doing this in the init does not work to get a JSON formatted output, I have to do it in
        # the method...
        _logger = logging.getLogger("ray.serve")
        _logger.handlers.clear()
        handler = logging.StreamHandler()
        handler.setFormatter(get_formatter(log_format=LOG_FORMAT))
        _logger.addHandler(handler)

        _logger.info("I'm healthy!")

        return {"status": "healthy"}

my_model = MyModel.bind()

get_formatter is code I can’t share, but it creates a formatter (with structlog) that structures the logs into JSONs. Unfortunately two things break my approach here:

  • Updating the handler in the init does not work, between the init and the method (here health), something happens that undoes my handler configuration. I suspect in RayServeWrappedReplicate here.
  • Even when I put the logging configuration in the method itself, just before doing the logging, my stdout logs get an unwanted prefix:
(ServeReplica:default_MyModel pid=382) {"event": "I'm healthy!", "level": "info"}

How can I configure Ray Serve logging so that messages are fully JSON, without having to reconfigure the logger inside the non-init endpoints? I’m happy to have the information of the pid and model/actor in my log, but it should be attributes in the json.

Hey,

I’m running into the same issue, I was wondering if you managed to find a solution eventually

@Toekan @Marco_Filippone
Did you guys find any solution to this?

We’re having the same issues…
Our custom log handler gets detached during Serve Replica startup.

To reproduce this, create a custom log handler, attach it and print a stack trace in its close() method to see what kills it.

Something like:

import logging
class CustomHandler(logging.Handler):
  [...]
  def close(self):
    import traceback
    traceback.print_stack()
    super().close()

The printed stack trace inside the Serve Replica process then looks like this:

[...]
File "[...]/lib/python3.10/site-packages/ray/serve/api.py", line 222, in __init__
  ASGIAppReplicaWrapper.__init__(self, frozen_app)
File "[...]/lib/python3.10/site-packages/ray/serve/_private/http_util.py", line 435, in __init__
  self._serve_asgi_lifespan = LifespanOn(Config(self._asgi_app, lifespan="on"))
File "[...]/lib/python3.10/site-packages/uvicorn/config.py", line 285, in __init__
  self.configure_logging()
File "[...]/lib/python3.10/site-packages/uvicorn/config.py", line 393, in configure_logging
  logging.config.dictConfig(self.log_config)
File "[...]/lib/python3.10/logging/config.py", line 811, in dictConfig
  dictConfigClass(config).configure()
File "[...]/lib/python3.10/logging/config.py", line 538, in configure
  _clearExistingHandlers()
File "[...]/lib/python3.10/logging/config.py", line 275, in _clearExistingHandlers
  logging.shutdown(logging._handlerList[:])
File "[...]/lib/python3.10/logging/__init__.py", line 2183, in shutdown
  h.close()
File "[...]/custom_handler.py", line XX, in close
  traceback.print_stack()

So, uvicorn calls dictConfig() in CPython logging module which then removes all existing handlers in _clearExistingHandlers(). This ultimately seems to be a bug in CPythons logging module in config.py, which seems to have a disable_existing_loggers setting to control exactly this, but does not seem to honor it correctly in _clearExistingHandlers().

There seems to have been a similar issue in log.py of older Ray versions, also calling dictConfig() with the non-working disable_existing_loggers. But we were able to work around this by importing ray before we attach our custom handler and later versions seem to have worked around this problem.

Versions:
Ray 2.37.0
uvicorn 0.23.2
CPython 3.10.12