Implement gunicorn access log format

[immerrr]

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]

ref #773, ref #527, ref #389

[immerrr]

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

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

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]

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]

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]

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

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

[Kludex]

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]

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]

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]

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]

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]

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]

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]

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]

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]

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]

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

[immerrr]

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]

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

[immerrr]

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]

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]

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.