jwhitlock
commented
3 years ago I worked on this yesterday, and found a few surprising things. In summary, my new strategy is:
- Reformat uvicorn logging as mozlog using JsonLogFormatter
- Add extra logging data to the Request object as needed, via request.state
- Extend JsonLogFormatter.convert_record to make clean JSON
- See if plain Python logging (instead of structlog) is sufficient for scripts like
ctms/bin/client_credentials.py
FastAPI flexibly supports async and sync Python, except for middleware, which must be async. It supports this by running the sync code, like our dependency injection functions and endpoint functions, in a thread pool. This messes with both methods that structlog uses for global log state - thread local context and context variables. Maybe if all the code was async, we could cleanly use contextvars, but I don't think it is a good time to tackle that. That leaves us with the traditional structlog binding, and I'm not sure it would be worth it at this time for the web app.
I found a sample configuration for formatting uvicorn logs with structlog for JSON logs. This technique also worked with the mozlog formatter from https://github.com/mozilla-services/python-dockerflow. The Request is passed as context to the logger, and it has a state element that can be used for arbitrary data. The FastAPI docs show using it for database initialization in a middleware. I was able to use it to save the client ID from OAuth2 initialization. There is other useful data in the Request object, such as the request path and the requester's IP. There is also data that isn't useful, like a reference to the app and the endpoint function, which show up in the JSON format and make it more challenging to work with. There is a .convert_record function that can be extended to clean up the data and make it more useful.
Update: It feels better to say "I learned a lot of interesting things and have a new strategy", as opposed to "I spent my day trying a bunch of stuff that didn't work, and now have 100 open tabs to triage, and a bunch of VIM windows and terminal sessions to close."
An optional recommendation of https://github.com/mozilla-services/dockerflow is to log to
stdoutin the mozlog json schema.Currently, it appears uvicorn or gunicorn is outputting a log entry per request, and FastAPI doesn't do any logging itself. The changes would be:
I'm a fan of structlog, which has a compatible style with mozlog, as well as a friendlier logging format for development. I've used it on MLS, see log.py.
Related: