diff --git a/python/kserve/kserve/model_server.py b/python/kserve/kserve/model_server.py index 3d121c8819..f99c3ad933 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 c699e97c80..ca07f28da1 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,66 @@ 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", "propagate": False}, + }, + } + + # 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) + self.server = _NoSignalUvicornServer(config=self.cfg) def run_sync(self): diff --git a/python/kserve/poetry.lock b/python/kserve/poetry.lock index 31fab8b49f..627d74870d 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" @@ -3126,6 +3141,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 fe74c71599..302878a995 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