Use structlog for logging

[simonw]

To solve #241 JSON logging.

[simonw]

Some tips here: https://github.com/tiangolo/fastapi/issues/78

[hannseman]

I encountered your issue when trying to find a solution and came up with the following, maybe it can help.

import logging.config
from typing import Tuple

import structlog
import uvicorn

from example.config import settings

shared_processors: Tuple[structlog.types.Processor, ...] = (
    structlog.contextvars.merge_contextvars,
    structlog.stdlib.add_logger_name,
    structlog.stdlib.add_log_level,
    structlog.processors.TimeStamper(fmt="iso"),
)

logging_config = {
    "version": 1,
    "disable_existing_loggers": False,
    "formatters": {
        "json": {
            "()": structlog.stdlib.ProcessorFormatter,
            "processor": structlog.processors.JSONRenderer(),
            "foreign_pre_chain": shared_processors,
        },
        "console": {
            "()": structlog.stdlib.ProcessorFormatter,
            "processor": structlog.dev.ConsoleRenderer(),
            "foreign_pre_chain": shared_processors,
        },
        **uvicorn.config.LOGGING_CONFIG["formatters"],
    },
    "handlers": {
        "default": {
            "level": "DEBUG",
            "class": "logging.StreamHandler",
            "formatter": "json" if not settings.debug else "console",
        },
        "uvicorn.access": {
            "level": "INFO",
            "class": "logging.StreamHandler",
            "formatter": "access",
        },
        "uvicorn.default": {
            "level": "INFO",
            "class": "logging.StreamHandler",
            "formatter": "default",
        },
    },
    "loggers": {
        "": {"handlers": ["default"], "level": "INFO"},
        "uvicorn.error": {
            "handlers": ["default" if not settings.debug else "uvicorn.default"],
            "level": "INFO",
            "propagate": False,
        },
        "uvicorn.access": {
            "handlers": ["default" if not settings.debug else "uvicorn.access"],
            "level": "INFO",
            "propagate": False,
        },
    },
}


def setup_logging() -> None:
    structlog.configure(
        processors=[
            structlog.stdlib.filter_by_level,
            *shared_processors,
            structlog.stdlib.PositionalArgumentsFormatter(),
            structlog.processors.StackInfoRenderer(),
            structlog.processors.format_exc_info,
            structlog.stdlib.ProcessorFormatter.wrap_for_formatter,
        ],
        context_class=dict,
        logger_factory=structlog.stdlib.LoggerFactory(),
        wrapper_class=structlog.stdlib.AsyncBoundLogger,
        cache_logger_on_first_use=True,
    )
    logging.config.dictConfig(logging_config)

And then it'll be run on the startup event:

@app.on_event("startup")
async def startup_event() -> None:
    setup_logging()

It depends on a setting called debug which controls if it should output the regular uvicorn logging or json.

[AnkitKundariya]

@hannseman I have tried the above suggestion given by you but somehow I'm getting the below error.

note : I'm running my application with Docker.

app_1 | {"event": "Exception in ASGI application\n", "exc_info": ["<class 'RuntimeError'>", "RuntimeError('no running event loop')", "<traceback object at 0x7f9d2f5dffc0>"], "logger": "uvicorn.error", "level": "error", "timestamp": "2021-12-02T12:06:36.011448Z"}

[RamiAwar]

I'm using this in a separate FastAPI app, worked perfectly when I changed the AsyncBoundLogger to BoundLogger only.

Also for some reason, I'm now getting some logs surfacing from internal packages, like Elasticsearch. But don't have time to deal with that now.