Implement gunicorn access log format #947

immerrr · 2021-02-03T15:44:54Z

This PR a very naïve and straightforward implementation of gunicorn access log format, which is currently ignored by uvicorn (see #527).

One notable omission is the WSGI variables: they should be rather straightforward to add, but I think it is important to agree on the approach first. And the approach goes as follows:

It puts the gunicorn log object all the way through to the RequestResponseCycle, and it unrolls gunicorn_log.access function

https://github.com/benoitc/gunicorn/blob/master/gunicorn/glogging.py#L331-L351

so that it is not necessary to recreate all the gunicorn primitives, like gunicorn.http.wsgi.Response and gunicorn.http.message.Request.

The timing is implemented via time.monotonic so that it works well w.r.t. DST transitions and leap seconds. The timing values are added to the asgi scope. And obviously, to be able to measure the timing, the logging had to be moved to the end of response processing.

~~Default uvicorn logging is kept intact to minimize the scope of this PR, and is only disabled when gunicorn_log is passed by gunicorn worker classes to avoid duplication.~~

GunicornSafeAtoms does several things:

it provides the values for gunicorn log formatter in the most performant way I could imagine
it aggregates response body size from ASGI messages
and it does what gunicorn.glogging.SafeAtoms does to provide fallbacks for missing values

Edit by @Kludex : closes #773, closes #527

immerrr · 2021-02-22T17:19:52Z

ref #773, ref #527, ref #389

immerrr · 2021-04-15T13:28:10Z

@euri10 is there anything i can do to help get this in? or at least to help to get the discussion started, as i would assume there's a decision to be taken w.r.t. the approach.

euri10 · 2021-05-28T07:54:42Z

@euri10 is there anything i can do to help get this in? or at least to help to get the discussion started, as i would assume there's a decision to be taken w.r.t. the approach.

back here from the issue discussion, I quickly looked on the PR, I can't pronounce on the gunicorn side of things, however what is pretty clear to me reading the PR is that the implementation is adding keys to the scope that are not in the asgi specification. (https://asgi.readthedocs.io/en/latest/specs/www.html#http-connection-scope).

I tried to dig a little in asgiref and didn't find a definitive answer as to whether or not it's "allowed", I would tend to say it is not,
see django/asgiref#178 and also django/asgiref#112 for interesting points.

It would be better to have an implementation that does not violate the spec, if not possible this would need a discussion about that beforehand, I cant remember where but I think this was discussed before and frowned upon, maybe @tomchristie remembers.

chbndrhnns · 2021-05-28T08:18:34Z

From what I see, these are the added keys:

request_start_time
request_end_time

Would the extensions approach from the spec work here?

There are times when protocol servers may want to provide server-specific extensions outside of a core ASGI protocol specification, or when a change to a specification is being trialled before being rolled in.
For this use case, we define a common pattern for extensions - named additions to a protocol specification that are optional but that, if provided by the server and understood by the application, can be used to get more functionality.
This is achieved via an extensions entry in the scope dictionary, which is itself a dict. Extensions have a Unicode string name that is agreed upon between servers and applications.

euri10 · 2021-05-28T08:28:06Z

Would the extensions approach from the spec work here?

I think yes that would be the most sensible thing to do to move things forward.

immerrr · 2021-05-28T11:19:26Z

Heyy, now we're talking (literally), thanks!

I'll update the PR to use the extensions approach, or if you see another way to store the start/end timestamps within the scope of the request, i'm open to other ideas 👍

immerrr · 2021-05-31T14:13:16Z

@euri10 i have updated the code to use scope['extensions']['uvicorn_request_duration'] to store the timestamps, but like i said previously, if there's a better place to put it, just let me know.

euri10 · 2021-05-31T14:19:34Z

you can use ./scripts/lint if you have linter issues, not sure if you saw it

Kludex · 2021-06-12T16:35:45Z

I really want this feature, but I'm not sure this is the way to go.

Some points on my mind:

I don't think we should have any reference to gunicorn on our source code besides the worker.
I think uvicorn should have its way to customize the logger format, which for convenience it's a good idea to match gunicorn's way.
I don't feel comfortable adding an extension on the ASGI scope just for the time, I think we can achieve that with a single variable, even if that variable needs to be sent to another object (cycle). 🤔

Those are my concerns at first glance. What do you think? @euri10 @immerrr

immerrr · 2021-06-13T09:10:15Z

I agree with the concerns listed above, as i mentioned earlier, it was done the way it was done to minimize the scope of change and to let the uvicorn team decide the fate of uvicorn's logging and formatting at your convenience.

If I'm reading this correctly, the requested changes are:

move tracking of request-response timing to a variable
turn the gunicorn logging format handling into uvicorn's native logging formatting

If those were to happen, would it make this PR "the way to go"?

Kludex · 2021-06-13T09:48:11Z

If I'm reading this correctly, the requested changes are:

move tracking of request-response timing to a variable

turn the gunicorn logging format handling into uvicorn's native logging formatting

If those were to happen, would it make this PR "the way to go"?

Yeah, but also adding the --access-log-format on the CLI command (just being explicit here).

Besides if we can get the answer to "is it possible to read the gunicorns --access-log-format in the UvicornWorker?" it would be cool.

EDIT: For the last question, maybe self.cfg.access_log_format? Not sure...

immerrr · 2021-06-13T09:55:59Z

Not sure if i understand the last question correctly, but i think the format is available as

self.log.cfg.access_log_format

On the following line:
https://github.com/encode/uvicorn/pull/947/files#diff-7c8a9d71c98f0ed83c32a88a1b7e777ef85776c98869045d24c74e3f7714494aR41

And I am making use of it in this PR.

Kludex · 2021-06-13T10:11:15Z

Ah, yeah! Perfect.

So, in summary:

Store request-response timing in a variable (being an attribute of RequestResponseCycle?).
As you said: "turn the gunicorn logging format handling into uvicorn's native logging formatting". This is for convenience, my point is that we should have our formatting rules.
Create the --access-log-format on uvicorn, and on the UvicornWorker send the "access_log_format": self.log.cfg.access_log_format instead of "gunicorn_log": self.log. In case we decide to not match the rules (exactly the same), we can create a converter on the UvicornWorker that will aim to match the gunicorn with uvicorn rules. But with this idea present, we can make use of --access-log-format either from uvicorn or gunicorn on uvicorn.

Does it make sense? 🤔

immerrr · 2021-06-13T10:19:49Z

It can be made to work.

It's been a while since I wrote this, but i think the default uvicorn logging uses colours, whereas gunicorn doesn't support that, so we either need to disable colouring (break backward compat), or agree that colouring is not possible with custom log formats, or start bending gunicorn formatting features right away :)

Kludex · 2021-06-13T11:30:04Z

It's been a while since I wrote this, but i think the default uvicorn logging uses colours, whereas gunicorn doesn't support that, so we either need to disable colouring (break backward compat), or agree that colouring is not possible with custom log formats, or start bending gunicorn formatting features right away :)

@euri10 thoughts?

immerrr · 2021-06-13T16:19:41Z

Just started implementing the requested changes, and ran into another point of contention/agreement. The existing uvicorn logging is done when response is started, whereas gunicorn logging is done when the response is ended (to be able to provide all response headers and total request-response duration time).

Do you want to move the default uvicorn logging to the end of the cycle? Or perhaps do the access log before or after response depending on whether or not access-log-format was passed?

This was one more question I was trying to avoid with this PR by keeping the gunicorn logging format gunicorn-specific :)

Kludex · 2021-06-13T16:38:56Z

Do you want to move the default uvicorn logging to the end of the cycle? Or perhaps do the access log before or after response depending on whether or not access-log-format was passed?

IMHO, we can move it. I also think that makes more sense to move it. But maybe we should take a look at how hypercorn does it or gunicorn itself with their main workers 🤔

immerrr · 2021-06-13T16:42:23Z

Oh, and another thing that should work right now and will not with the new suggested approach is the handling of gunicorn's --access-logfile. Current implementation takes the pre-configured logger object from gunicorn with all its handlers

uvicorn/uvicorn/protocols/http/httptools_impl.py

Lines 534 to 536 in 4e7da54

    
           self.gunicorn_log.access_log.info( 
        
               self.gunicorn_log.cfg.access_log_format, 
        
               self.gunicorn_atoms,

~~And if the new version only uses the access log format, this behaviour will have to be reproduced later on.~~

EDIT: nvm, log file and levels are copied in workers.py

immerrr · 2021-06-14T10:26:23Z

I have added a minimal test to exercise gunicorn worker logging, because it is true that previously there were no tests for this.

immerrr · 2021-06-21T16:36:50Z

I have updated the branch according to the feedback, it's almost there:

the old default logging format is kept as is
the --access-log-format parameter still needs to be added to uvicorn itself

staubina · 2023-01-04T16:48:57Z

Has this PR and potential fix died off? Does anyone have any suggestions here using just Uvicorn?

immerrr · 2023-01-04T17:12:03Z

I have been reluctant to update the PR, as it was repeatedly stated that this was not a priority, and the latest review requested sizeable changes, which I have been unable to expend for a work that was going to spend the next X months in the "low priority" bucket.

If my understanding is incorrect or things have changed and now there is tangible interest in this, I can give the PR a push.

staubina · 2023-01-04T18:59:53Z

I appreciate the effort you have put in here. I was looking to resolve an issue with passing on more detailed logs with access information in a JSON format and stumbled into this PR. Still looking to see if this is something I will need or if I just need to expand my Custom Format approach and add a middleware like asgi-logger to get more details about the state.

The benefit of this approach for users would be not need a separate package to format the logs.

I think in my case, I might still need the Middleware to get that data and pass it on to the JSON log formatter.

tl;dr

I think this is not what I need to resolve my issue now that I have reviewed some of the other threads linked, like: #859

br3ndonland · 2023-01-05T02:41:09Z

I have been reluctant to update the PR, as it was repeatedly stated that this was not a priority, and the latest review requested sizeable changes, which I have been unable to expend for a work that was going to spend the next X months in the "low priority" bucket.

If my understanding is incorrect or things have changed and now there is tangible interest in this, I can give the PR a push.

No problem @immerrr, that's understandable! I'm in the same boat myself - just haven't really been able to put the time in. It's one of those things that maintainers say isn't a priority, but then people keep asking about it, so... 🤷

Honestly, as a maintainer myself, I'm not always sure what the priorities are. Most people just work on stuff they need, or on highly-requested features. The Gunicorn piece has always been particularly confusing to me, because the Uvicorn docs recommend deploying with Gunicorn, but we don't test the Gunicorn worker, and we don't integrate with Gunicorn's access log format, so we don't actually provide much support for Gunicorn. I built another project, inboard, that has a more thorough integration with Gunicorn, and lots of Gunicorn testing with and without Docker, so that's how I approached it. I might try implementing the Gunicorn access log format in inboard, then I could come back here with some more ideas.

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. Fixes: kserve#2778 Signed-off-by: Luca Toscano <[email protected]>

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 make CI happy I had to move the python3.7-slim images to python3.8-slim. Fixes: kserve#2778 Signed-off-by: Luca Toscano <[email protected]>

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 make CI happy I had to move the python3.7-slim images to python3.8-slim. Since Python 3.7 is going to be EOLed in a couple of months, it seems good to move the minimum compatibility to Python 3.8. Fixes: kserve#2778 Signed-off-by: Luca Toscano <[email protected]>

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

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: #2778 Signed-off-by: Luca Toscano <[email protected]>

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

immerrr mentioned this pull request Feb 3, 2021

Honor gunicorn access log format #527

Open

euri10 added enhancement logging workers/gunicorn labels May 28, 2021

immerrr force-pushed the implement-gunicorn-access-log-format branch from ae9903a to 0d89de0 Compare May 31, 2021 14:12

immerrr force-pushed the implement-gunicorn-access-log-format branch from 0d89de0 to 4e7da54 Compare May 31, 2021 14:43

immerrr force-pushed the implement-gunicorn-access-log-format branch from 4e7da54 to f29f09e Compare June 14, 2021 10:24

immerrr force-pushed the implement-gunicorn-access-log-format branch 2 times, most recently from 36a16d9 to b69f060 Compare June 20, 2021 06:38

euri10 mentioned this pull request Jun 21, 2021

Remove scope from access log when using json logging formatter #859

Merged

Kludex modified the milestones: Version 0.20.0, Version 0.21.0 Oct 29, 2022

jan-janssen referenced this pull request in materialsproject/emmet Nov 7, 2022

switch to uvicorn-tschaume and pip-tools

9131828

jan-janssen mentioned this pull request Nov 8, 2022

Add uvicorn-tschaume conda-forge/staged-recipes#21051

Closed

10 tasks

Kludex mentioned this pull request Dec 16, 2022

Version 0.22.0 #1808

Closed

16 tasks

Kludex modified the milestones: Version 0.21.0, Version 0.22.0 Mar 22, 2023

elukey mentioned this pull request Apr 1, 2023

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

Merged

7 tasks

elukey mentioned this pull request May 18, 2023

Add a KServe module level logger kserve/kserve#2884

Merged

4 tasks

br3ndonland mentioned this pull request Jun 4, 2023

Test workers #1995

Closed

3 tasks

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Implement gunicorn access log format #947

Implement gunicorn access log format #947

immerrr commented Feb 3, 2021 •

edited

Loading

immerrr commented Feb 22, 2021

immerrr commented Apr 15, 2021

euri10 commented May 28, 2021

chbndrhnns commented May 28, 2021 •

edited

Loading

euri10 commented May 28, 2021

immerrr commented May 28, 2021

immerrr commented May 31, 2021

euri10 commented May 31, 2021

Kludex commented Jun 12, 2021

immerrr commented Jun 13, 2021

Kludex commented Jun 13, 2021 •

edited

Loading

immerrr commented Jun 13, 2021

Kludex commented Jun 13, 2021 •

edited

Loading

immerrr commented Jun 13, 2021

Kludex commented Jun 13, 2021

immerrr commented Jun 13, 2021

Kludex commented Jun 13, 2021

immerrr commented Jun 13, 2021 •

edited

Loading

immerrr commented Jun 14, 2021

immerrr commented Jun 21, 2021

staubina commented Jan 4, 2023

immerrr commented Jan 4, 2023

staubina commented Jan 4, 2023 •

edited

Loading

br3ndonland commented Jan 5, 2023

Implement gunicorn access log format #947

Are you sure you want to change the base?

Implement gunicorn access log format #947

Conversation

immerrr commented Feb 3, 2021 • edited Loading

immerrr commented Feb 22, 2021

immerrr commented Apr 15, 2021

euri10 commented May 28, 2021

chbndrhnns commented May 28, 2021 • edited Loading

euri10 commented May 28, 2021

immerrr commented May 28, 2021

immerrr commented May 31, 2021

euri10 commented May 31, 2021

Kludex commented Jun 12, 2021

immerrr commented Jun 13, 2021

Kludex commented Jun 13, 2021 • edited Loading

immerrr commented Jun 13, 2021

Kludex commented Jun 13, 2021 • edited Loading

immerrr commented Jun 13, 2021

Kludex commented Jun 13, 2021

immerrr commented Jun 13, 2021

Kludex commented Jun 13, 2021

immerrr commented Jun 13, 2021 • edited Loading

immerrr commented Jun 14, 2021

immerrr commented Jun 21, 2021

staubina commented Jan 4, 2023

immerrr commented Jan 4, 2023

staubina commented Jan 4, 2023 • edited Loading

br3ndonland commented Jan 5, 2023

immerrr commented Feb 3, 2021 •

edited

Loading

chbndrhnns commented May 28, 2021 •

edited

Loading

Kludex commented Jun 13, 2021 •

edited

Loading

Kludex commented Jun 13, 2021 •

edited

Loading

immerrr commented Jun 13, 2021 •

edited

Loading

staubina commented Jan 4, 2023 •

edited

Loading