FastAPI and Uvicorn Logging #python #fastapi #uvicorn #logging

README.md

FastAPI and Uvicorn Logging

When running FastAPI app, all the logs in console are from Uvicorn and they do not have timestamp and other useful information. As Uvicorn applies python logging module, we can override Uvicorn logging formatter by applying a new logging configuration.

Meanwhile, it's able to unify the your endpoints logging with the Uvicorn logging by configuring all of them in the config file log_conf.yaml.

Before overriding:

uvicorn main:app --reload

INFO:     Uvicorn running on http://127.0.0.1:8000 (Press CTRL+C to quit)
INFO:     Started reloader process [34318] using StatReload
INFO:     Started server process [34320]
INFO:     Waiting for application startup.
INFO:     Application startup complete.
INFO:     127.0.0.1:50062 - "GET / HTTP/1.1" 200 OK

After applying log_conf.yaml:

uvicorn main:app --reload --log-config=log_conf.yaml

2023-03-08 15:40:41,170 - uvicorn.error - INFO - Uvicorn running on http://127.0.0.1:8000 (Press CTRL+C to quit)
2023-03-08 15:40:41,170 - uvicorn.error - INFO - Started reloader process [34322] using StatReload
2023-03-08 15:40:41,297 - asyncio - DEBUG - Using selector: EpollSelector
2023-03-08 15:40:41,432 - uvicorn.error - INFO - Started server process [34324]
2023-03-08 15:40:41,432 - uvicorn.error - INFO - Waiting for application startup.
2023-03-08 15:40:41,432 - uvicorn.error - INFO - Application startup complete.
2023-03-08 15:48:21,450 - main - INFO - request / endpoint!
2023-03-08 15:48:21,450 - uvicorn.access - INFO - 127.0.0.1:59782 - "GET / HTTP/1.1" 200

logs with FastAPI and Uvicorn · tiangolo/fastapi · Discussion #7457 · GitHub

Python Comprehensive Logging using YAML Configuration · GitHub

log_conf.yaml

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
root:
  level: DEBUG
  handlers:
    - default
  propagate: no

main.py

from fastapi import FastAPI
import logging

logger = logging.getLogger(__name__)

app = FastAPI()

@app.get("/")
async def func():
    logger.info(f"request / endpoint!")
    return {"message": "hello world!"}

requirements.txt

uvicorn>=0.20.0
fastapi>=0.89.1
PyYAML>=6.0

Hey Thanks for this , have a doubt Can we override the values using environment variables , As we have different env , can we override value of root level to ERROR in prod ....

As I know, PyYaml doesn't parse env vars in default, So it's not possible to use --log-config in Uvicorn to read env into logging config. You can invoke your own custom logging conf after Uvicorn starting up without --log-config loading, a simple and direct example:

from fastapi import FastAPI
import logging
import logging.config
import os

ROOT_LEVEL = os.environ.get('PROD', "INFO")

LOGGING_CONFIG = {
    "version": 1,
    "disable_existing_loggers": True,
    "formatters": {
        "standard": {"format": "%(asctime)s [%(levelname)s] %(name)s: %(message)s"},
    },
    "handlers": {
        "default": {
            "level": "INFO",
            "formatter": "standard",
            "class": "logging.StreamHandler",
            "stream": "ext://sys.stdout",  # Default is stderr
        },
    },
    "loggers": {
        "": {  # root logger
            "level": ROOT_LEVEL, #"INFO",
            "handlers": ["default"],
            "propagate": False,
        },
        "uvicorn.error": {
            "level": "DEBUG",
            "handlers": ["default"],
        },
        "uvicorn.access": {
            "level": "DEBUG",
            "handlers": ["default"],
        },
    },
}

logging.config.dictConfig(LOGGING_CONFIG)

logger = logging.getLogger(__name__)
app = FastAPI()

@app.get("/")
async def func():
    logger.info(f"request / endpoint!")
    return {"message": "hello world!"}

Moreover, you can also load the LOGGING_CONFIG dict from the yaml file which supports env vars, for example, by defining resolver in pyyaml to support itPyYaml Replace Env Vars

for uvicorn logs can we print http status code separately ,

very useful, thanks!

Hi, earlier the message was: "GET / HTTP/1.1" 200 OK, but after manual logging config the mesaage is like: "GET / HTTP/1.1" 200, here we can see that the last mesaage "OK" from line is missing. Also if we hit error 404 then it only shows "404", instead of "404 Not Found".

This is brilliant, thank you!

you sir (or lady), are very nice! thank you

it great to find this,
thanks !!!

Thanks!

Hi, earlier the message was: "GET / HTTP/1.1" 200 OK, but after manual logging config the mesaage is like: "GET / HTTP/1.1" 200, here we can see that the last mesaage "OK" from line is missing. Also if we hit error 404 then it only shows "404", instead of "404 Not Found".

Just a quick note, updating the format section in config file with "%(asctime)s - %(name)s - %(levelname)s - %(client_addr)s - \"%(request_line)s\" %(status_code)s" will restore the full status message.

Alternatively, a simpler method that worked for me:

# Display Uvicorn access logs with timestamps
log_config = uvicorn.config.LOGGING_CONFIG
log_config["formatters"]["access"]["fmt"] = (
    '%(asctime)s - %(name)s - %(levelname)s - %(client_addr)s - "%(request_line)s" %(status_code)s'
)

uvicorn.run("app:create_app", host="127.0.0.1", port=8000, log_config=log_config)

Hope this helps :)

thanks working

If you only really care about logging some extra info for HTTP requests, I've found @app.middleware("http") to be the silver bullet. Excellent example at this SO answer.

Tank you so much for this!

In case you also want to use gunicorn, you just have to convert the conf to JSON and start gunicorn with --log-config-json log_conf.json.
The loggers for gunicorn are called:

"gunicorn.error": {
    "level": "INFO",
    "handlers": [
        "default"
    ],
    "propagate": "no"
},
"gunicorn.access": {
    "level": "INFO",
    "handlers": [
        "access"
    ],
    "propagate": "no"
}

It is very helpful, thanks a lot!

Very helpful, thank you!

What is the significance of "ext" in this stream definition?

stream: ext://sys.stdout

I have issues where my app is not logging to journalctl with the name of the app defined in the conf file but rather as the name of the script that starts it in the Exec. So, am wondering if either pythons buffering or this definition could cause this? Can't find what "ext" means in the logging docs.

Also, it seems like some discussion should be devoted to simply logging to the uvicorn tree:

logger = logging.getLogger(f"uvicorn.{__name__}")