FastAPI gunicorn add a logging timestamp

Question

I am using docker to run FastAPI https://fastapi.tiangolo.com/deployment/

tiangolo/uvicorn-gunicorn-fastapi:python3.7

the start.sh looks like:

exec gunicorn -k uvicorn.workers.UvicornWorker -c "$GUNICORN_CONF" "$APP_MODULE"

My docker log looks like without timestamps:

INFO:     123.123.123.123:48736 - "GET /wp-login.php HTTP/1.0" 404 Not Found
INFO:     123.123.123.123:48808 - "GET /robots.txt HTTP/1.0" 404 Not Found
INFO:     123.123.123.123:48810 - "GET / HTTP/1.0" 200 OK

It seems in the gunicorn_conf.py it uses

use_loglevel = os.getenv("LOG_LEVEL", "info")

How can easily and elegantly modify the logger format of INFO and ERROR with timestamps?

score 6 · Accepted Answer · answered Nov 11 '20 at 17:28

I believe the access_log_format option is currently ignored when using the uvicorn/gunicorn/fastapi combo. But that is mostly for editing what will be the %(message)s part of the log anyway. If you just want to add a timestamp you should be able to override the behavior of the loggers (though the defaults had a timestamp for me).

I put the example below in __init__.py right before the fastapi app was defined.

import logging, logging.config

LOG_CONFIG = {
    "version": 1,
    "disable_existing_loggers": True,
    "formatters": {"default": {"format": "%(asctime)s [%(process)s] %(levelname)s: %(message)s"}},
    "handlers": {
        "console": {
            "formatter": "default",
            "class": "logging.StreamHandler",
            "stream": "ext://sys.stdout",
            "level": "INFO",
        }
    },
    "root": {"handlers": ["console"], "level": "INFO"},
    "loggers": {
        "gunicorn": {"propagate": True},
        "gunicorn.access": {"propagate": True},
        "gunicorn.error": {"propagate": True},
        "uvicorn": {"propagate": True},
        "uvicorn.access": {"propagate": True},
        "uvicorn.error": {"propagate": True},
    },
}

logging.config.dictConfig(LOG_CONFIG)
logger = logging.getLogger(__name__)

Check out this answer for some good examples of the logging dict config.

If you actually want to edit the access log format of uvicorn I'm not sure there is an "official" way to do so. As of this writing they seem to have a hardcoded format in their code:

            if self.access_log:
                self.access_logger.info(
                    '%s - "%s %s HTTP/%s" %d',
                    get_client_addr(self.scope),
                    self.scope["method"],
                    get_path_with_query_string(self.scope),
                    self.scope["http_version"],
                    status_code,
                    extra={"status_code": status_code, "scope": self.scope},
                )

I am interested in having that print x-forwarded-for header values for example. One ugly way around that is to monkey patch uvicorn.protocols.utils.get_client_addr and pull whatever you want from the scope dict that gets passed to it. It happens to have the request headers. NOTE: This may have unintended consequences, particularly if the uvicorn folks change their code to use get_client_addr for anything more than printing a value.

Perhaps there is a way to do this with a custom worker class that uses a custom logger, but I haven't seen that done yet either.

score 2 · Answer 2 · answered May 07 '20 at 10:47

2

You should be able to modify the format of the access log using the access_log_format variable in your gunicorn_conf.py file. You can base your gunicorn_conf.py file this one used in the uvicorn-gunicorn docker image.

answered May 07 '20 at 10:47

pypae

639
6
16

@user670186 Could you provide your code sample on how you get logging to work with fastapi? I am using docker too but unable to get any logs. – Atihska Aug 20 '20 at 17:25
1

I don't think the `access_log_format` option currently works if you are using uvicorn/gunicorn btw: https://github.com/encode/uvicorn/issues/527 – totalhack Nov 11 '20 at 17:09

FastAPI gunicorn add a logging timestamp

2 Answers2