Fastapi: [QUESTION] How to print logs to file

[luozhouyang]

First check

• [x] I used the GitHub search to find a similar issue and didn't find it.
• [x] I searched the FastAPI documentation, with the integrated search.
• [x] I already searched in Google "How to X in FastAPI" and didn't find any information.

Description

The logouts print by fastapi are not saved to a log file.

• how can i print the logouts to a file?
• how can i config the log format using fastapi?

[hyperleex]

Hello @luozhouyang , I solved this problem by changing the uvicorn configuration

run.py

import uvicorn
import settings

if __name__ == "__main__":
    uvicorn.run(
        "core.handler:app",
        port=8000,
        host="0.0.0.0",
        log_config=settings.LOGGING_CONFIG,
    )

log_config accept a dictionary with logging settings, as in DJANGO

[Slyfoxy]

Hi, @luozhouyang

You can config logs with loguru. It can change the format of standard logs and write them to a file

[luozhouyang]

Thanks! @Slyfoxy
loguru looks amazing! It can easily write logs to files in pretty format.
But how can i format logs from fastapi itself? Any examples or documentations?

[luozhouyang]

Thanks @hyperleex , I'll have a try.

[Slyfoxy]

Try this example. I hope it will be useful :fox_face:

import logging
import sys
from pprint import pformat

from fastapi import FastAPI
from loguru import logger
from loguru._defaults import LOGURU_FORMAT
from starlette.requests import Request


class InterceptHandler(logging.Handler):
    """
    Default handler from examples in loguru documentaion.
    See https://loguru.readthedocs.io/en/stable/overview.html#entirely-compatible-with-standard-logging
    """

    def emit(self, record):
        # Get corresponding Loguru level if it exists
        try:
            level = logger.level(record.levelname).name
        except ValueError:
            level = record.levelno

        # Find caller from where originated the logged message
        frame, depth = logging.currentframe(), 2
        while frame.f_code.co_filename == logging.__file__:
            frame = frame.f_back
            depth += 1

        logger.opt(depth=depth, exception=record.exc_info).log(
            level, record.getMessage()
        )


def format_record(record: dict) -> str:
    """
    Custom format for loguru loggers.
    Uses pformat for log any data like request/response body during debug.
    Works with logging if loguru handler it.

    Example:
    >>> payload = [{"users":[{"name": "Nick", "age": 87, "is_active": True}, {"name": "Alex", "age": 27, "is_active": True}], "count": 2}]
    >>> logger.bind(payload=).debug("users payload")
    >>> [   {   'count': 2,
    >>>         'users': [   {'age': 87, 'is_active': True, 'name': 'Nick'},
    >>>                      {'age': 27, 'is_active': True, 'name': 'Alex'}]}]
    """
    format_string = LOGURU_FORMAT

    if record["extra"].get("payload") is not None:
        record["extra"]["payload"] = pformat(
            record["extra"]["payload"], indent=4, compact=True, width=88
        )
        format_string += "\n<level>{extra[payload]}</level>"

    format_string += "{exception}\n"
    return format_string


app = FastAPI(title="Logger Handler", debug=True)

# set loguru format for root logger
logging.getLogger().handlers = [InterceptHandler()]

# set format
logger.configure(
    handlers=[{"sink": sys.stdout, "level": logging.DEBUG, "format": format_record}]
)

# Also set loguru handler for uvicorn loger.
# Default format:
# INFO:     127.0.0.1:35238 - "GET / HTTP/1.1" 200 OK
#
# New format:
# 2020-04-18 16:33:49.728 | INFO     | uvicorn.protocols.http.httptools_impl:send:447 - 127.0.0.1:35942 - "GET / HTTP/1.1" 200

# uvicorn loggers: .error .access .asgi
# https://github.com/encode/uvicorn/blob/master/uvicorn/config.py#L243
logging.getLogger("uvicorn.access").handlers = [InterceptHandler()]


@app.get("/")
def index(request: Request) -> None:
    logger.info("loguru log")
    logging.info("logging log")

    logging.getLogger("fastapi").debug("fatapi info log")
    logger.bind(payload=dict(request.query_params)).debug("params with formating")
    return None

Start server with uvicorn main:app --reload.

Sending request: curl "localhost:8000/?a=11111111111111&b=2222222222222&c=33333333333&d=444444444444444"

Check server logs:

(venv) [nick@nick untitled]$ uvicorn main:app --reload 
INFO:     Uvicorn running on http://127.0.0.1:8000 (Press CTRL+C to quit)
INFO:     Started reloader process [194284]
2020-04-18 16:48:12.183 | INFO     | uvicorn.main:serve:397 - Started server process [194286]
2020-04-18 16:48:12.184 | INFO     | uvicorn.lifespan.on:startup:22 - Waiting for application startup.
2020-04-18 16:48:12.184 | INFO     | uvicorn.lifespan.on:startup:34 - Application startup complete.
2020-04-18 16:48:15.549 | INFO     | main:index:69 - loguru log
2020-04-18 16:48:15.550 | INFO     | main:index:70 - logging log
2020-04-18 16:48:15.551 | DEBUG    | main:index:73 - params with formating
{   'a': '11111111111111',
    'b': '2222222222222',
    'c': '33333333333',
    'd': '444444444444444'}
2020-04-18 16:48:15.553 | INFO     | uvicorn.protocols.http.httptools_impl:send:447 - 127.0.0.1:36312 - "GET /?a=11111111111111&b=2222222222222&c=33333333333&d=444444444444444 HTTP/1.1" 200

[luozhouyang]

@Slyfoxy Thank you very much!

[tiangolo]

Thanks for the help here everyone! :clap: :bow:

Thanks for reporting back and closing the issue @luozhouyang :+1:

[mcauto]

@Slyfoxy

Awesome!

[questionsKev]

With the latest update to uvicorn, this example no longer works properly. It looks like they are no longer overriding the root log handler: https://github.com/encode/uvicorn/commit/e382440aa6b604ecdd323288279876767ab36443

Because of this, the log is printed twice:

`
INFO: Started server process [2039]

2020-07-24 17:48:54.098 | INFO | uvicorn.main:serve:405 - Started server process [2039]
`

I'm no expert at python logging, but I assume I need to change:
logging.getLogger("uvicorn.access").handlers = [InterceptHandler()]

I changed it to "uvicorn" but now my logs look like this:
`
2020-07-24 17:50:23.621 | INFO | uvicorn.main:serve:405 - Started server process [2240]

2020-07-24 17:50:23.621 | INFO | uvicorn.main:serve:405 - Started server process [2240]
`
Any ideas @Slyfoxy ? Thanks for your superb example! It's the cleanest and easiest to implement one I've found so far.

[Slyfoxy]

Hi, @questionsKev !

I'm very glad that you liked my example, thanks 😄

I did not know that in the new version uvicorn fixed the problem with the root handler, since I had not yet updated it in my projects. 😅

The new problem of duplication is solved easily. Disable the access and error loggers. So their output is redirected to the default logger - uvicorn 🛠️

    # works with uvicorn==0.11.6
    loggers = (
        logging.getLogger(name)
        for name in logging.root.manager.loggerDict
        if name.startswith("uvicorn.")
    )
    for uvicorn_logger in loggers:
        uvicorn_logger.handlers = []
    logging.getLogger("uvicorn").handlers = [InterceptHandler()]

Since the example contains many lines of code and the uvicorn logging issue is quite popular I decided to make a gist 🗒️

I hope the community finds it useful! 🦊

[lvar]

@Slyfoxy I try to save the payload params into a file but isn't working...

logger.bind(payload=await request.json()).debug("params with formating")
logger.add("log/access.log", enqueue=True , backtrace=True, diagnose=True)

The file only prints "params with formating"

[riki-nitdgp]

You can try this also https://medium.com/1mgofficial/how-to-override-uvicorn-logger-in-fastapi-using-loguru-124133cdcd4e