From fc4110249ce60812f7131ff6dd95885eadc53e91 Mon Sep 17 00:00:00 2001 From: Luca Toscano Date: Fri, 31 Mar 2023 15:30:16 +0200 Subject: [PATCH] python: allow to override the UvicornServer's default log config It is useful to be able to change Uvicorn's log settings, for example to be able to change the access log's format. The Uvicorn's Config class provides a "configure_logging" function that is smart about the log_config parameter - if it is a string, and not a dictionary, it is interpreted as a file containing logging directives and that needs to be loaded from disk. This is very convenient for the KServe use case: one can either use the default config, hardcoded in a dictionary, or anything provided as yaml or json file. This change fixes also the default UvicornServer's config. Sadly the current Uvicorn implementation doesn't support changing the access log format, but they suggest to use asgi-logger: https://github.com/encode/uvicorn/pull/947#issuecomment-1283006367 It seems the only way forward to allow a decent customization of a vital sign like the access log. The main downside is that asgi-logger requires python3.8+, so to a temporary workaround could be to add the package as extra in poetry's config and import the AccessLoggerMiddleware only if the user sets the access log format. Fixes: #2778 Signed-off-by: Luca Toscano --- python/kserve/kserve/model_server.py | 19 +++- python/kserve/kserve/protocol/rest/server.py | 94 ++++++++++++-------- python/kserve/poetry.lock | 16 ++++ python/kserve/pyproject.toml | 6 ++ 4 files changed, 96 insertions(+), 39 deletions(-) diff --git a/python/kserve/kserve/model_server.py b/python/kserve/kserve/model_server.py index 3d121c8819c..f99c3ad9337 100644 --- a/python/kserve/kserve/model_server.py +++ b/python/kserve/kserve/model_server.py @@ -55,6 +55,10 @@ help="Enable docs url '/docs' to display Swagger UI.") parser.add_argument("--enable_latency_logging", default=True, type=lambda x: bool(strtobool(x)), help="Output a log per request with latency metrics.") +parser.add_argument("--log_config_file", default=None, type=str, + help="File path containing UvicornServer's log config. Needs to be a yaml or json file.") +parser.add_argument("--access_log_format", default=None, type=str, + help="Format to set for the access log (provided by asgi-logger).") args, _ = parser.parse_known_args() @@ -76,6 +80,8 @@ class ModelServer: enable_grpc (bool): Whether to turn on grpc server. Default: ``True`` enable_docs_url (bool): Whether to turn on ``/docs`` Swagger UI. Default: ``False``. enable_latency_logging (bool): Whether to log latency metric. Default: ``True``. + log_config_file (dict): File path containing UvicornServer's log config. Default: ``None``. + access_log_format (string): Format to set for the access log (provided by asgi-logger). Default: ``None`` """ def __init__(self, http_port: int = args.http_port, @@ -86,7 +92,9 @@ def __init__(self, http_port: int = args.http_port, registered_models: ModelRepository = ModelRepository(), enable_grpc: bool = args.enable_grpc, enable_docs_url: bool = args.enable_docs_url, - enable_latency_logging: bool = args.enable_latency_logging): + enable_latency_logging: bool = args.enable_latency_logging, + log_config_file: str = args.log_config_file, + access_log_format: str = args.access_log_format): self.registered_models = registered_models self.http_port = http_port self.grpc_port = grpc_port @@ -100,6 +108,8 @@ def __init__(self, http_port: int = args.http_port, self.model_repository_extension = ModelRepositoryExtension( model_registry=self.registered_models) self._grpc_server = GRPCServer(grpc_port, self.dataplane, self.model_repository_extension) + self.log_config_file = log_config_file + self.access_log_format = access_log_format def start(self, models: Union[List[Model], Dict[str, Deployment]]) -> None: if isinstance(models, list): @@ -143,7 +153,9 @@ async def serve(): sig, lambda s=sig: asyncio.create_task(self.stop(sig=s)) ) self._rest_server = UvicornServer(self.http_port, [serversocket], - self.dataplane, self.model_repository_extension, self.enable_docs_url) + self.dataplane, self.model_repository_extension, + self.enable_docs_url, log_config_file=self.log_config_file, + access_log_format=self.access_log_format) if self.workers == 1: await self._rest_server.run() else: @@ -153,7 +165,8 @@ async def serve(): # https://github.com/tiangolo/fastapi/issues/1586 multiprocessing.set_start_method('fork') server = UvicornServer(self.http_port, [serversocket], - self.dataplane, self.model_repository_extension, self.enable_docs_url) + self.dataplane, self.model_repository_extension, + self.enable_docs_url, custom_log_config=self.log_config) for _ in range(self.workers): p = Process(target=server.run_sync) p.start() diff --git a/python/kserve/kserve/protocol/rest/server.py b/python/kserve/kserve/protocol/rest/server.py index c699e97c807..3ce05fa9efe 100644 --- a/python/kserve/kserve/protocol/rest/server.py +++ b/python/kserve/kserve/protocol/rest/server.py @@ -126,7 +126,8 @@ def create_application(self) -> FastAPI: class UvicornServer: def __init__(self, http_port: int, sockets: List[socket.socket], - data_plane: DataPlane, model_repository_extension, enable_docs_url): + data_plane: DataPlane, model_repository_extension, enable_docs_url, + log_config_file: str = None, access_log_format: str = None): super().__init__() self.sockets = sockets rest_server = RESTServer(data_plane, model_repository_extension, enable_docs_url) @@ -136,46 +137,67 @@ def __init__(self, http_port: int, sockets: List[socket.socket], client=PrintTimings(), metric_namer=StarletteScopeToName(prefix="kserve.io", starlette_app=app) ) + log_config = { + "version": 1, + "formatters": { + "default": { + "()": "uvicorn.logging.DefaultFormatter", + "datefmt": DATE_FMT, + "fmt": "%(asctime)s.%(msecs)03d %(name)s %(levelprefix)s %(message)s", + "use_colors": None, + }, + "access": { + "()": "uvicorn.logging.AccessFormatter", + "datefmt": DATE_FMT, + "fmt": '%(asctime)s.%(msecs)03d %(name)s %(levelprefix)s %(client_addr)s %(process)s - ' + '"%(request_line)s" %(status_code)s', + # noqa: E501 + }, + }, + "handlers": { + "default": { + "formatter": "default", + "class": "logging.StreamHandler", + "stream": "ext://sys.stderr", + }, + "access": { + "formatter": "access", + "class": "logging.StreamHandler", + "stream": "ext://sys.stdout", + }, + }, + "loggers": { + "uvicorn": {"handlers": ["default"], "level": "INFO"}, + "uvicorn.error": {"level": "INFO"}, + "uvicorn.access": {"handlers": ["access"], "level": "INFO"}, + }, + } + + # If the log_config value is a string ending up with ".json" + # or ".yaml", it is interpreted as file path and the log configuration + # is loaded from disk. + if log_config_file: + log_config = log_config_file + self.cfg = uvicorn.Config( app=app, host="0.0.0.0", + log_config=log_config, port=http_port, - log_config={ - "version": 1, - "formatters": { - "default": { - "()": "uvicorn.logging.DefaultFormatter", - "datefmt": DATE_FMT, - "fmt": "%(asctime)s.%(msecs)03d %(name)s %(levelprefix)s %(message)s", - "use_colors": None, - }, - "access": { - "()": "uvicorn.logging.AccessFormatter", - "datefmt": DATE_FMT, - "fmt": '%(asctime)s.%(msecs)03d %(name)s %(levelprefix)s %(client_addr)s %(process)s - ' - '"%(request_line)s" %(status_code)s', - # noqa: E501 - }, - }, - "rest": { - "default": { - "formatter": "default", - "class": "logging.StreamHandler", - "stream": "ext://sys.stderr", - }, - "access": { - "formatter": "access", - "class": "logging.StreamHandler", - "stream": "ext://sys.stdout", - }, - }, - "loggers": { - "uvicorn": {"rest": ["default"], "level": "INFO"}, - "uvicorn.error": {"level": "INFO"}, - "uvicorn.access": {"rest": ["access"], "level": "INFO", "propagate": False}, - }, - } ) + + # More context in https://github.com/encode/uvicorn/pull/947 + # At the time of writing the ASGI specs are not clear when it comes + # to change the access log format, and hence the Uvicorn upstream devs + # chose to create a custom middleware for this. + # The allowed log format is specified in https://github.com/Kludex/asgi-logger#usage + if access_log_format: + from asgi_logger import AccessLoggerMiddleware + logging.getLogger("uvicorn.access").handlers = [] + app.add_middleware( + AccessLoggerMiddleware, format=access_log_format, + logger=logging.getLogger("uvicorn.access")) + self.server = _NoSignalUvicornServer(config=self.cfg) def run_sync(self): diff --git a/python/kserve/poetry.lock b/python/kserve/poetry.lock index 642d5e5ea87..41a1b3afe88 100644 --- a/python/kserve/poetry.lock +++ b/python/kserve/poetry.lock @@ -203,6 +203,21 @@ doc = ["packaging", "sphinx-autodoc-typehints (>=1.2.0)", "sphinx-rtd-theme"] test = ["contextlib2", "coverage[toml] (>=4.5)", "hypothesis (>=4.0)", "mock (>=4)", "pytest (>=7.0)", "pytest-mock (>=3.6.1)", "trustme", "uvloop (<0.15)", "uvloop (>=0.15)"] trio = ["trio (>=0.16,<0.22)"] +[[package]] +name = "asgi-logger" +version = "0.1.0" +description = "Middleware based uvicorn access logger! :tada:" +category = "main" +optional = true +python-versions = ">=3.8,<4.0" +files = [ + {file = "asgi-logger-0.1.0.tar.gz", hash = "sha256:b289f530bf49d14320242a567580ffc8ad053ba5667eece27d25a97822d3a0aa"}, + {file = "asgi_logger-0.1.0-py3-none-any.whl", hash = "sha256:f2d1252cfc48b4a806d1810f0308ba2979fa73aca06ecc809903a8ebc5a6ef23"}, +] + +[package.dependencies] +asgiref = ">=3.4.1,<4.0.0" + [[package]] name = "asgiref" version = "3.6.0" @@ -3116,6 +3131,7 @@ docs = ["furo", "jaraco.packaging (>=9)", "jaraco.tidelift (>=1.4)", "rst.linker testing = ["big-O", "flake8 (<5)", "jaraco.functools", "jaraco.itertools", "more-itertools", "pytest (>=6)", "pytest-black (>=0.3.7)", "pytest-checkdocs (>=2.4)", "pytest-cov", "pytest-enabler (>=1.3)", "pytest-flake8", "pytest-mypy (>=0.9.1)"] [extras] +logging = ["asgi-logger"] storage = ["azure-identity", "azure-storage-blob", "azure-storage-file-share", "boto3", "google-cloud-storage", "requests", "urllib3"] [metadata] diff --git a/python/kserve/pyproject.toml b/python/kserve/pyproject.toml index ea154ece572..271e33eb9b8 100644 --- a/python/kserve/pyproject.toml +++ b/python/kserve/pyproject.toml @@ -61,6 +61,9 @@ azure-storage-file-share = { version = "~12.7.0", optional = true } azure-identity = { version = "^1.8.0", optional = true } boto3 = { version = "^1.21.0", optional = true } +# Logging dependencies. They can be opted into by apps. +asgi-logger = { version = "^0.1.0", optional = true, python = ">3.8.0,<3.11" } + [tool.poetry.extras] storage = [ "urllib3", @@ -71,6 +74,9 @@ storage = [ "azure-identity", "boto3", ] +logging = [ + "asgi-logger" +] [tool.poetry.group.test] optional = true