logs with FastAPI and Uvicorn

[Jackovic]

Hello,

Thanks for FastAPI, easy to use in my Python projects !
However, I have an issue with logs.
In my Python project, I use :

app = FastAPI()
uvicorn.run(app, host="0.0.0.0", port=8000)

And when i test my app I get in the console :

INFO: Started server process...
INFO: Waiting for application startup
INFO: Application startup complete.
INFO: Uvicorn running on http://0.0.0.0:8000 (Press ...)
INFO: 127.0.0.1:41668 - "GET /app/?type=env HTTP/1.1" 304 Not Modified
...

This 5 lines are exactly what I expected.
Now I want to have access to these logs because I want to re-format them.

So, if i am right, I have a logger managing :

INFO: Started server process...
INFO: Waiting for application startup
INFO: Application startup complete.
INFO: Uvicorn running on http://0.0.0.0:8000 (Press ...)

and a logger managing :

INFO: 127.0.0.1:41668 - "GET /app/?type=env HTTP/1.1" 304 Not Modified

Is it right ?

I have no problem to get access to the first, I can use :

log1 = logging.getLogger("uvicorn.error")

and then change the formatter,
but, for the second I was expecting that :

log2 = logging.getLogger("uvicorn.access")

will do the same, but I am unable to change the formatter for the log :

INFO: 127.0.0.1:41668 - "GET /app/?type=env HTTP/1.1" 304 Not Modified

How I can do that in my Python 3.7 script with FastAPI 0.52.0 and Uvicorn 0.11.3 ?
Thank you.

[dbanty]

This is probably a better question for uvicorn, but I'll take a stab at answering it. Full disclaimer, this is very likely not the "right way" to do this in uvicorn but...

uvicorn.run takes in a log_config keyword arg which lets you configure the loggers. There is a default log config, you could grab that and override what you need to if the case is simple enough.

log_config = uvicorn.config.LOGGING_CONFIG
log_config["formatters"]["access"]["fmt"] = "%(asctime)s - %(levelname)s - %(message)s"
uvicorn.run(app, log_config=log_config)

The problem with just getting the logger and configuring it seems to be that when you call uvicorn.run, uvicorn applies their logger handlers/formatters. If this is after you tried to apply your own handler, yours would get overridden.

You could also try configuring your logging handlers after FastAPI starts up? Might have better luck as uvicorn won't be overriding at that point.

@app.on_event("startup")
async def startup_event():
    logger = logging.getLogger("uvicorn.access")
    handler = logging.StreamHandler()
    handler.setFormatter(logging.Formatter("%(asctime)s - %(levelname)s - %(message)s"))
    logger.addHandler(handler)

The way I have that adds a new handler, it won't override the existing internal one. If that's okay for you it might be a better approach.

[Jackovic]

Doing :

log_config = uvicorn.config.LOGGING_CONFIG
log_config["formatters"]["access"]["fmt"] = "%(asctime)s - %(levelname)s - %(message)s"
log_config["formatters"]["default"]["fmt"] = "%(asctime)s - %(levelname)s - %(message)s"
uvicorn.run(app, log_config=log_config)

is exactly what I was looking for !
Thank you dbanty.

[dbanty]

@Jackovic great to hear! If you're all set then go ahead and close the issue. Might be worth asking in https://github.com/encode/uvicorn if they would add some recommendations about configuring logging to their documentation. Might be similar to encode/uvicorn#491 which looks a bit stale.

[mandarvaze]

@dbanty using @app.on_event("startup") as suggested by you above worked. Thanks.
But I lose the colorized output :( - Any suggestions on how to keep that ?

I also seem to be seeing two entries. One colorized - without the timestamp, in uvicorn's default formatting (access log) and next line is in my format, with timestamp, no colors.

I think there are multiple "handlers", and I'm overriding just one. How to debug this further ?

[randomunrandom]

I recently came across the same issue and here's how I solve it:

1. "double outputs" - after looking at uvicorn.config.LOGGING_CONFIG I saw that it defines handlers for root logger and for it's own loggers. But python logging system is hierarchical - if you define handlers for "a" logger, you can log to "a.b" and get the same handlers. And when I logged to my logger it must have gone up to root logger and get double logged. To solve this I removed root logger from uvicorn configuration, like this:

uvicorn_log_config = uvicorn.config.LOGGING_CONFIG
del uvicorn_log_config["loggers"][""]
uvicorn.run(app, log_config=uvicorn_log_config)

2. "colored output" - I looked at uvicon source code and found logging.py file with class ColourizedFormatter. After looking at it's code I found out that it colorizes all levelprefix with custom click function. So I changed my formater instance to uvicorn.logging.ColourizedFormatter and levelname to levelprefix like so:

console_formatter = uvicorn.logging.ColourizedFormatter(
    "{levelprefix:<8} @ {name} : {message}",
    style="{",
    use_colors=True
)

Hope this helps

[invokermain]

@dbanty thanks so much, after an hour of trying to understand Uvicorn's strange logging behaviours you just made it all very clear.

[dorinclisu]

There is another potential solution if you want to unify the uvicorn logging with your actual endpoints logging (a good idea in my opinion), by passing None to log_config. This will essentially stop uvicorn from patching the existing logging configuration:

...
logging.basicConfig(format='{levelname:7} {message}', style='{', level=logging.INFO)
uvicorn.run(app, log_config=None)

Of course the default uvicorn coloring is lost but nothing stops you from setting a custom formatter in a global, transparent way that can also handle colors.

[KaranTrivedi]

Is there a way to capture the output of exception/failure dumps? I notice that if there is a syntax error, it doesnt go to a file, it get thrown into journalctl, I am running the start.py containing the uvicorn.run() command with a service file.

[gauravkoradiya]

There is another potential solution if you want to unify the uvicorn logging with your actual endpoints logging (a good idea in my opinion), by passing None to log_config. This will essentially stop uvicorn from patching the existing logging configuration:

...
logging.basicConfig(format='{levelname:7} {message}', style='{', level=logging.INFO)
uvicorn.run(app, log_config=None)

Of course the default uvicorn coloring is lost but nothing stops you from setting a custom formatter in a global, transparent way that can also handle colors.

For that doe we need to add configuration as i done here?

It work for me. Thank you @dorinclisu for this suggestion.

[houmie]

Sorry, I'm a bit lost.

This solution by @Jackovic works locally:

log_config = uvicorn.config.LOGGING_CONFIG
log_config["formatters"]["access"]["fmt"] = "%(asctime)s - %(levelname)s - %(message)s"
log_config["formatters"]["default"]["fmt"] = "%(asctime)s - %(levelname)s - %(message)s"
uvicorn.run(app, log_config=log_config)

But how do we achieve this when using Gunicorn and uvicorn on production server?

[Unit]
Description=Gunicorn instance to serve app
After=network.target

[Service]
User=www-data
Group=www-data
WorkingDirectory=/home/admin/app
Environment="PATH=/home/admin/.pyenv/versions/venv/bin"
ExecStart=/home/admin/.pyenv/versions/venv/bin/gunicorn -c /etc/app/config.py main:app
Restart=always

[Install]
WantedBy=multi-user.target

/etc/app/config.py

bind = "127.0.0.1:8000"
backlog = 2048
workers = 4
worker_class = "uvicorn.workers.UvicornWorker"
worker_connections = 1000
timeout = 30
keepalive = 2
spew = False
daemon = False
pidfile = None
umask = 0
user = None
group = None
tmp_upload_dir = None
errorlog = "/var/log/app/error.log"
loglevel = "info"
accesslog = "/var/log/app/access.log"
access_log_format = '%(h)s %(l)s %(u)s %(t)s "%(r)s" %(s)s %(b)s "%(f)s" "%(a)s"'
proc_name = None

Because we can't create log_config and pass it in. And the access_log_format seems to use a very different formatting. I appreciate a hint how to proceed with this.

Thank you

[mandarvaze]

@houmie
You can indeed pass log_config to uvicorn
e.g. Here is my sample config file

version: 1
disable_existing_loggers: False
formatters:
  default:
    "()": uvicorn.logging.DefaultFormatter
    format: '%(asctime)s - %(name)s - %(levelname)s - %(message)s'
  access:
    "()": uvicorn.logging.AccessFormatter
    format: '%(asctime)s - %(name)s - %(levelname)s - %(message)s'
handlers:
  default:
    formatter: default
    class: logging.StreamHandler
    stream: ext://sys.stderr
  access:
    formatter: access
    class: logging.StreamHandler
    stream: ext://sys.stdout
loggers:
  uvicorn.error:
    level: INFO
    handlers:
      - default
    propagate: no
  uvicorn.access:
    level: INFO
    handlers:
      - access
    propagate: no

You can now start uvicorn with --log-config=log_conf.yaml (assuming the above file is saved as log_conf.yaml)

You may need to change StreamHandler to FileHandler and other appropriate changes.
I hope this helps

[houmie]

@mandarvaze Thank you for your reply.

It's actually more complicated with Gunicorn, because you don't have a clear entry point to pass in the config.

ExecStart=/home/admin/.pyenv/versions/venv/bin/gunicorn -c /etc/app/config.py main:app 

I have found a similar issue: encode/uvicorn#491

But it's not straight forward, as I need to subclass the worker it seems, which can't be found.

Thanks

[KaranTrivedi]

Is there a way to show response time in the logs?

[mecampbellsoup]

Does anyone know if it is possible to disable logging for specific endpoints only?

[JarroVGIT]

As these are Uvicorn logs, I would recommend to ask this in that repo.

[tiangolo]

Thanks for the discussion here everyone! 👏 🙇

Thanks for reporting back and closing the issue @Jackovic 👍