Fastapi: 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 https://github.com/encode/uvicorn/issues/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)

1. "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.