Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

python: allow to override the UvicornServer's default log config #2782

Merged
merged 1 commit into from
May 5, 2023
Merged

python: allow to override the UvicornServer's default log config #2782

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
19 changes: 16 additions & 3 deletions python/kserve/kserve/model_server.py
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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,
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@elukey Do you have an example how to pass this on the inference service yaml? I guess you need to mount this log file as ConfigMap

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@yuzisun Yes exactly something similar, it just need a file to be present on the pod, it shouldn't be too difficult. I can try to come up with an example, lemme know if it is needed :)

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()

Expand All @@ -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``.
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

missing access_log_format

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Added :)

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,
Expand All @@ -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
Expand All @@ -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):
Expand Down Expand Up @@ -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:
Expand All @@ -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()
Expand Down
98 changes: 62 additions & 36 deletions python/kserve/kserve/protocol/rest/server.py
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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)
Expand All @@ -136,46 +137,71 @@ 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
# As indicated by the asgi-logger docs, we need to clear/unset
# any setting for uvicorn.access to avoid log duplicates.
logging.getLogger("uvicorn.access").handlers = []
app.add_middleware(
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

How this is different from the uvicorn.logging.AccessFormatter config?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

My understanding from

  • https://github.com/encode/uvicorn/blob/master/uvicorn/logging.py#L102
  • Implement gunicorn access log format encode/uvicorn#947 (comment)
    is that the access log formatter provided by uvicorn is not as powerful as other ones (like Gunicorn's). For example, in my use case I'd need to log request headers like User Agent to then be able to collect them in logstash and have a nice aggregation in Kibana, but other people may have different use cases. With the default access log formatter we get a limited format to use, meanwhile with asgi-logger we have way more possibilities available. It is sad that uvicorn didn't really decide what to do yet, but I suppose this is due to ASGI specs (see what's written in the github issue above). Note that if one wants to use and override uvicorn.logging.AccessFormatter they can via log_config_file.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The idea of the patch is to have several type of access logs:

  • By default, the one provided by the hardcoded config in the UvicornServer class, currently broken due to the missing handlers key in the python log config (so we don't have any log).
  • A custom, Uvicorn based config provided via external yaml/json file, to customize the Uvicorn's AccessFormatter and the other ones (for example, emitting Json etc..).
  • A custom, asgi-logger based logging format only for stdout (so limited but effective for the k8s use case imho) to get all the configs offered by Gunicorn (see https://docs.gunicorn.org/en/stable/settings.html#access-log-format).

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@elukey thanks for the explanation. We also have starlette metrics logging for printing the time spent on the endpoints, do you think we still need it with the uvicorn access logging?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@yuzisun I'd keep it for the moment, so we can figure out with the community what's needed and what not. I didn't check but starlette shouldn't have its own access log right? Everything should go through uvicorn, but the precise relationship between the two is not 100% clear to me (if you want to shed some clarity I'd be very happy). If you want we can create a documentation page somewhere with all the details discussed in here, so folks in the community can refer to it and report use cases etc..

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

And also third option, custom config file (note the Custom-cfg-file prefix in the access log formatter):

version: 1
disable_existing_loggers: False
formatters:
  default:
    (): 'uvicorn.logging.DefaultFormatter'
    fmt: '%(asctime)s %(levelprefix)-9s %(name)s -: %(message)s'
  access:
    (): 'uvicorn.logging.AccessFormatter'
    fmt: 'Custom-cfg-file - %(asctime)s %(levelprefix)-9s %(name)s -: %(client_addr)s - "%(request_line)s" %(status_code)s'
handlers:
  default:
    class: logging.StreamHandler
    formatter: default
    stream: ext://sys.stderr
  access:
    class: logging.StreamHandler
    formatter: access
    stream: ext://sys.stdout
loggers:
  uvicorn:
    level: INFO
    handlers:
      - default
  uvicorn.error:
    level: INFO
  uvicorn.access:
    level: INFO
    propagate: False
    handlers:
      - access

and logs:

2023-04-25 16:55:54.004 5476 root INFO [__call__():128] requestId: N.A., preprocess_ms: 0.015735626, explain_ms: 0, predict_ms: 0.00667572, 
postprocess_ms: 0.003099442                                                                                                                 
Custom-cfg-file - 2023-04-25 16:55:54,005 INFO:     uvicorn.access -: 127.0.0.1:35892 - "POST /v1/models/test%3Apredict HTTP/1.1" 200 OK    
2023-04-25 16:55:54.005 5476 root INFO [timing():48] kserve.io.kserve.protocol.rest.v1_endpoints.predict 0.0012352466583251953, ['http_statu
s:200', 'http_method:POST', 'time:wall']                                                                                                    
2023-04-25 16:55:54.005 5476 root INFO [timing():48] kserve.io.kserve.protocol.rest.v1_endpoints.predict 0.0012319999999998998, ['http_statu
s:200', 'http_method:POST', 'time:cpu']

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Almost! Sigh :(
When using asgi-logger I still see a little duplication:

127.0.0.1:41344 - - [25/Apr/2023:16:46:57 +0000] "POST /v1/models/test:predict HTTP/1.1" 200 - "-" "curl/7.74.0"
2023-04-25 16:46:57.906 5395 access INFO [log():67] 127.0.0.1:41344 - - [25/Apr/2023:16:46:57 +0000] "POST /v1/models/test:predict HTTP/1.1" 200 - "-" "curl/7.74.0"

In theory it shouldn't happen, maybe it is due how to asgi-logger sets the logger + propagation. Will investigate :)

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Ok should be fixed now, I added an extra setting for asgi-logger (to avoid propagation).

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Asked in Kludex/asgi-logger#6 some guidance about what I have written, maybe there is another/better way.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@yuzisun the change should be ready for a review, I checked and the output looks good now (no more repetitions).

AccessLoggerMiddleware, format=access_log_format)
# The asgi-logger settings don't set propagate to False,
# so we get duplicates if we don't set it explicitly.
logging.getLogger("access").propagate = False

self.server = _NoSignalUvicornServer(config=self.cfg)

def run_sync(self):
Expand Down
16 changes: 16 additions & 0 deletions python/kserve/poetry.lock
View file
Open in desktop

Some generated files are not rendered by default. Learn more about how customized files appear on GitHub.

6 changes: 6 additions & 0 deletions python/kserve/pyproject.toml
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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",
Expand All @@ -71,6 +74,9 @@ storage = [
"azure-identity",
"boto3",
]
logging = [
"asgi-logger"
]

[tool.poetry.group.test]
optional = true
Expand Down