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

elukey · 2023-03-31T15:46:59Z

What this PR does / why we need it:
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:

encode/uvicorn#947 (comment)

It seems the only way forward to allow a decent customization
of a vital sign like the access log.

The main issue is that asgi-logger requires Python 3.8, so the dependency is added
as extra to Poetry's config.

Which issue(s) this PR fixes (optional, in fixes #<issue number>(, fixes #<issue_number>, ...) format, will close the issue(s) when PR gets merged):
Fixes: #2778

Type of changes
Please delete options that are not relevant.

Bug fix (non-breaking change which fixes an issue)
New feature (non-breaking change which adds functionality)
Breaking change (fix or feature that would cause existing functionality to not work as expected)
This change requires a documentation update

Feature/Issue validation/testing:

Please describe the tests that you ran to verify your changes and relevent result summary. Provide instructions so it can be reproduced.
Please also list any relevant details for your test configuration.

I tried to use the following snippet:

import kserve
from typing import Dict
import argparse
import logging

logger = logging.getLogger()

class CustomPredictor(kserve.Model):
    def __init__(self, name: str):
        super().__init__(name)
        self.name = name
        self.load()

    def load(self):
        self.ready = True

    def predict(self, request: Dict, headers: Dict) -> Dict:
        return {"predictions": True}

if __name__ == "__main__":
    model = CustomPredictor("test")
    kserve.ModelServer(workers=1, enable_latency_logging=False, log_config_file="/tmp/test1.yaml").start([model])

I saved in /tmp/test1.yaml a logging config, and ran the above script. I was able to observe access logs following the configuration that I passed in the file.

Moreover, if I run the ModelServer class without log_config_file, I see access logs as expected (as opposed to now that I don't see them, IIUC due to the wrong default config hardcoded in the UvicornServer's class).

I also tried the new access_log_format parameter, that works as expected (namely I am able to use something like '%(h)s %(l)s %(u)s %(t)s "%(r)s" %(s)s %(b)s "%(f)s" "%(a)s"' to customize the access logs:

127.0.0.1:48276 - - [01/Apr/2023:12:02:07 +0000] "GET /v1/ HTTP/1.1" 404 - "-" "curl/7.74.0"

For the moment the support is only for the asgi-logger's default, namely stdout, but we can surely add an option to log to disk or similar (but not sure if KServe users really need it).

Logs

Special notes for your reviewer:

Please confirm that if this PR changes any image versions, then that's the sole change this PR makes.

Checklist:

Have you added unit/e2e tests that prove your fix is effective or that this feature works?
No idea if unit tests are needed in this case, lemme know if you fell differently.
Has code been commented, particularly in hard-to-understand areas?
Have you made corresponding changes to the documentation?
Not sure if any are needed.

Release note:

Fix the default Uvicorn's log configuration and allow to override it using a custom json or yaml file. Add an experimental parameter to the model server class to support gunicorn's access_log_format config.

elukey · 2023-03-31T15:48:19Z

Hi folks! Still need to figure out how to test this change, but early feedback is really good :)

elukey · 2023-04-01T08:15:17Z

Added a simple test case to the PR's description, should be ready for a review :)

elukey · 2023-04-01T15:47:46Z

lovely, asgi-logger requires python 3.8+, and of course some tests in CI depend on 3.7. Not sure what's the best forward, lemme know :)

elukey · 2023-04-03T09:11:07Z

Some tests are still failing, IIUC due to the aix360 package that depends on tensorflow==1.14 that in turn is not compatible with Python 3.8 afaics..

elukey · 2023-04-03T09:19:03Z

Summary for the reviewers (based on my understanding of the code):

It seems that the UvicornServer's default logging config is not working, so Uvicorn's access logs are not available in Kserve pods. The issue should be fixable simply replacing "rest" with "handlers" in the logging config.
Uvicorn's config seems to support passing the path of a yaml or json file (instead of a dict) to change the logging configuration. I added the code to support it, that seems working nicely.
The main issue of the above is that I cannot change the access log format, for example to dump some request headers like User Agent etc.. From Implement gunicorn access log format encode/uvicorn#947 (comment) the way forward seems to use asgi-logger as Uvicorn Middleware, but for the moment I think it supports only printing to stdout (should be fine for most of the use cases in theory). The main drawback is that asgi-logger runs only on python3.8+, and this breaks CI. When I tried to upgrade all the docker images to python3.8-slim I found a problem with the aix360 package, that supports on tensorflow==1.14 and that in turn runs only on Python up to 3.7 (lovely).

If you want I can try to split the pull request into two steps:

Fix/Customize access logging (so users will see something, but they will not be able to configure the access log format like they do with gunicorn for example).
Work on the asgi-logger etc.. to figure out how to best add it to Kserve.

Lemme know :)

elukey · 2023-04-03T13:36:39Z

Created Trusted-AI/AIX360#172 to see if we can get a bump in the aix360's version.
Python 3.7 is going to be EOLed in a couple of months time, so if AIX360 is not getting updated I'd think about excluding it from CI.

rachitchauhan43 · 2023-04-05T03:13:54Z

@elukey : What about model_server logging_format ? Can you include changes to allow formatting that as well ?
https://github.com/kserve/kserve/blob/master/python/kserve/kserve/model_server.py#L61

This PR has no changes #2762 and has been closed. If, we do not see the traction on this one, it would be great to get the changes corresponding to influence the logger format too via this PR itself.

elukey · 2023-04-05T06:29:41Z

@elukey : What about model_server logging_format ? Can you include changes to allow formatting that as well ? https://github.com/kserve/kserve/blob/master/python/kserve/kserve/model_server.py#L61

This PR has no changes #2762 and has been closed. If, we do not see the traction on this one, it would be great to get the changes corresponding to influence the logger format too via this PR itself.

Hi! I think that we should keep the two things separated, my PR is related to Uvicorn's logging, meanwhile what you point out is related to the model server's logging. It is equally important but my PR is already big and I'd like to avoid adding things, unless the upstream devs suggests so. Could you open a PR like #2762 with the required changes?

elukey · 2023-04-06T13:03:08Z

@yuzisun @theofpa Hi! If you have time could you give me some feedback about this change? Thanks a lot in advance :)

yuzisun · 2023-04-08T13:41:03Z

@yuzisun @theofpa Hi! If you have time could you give me some feedback about this change? Thanks a lot in advance :)

Sorry @elukey you may need to resolve the conflict as we have now migrated to poetry for python dependency resolution.

elukey · 2023-04-08T13:56:25Z

@yuzisun @theofpa Hi! If you have time could you give me some feedback about this change? Thanks a lot in advance :)

Sorry @elukey you may need to resolve the conflict as we have now migrated to poetry for python dependency resolution.

Thanks a lot for the feedback, I have pushed another version of the pull request, but the asgi-logger problem remains, namely that it requires python 3.8.. One possible workaround is to add an extra (IIRC it is called in that way) for kserve to install it only if requested (something like pip install kserve[extra-logging] or similar). Do you have any preference? The access log customization could be an "experimental" feature and CI could keep working with Python 3.7 for the time being.

elukey · 2023-04-08T14:07:57Z

Added the asgi-logger dependency as extra to poetry's config, this should avoid to move to python3.8 in all docker images :)

elukey · 2023-04-08T16:01:46Z

@yuzisun should be ready for a review :)

elukey · 2023-04-11T08:04:50Z

Forgot to run poetry lock, this is the result:

The current project's Python requirement (>=3.7.1,<3.11) is not compatible with some of the required packages Python requirement:
  - asgi-logger requires Python >=3.8,<4.0, so it will not be satisfied for Python >=3.7.1,<3.8

Because asgi-logger (0.1.0) requires Python >=3.8,<4.0
 and no versions of asgi-logger match >0.1.0,<0.2.0, asgi-logger is forbidden.
So, because kserve depends on asgi-logger (^0.1.0), version solving failed.

  • Check your dependencies Python requirement: The Python requirement can be specified via the `python` or `markers` properties
    
    For asgi-logger, a possible solution would be to set the `python` property to ">=3.8,<3.11"

elukey · 2023-04-11T09:22:53Z

Found a workaround and re-tested everything, lemme know your thoughts :)

elukey · 2023-04-16T10:15:22Z

@yuzisun Hi! Do you think that the PR could be reviewed? Let me know if it is missing anything major, it would be great if it was included in 0.11 (to get access log working again asap :).

yuzisun · 2023-04-24T00:10:10Z

python/kserve/kserve/model_server.py

@@ -76,6 +80,7 @@ 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``.


missing access_log_format

yuzisun · 2023-04-24T00:12:40Z

python/kserve/kserve/protocol/rest/server.py

+        if access_log_format:
+            from asgi_logger import AccessLoggerMiddleware
+            logging.getLogger("uvicorn.access").handlers = []
+            app.add_middleware(


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

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.

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

@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?

@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..

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']

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

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

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

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

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: encode/uvicorn#947 (comment) 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: kserve#2778 Signed-off-by: Luca Toscano <[email protected]>

yuzisun · 2023-05-03T10:19:28Z

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,


@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

@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 :)

yuzisun · 2023-05-05T11:42:59Z

Looks goods! Thanks @elukey !

/lgtm
/approve

kserve-oss-bot · 2023-05-05T11:43:05Z

[APPROVALNOTIFIER] This PR is APPROVED

This pull-request has been approved by: elukey, yuzisun

The full list of commands accepted by this bot can be found here.

The pull request process is described here

Needs approval from an approver in each of these files:

~~python/kserve/OWNERS~~ [yuzisun]

Approvers can indicate their approval by writing /approve in a comment
Approvers can cancel approval by writing /approve cancel in a comment

…rve#2782) 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: encode/uvicorn#947 (comment) 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: kserve#2778 Signed-off-by: Luca Toscano <[email protected]> Signed-off-by: iamlovingit <[email protected]>

kserve-oss-bot requested review from sukumargaonkar and theofpa March 31, 2023 15:47

elukey force-pushed the master branch 2 times, most recently from 396970e to e0e7b31 Compare March 31, 2023 16:09

elukey force-pushed the master branch 3 times, most recently from 4685e4d to 3044b05 Compare April 1, 2023 15:04

elukey force-pushed the master branch 2 times, most recently from 73cd31e to 8c8a8f9 Compare April 3, 2023 08:21

elukey force-pushed the master branch from 8c8a8f9 to 38a8ade Compare April 4, 2023 15:06

elukey force-pushed the master branch from 38a8ade to 3ce26c3 Compare April 8, 2023 13:50

elukey force-pushed the master branch 2 times, most recently from 536fa3e to 7f7f28c Compare April 8, 2023 14:06

elukey force-pushed the master branch 2 times, most recently from 9810d8f to ef9d13b Compare April 11, 2023 09:11

yuzisun reviewed Apr 24, 2023

View reviewed changes

elukey force-pushed the master branch from ef9d13b to fc41102 Compare April 24, 2023 06:24

This was referenced Apr 25, 2023

Update documentation for access log changes kserve/website#254

Closed

docs: add access log documentation for custom model predictors (#254) kserve/website#255

Merged

elukey force-pushed the master branch from fc41102 to 0da4651 Compare April 25, 2023 16:34

elukey force-pushed the master branch from 0da4651 to 42e058d Compare April 26, 2023 08:01

elukey mentioned this pull request Apr 26, 2023

Instructions to overwrite uvicorn logger Kludex/asgi-logger#6

Open

yuzisun reviewed May 3, 2023

View reviewed changes

kserve-oss-bot assigned yuzisun May 5, 2023

kserve-oss-bot added the lgtm label May 5, 2023

kserve-oss-bot added the approved label May 5, 2023

yuzisun merged commit bde4f4c into kserve:master May 5, 2023

elukey mentioned this pull request May 11, 2023

Automatic escape of header fields Kludex/asgi-logger#40

Open

elukey mentioned this pull request May 18, 2023

Add a KServe module level logger #2884

Merged

4 tasks

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

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

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

elukey commented Mar 31, 2023 •

edited

Loading

elukey commented Mar 31, 2023

elukey commented Apr 1, 2023

elukey commented Apr 1, 2023

elukey commented Apr 3, 2023

elukey commented Apr 3, 2023

elukey commented Apr 3, 2023 •

edited

Loading

rachitchauhan43 commented Apr 5, 2023 •

edited

Loading

elukey commented Apr 5, 2023

elukey commented Apr 6, 2023

yuzisun commented Apr 8, 2023

elukey commented Apr 8, 2023

elukey commented Apr 8, 2023

elukey commented Apr 8, 2023

elukey commented Apr 11, 2023

elukey commented Apr 11, 2023

elukey commented Apr 16, 2023

yuzisun Apr 24, 2023

elukey Apr 24, 2023

yuzisun Apr 24, 2023

elukey Apr 24, 2023

elukey Apr 24, 2023

yuzisun Apr 24, 2023

elukey Apr 24, 2023

elukey Apr 25, 2023

elukey Apr 26, 2023

elukey Apr 26, 2023

elukey Apr 26, 2023

elukey Apr 27, 2023

yuzisun May 3, 2023

elukey May 4, 2023

yuzisun commented May 5, 2023

kserve-oss-bot commented May 5, 2023

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

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

Conversation

elukey commented Mar 31, 2023 • edited Loading

elukey commented Mar 31, 2023

elukey commented Apr 1, 2023

elukey commented Apr 1, 2023

elukey commented Apr 3, 2023

elukey commented Apr 3, 2023

elukey commented Apr 3, 2023 • edited Loading

rachitchauhan43 commented Apr 5, 2023 • edited Loading

elukey commented Apr 5, 2023

elukey commented Apr 6, 2023

yuzisun commented Apr 8, 2023

elukey commented Apr 8, 2023

elukey commented Apr 8, 2023

elukey commented Apr 8, 2023

elukey commented Apr 11, 2023

elukey commented Apr 11, 2023

elukey commented Apr 16, 2023

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

yuzisun commented May 5, 2023

kserve-oss-bot commented May 5, 2023

elukey commented Mar 31, 2023 •

edited

Loading

elukey commented Apr 3, 2023 •

edited

Loading

rachitchauhan43 commented Apr 5, 2023 •

edited

Loading