Log formatter partially ignored with multiple workers

[geokarak]

I noticed that my custom log formatter for uvicorn.error is partially ignored when I start my (FastAPI) app with multiple workers. This behaviour is best visualized with the following screenshot:

From the above picture, one can see that when using multiple workers, it seems that my log formatter is partially applied (middle block where logs start with a timestamp).

Reproduce issue

The structure of my dummy editable application is as follows:

├── src
│   └── myapp
│       ├── __init__.py
│       ├── logging_config.py
│       ├── main.py

where

# main.py
import logging.config

from fastapi import FastAPI

from myapp.logging_config import LOGGING_CONFIG

logging.config.dictConfig(LOGGING_CONFIG)

app = FastAPI()


@app.get("/")
async def root():
    return {"message": "Welcome to the Visa Check API!"}

and

# logging_config.py
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
            "handlers": ["default"],
            "level": "WARNING",
            "propagate": False,
        },
        "uvicorn.error": {"handlers": ["default"], "level": "INFO", "propagate": False},
        "uvicorn.access": {
            "handlers": ["default"],
            "level": "INFO",
            "propagate": False,
        },
    },
}

I should note that, when calling uvicorn programmatically with uvicorn.run("myapp.main:app", log_config=LOGGING_CONFIG, workers=2) inside main.py, all logs are formatted appropriately. I could only see this issue when I run the app from the command line with uvicorn myapp.main:app --workers 2 as shown in the initial screenshot.

[nectarindev]

This happens because uvicorn makes its own default logger configuration. In the case of a single worker, it looks like your dictConfig runs before uvicorn writes the first log, so everything is fine, but in the case of multiple workers, this does not work.

I would suggest putting your logger configuration into a file and specifying it using cli:

// log_config.json
{
    "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"
        }
    },
    "loggers": {
        "": {
            "handlers": ["default"],
            "level": "WARNING",
            "propagate": false
        },
        "uvicorn.error": {"handlers": ["default"], "level": "INFO", "propagate": false},
        "uvicorn.access": {
            "handlers": ["default"],
            "level": "INFO",
            "propagate": false
        }
    }
}

uvicorn myapp.main:app --log-config log_config.json --workers 2