Fastapi: Debug Logging (Maybe just a n00b issue)

[charliegriefer]

Disclaimer: n00b to Python altogether. This is the first Python app that I've ever built.

Trying to add formatted debug logging to the screen. I've gotten it to the point where the debug output shows twice. Once with the formatting applied, and once raw.

Scaled down code would be:

import logging

from fastapi import FastAPI

api = FastAPI()

logger = logging.getLogger("api")
logger.setLevel(logging.DEBUG)

fh = logging.FileHandler("QED.log")
fh.setLevel(logging.ERROR)
ch = logging.StreamHandler()
ch.setLevel(logging.DEBUG)
formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')
fh.setFormatter(formatter)
ch.setFormatter(formatter)

logger.addHandler(fh)
logger.addHandler(ch)

@api.get("/")
def read_root():
    logger.debug("THIS IS A DEBUG LOG")
    logger.error("SOMETHING WENT VERY VERY WRONG")
    return {"Hello": "World"}

Output to the console is:

2019-06-04 12:44:51,169 - api - DEBUG - THIS IS A DEBUG LOG
DEBUG: THIS IS A DEBUG LOG
2019-06-04 12:44:51,169 - api - ERROR - SOMETHING WENT VERY VERY WRONG
ERROR: SOMETHING WENT VERY VERY WRONG
INFO: ('127.0.0.1', 55229) - "GET / HTTP/1.1" 200

So, two things are happening.

1. Seeing both the formatted message and the raw message.
2. Seeing the ERROR level message in the console. That should only be written to QED.log

Thanks!

[euri10]

Guessing that you started the app with uvicorn it looks like this is the
logs of it.
You can use the log-level flag, see
https://www.uvicorn.org/settings/#logging

e mar. 4 juin 2019 à 9:37 PM, Charlie Griefer [e-mail] a
écrit :

Disclaimer: n00b to Python altogether. This is the first Python app that
I've ever built.

Trying to add formatted debug logging to the screen. I've gotten it to the
point where the debug output shows twice. Once with the formatting applied,
and once raw.

Scaled down code would be:

import logging

from fastapi import FastAPI

api = FastAPI()

logger = logging.getLogger("api")
logger.setLevel(logging.DEBUG)

fh = logging.FileHandler("QED.log")
fh.setLevel(logging.DEBUG)
ch = logging.StreamHandler()
ch.setLevel(logging.DEBUG)
formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')
fh.setFormatter(formatter)
ch.setFormatter(formatter)

logger.addHandler(fh)
logger.addHandler(ch)

@api.get("/")
def read_root():
logger.debug("THIS IS A DEBUG LOG")
return {"Hello": "World"}

Output to the console is:

2019-06-04 12:12:05,541 - api - DEBUG - THIS IS A DEBUG LOG
DEBUG: THIS IS A DEBUG LOG
INFO: ('127.0.0.1', 54183) - "GET / HTTP/1.1" 200

Any advice to a Python n00b on how to remove that second unformatted debug?

Thanks!

—
You are receiving this because you are subscribed to this thread.
Reply to this email directly, view it on GitHub
https://github.com/tiangolo/fastapi/issues/290?email_source=notifications&email_token=AAINSPTERYYFZ2BZEACYBSDPY2767A5CNFSM4HTAJOIKYY3PNVWWK3TUL52HS4DFUVEXG43VMWVGG33NNVSW45C7NFSM4GXTSYKA,
or mute the thread
https://github.com/notifications/unsubscribe-auth/AAINSPS7WED6ZLUAP6B7RK3PY2767ANCNFSM4HTAJOIA
.

[charliegriefer]

Hey euri10...

Thanks for the reply!

I started the app with uvicorn qed.api:api --reload

... so I don't _think_ I should be seeing uvicorn log items?

[euri10]

I think the uvicorn default is info and that is the

INFO: ('127.0.0.1', 54183) - "GET / HTTP/1.1" 200

Le mar. 4 juin 2019 à 10:05 PM, Charlie Griefer [e-mail]
a écrit :

Hey euri10...

Thanks for the reply!

I started the app with uvicorn qed.api:api --reload

... so I don't think I should be seeing uvicorn log items?

—
You are receiving this because you commented.
Reply to this email directly, view it on GitHub
https://github.com/tiangolo/fastapi/issues/290?email_source=notifications&email_token=AAINSPTKKZLUP57RDYOXHULPY3DH3A5CNFSM4HTAJOIKYY3PNVWWK3TUL52HS4DFVREXG43VMVBW63LNMVXHJKTDN5WW2ZLOORPWSZGODW5WZHQ#issuecomment-498822302,
or mute the thread
https://github.com/notifications/unsubscribe-auth/AAINSPVGCNMWAKDZPR3TT4TPY3DH3ANCNFSM4HTAJOIA
.

[charliegriefer]

I'm ok with seeing that line specifically. But what I'm seeing is two debug lines:

2019-06-04 12:44:51,169 - api - DEBUG - THIS IS A DEBUG LOG
DEBUG: THIS IS A DEBUG LOG

... and two error lines:

2019-06-04 12:44:51,169 - api - ERROR - SOMETHING WENT VERY VERY WRONG
ERROR: SOMETHING WENT VERY VERY WRONG

I should only be seeing one debug line (preferably the formatted one), and no error lines.

[euri10]

Could come from the root logger, you could check if handlers exist before
adding them
If not that I'm out of ideas

Le mar. 4 juin 2019 à 10:09 PM, Charlie Griefer [e-mail]
a écrit :

I'm ok with seeing that line specifically. But what I'm seeing is two
debug lines:

2019-06-04 12:44:51,169 - api - DEBUG - THIS IS A DEBUG LOG
DEBUG: THIS IS A DEBUG LOG

... and two error lines:

2019-06-04 12:44:51,169 - api - ERROR - SOMETHING WENT VERY VERY WRONG
ERROR: SOMETHING WENT VERY VERY WRONG

I should only be seeing one debug line (preferably the formatted one), and
no error lines.

—
You are receiving this because you commented.
Reply to this email directly, view it on GitHub
https://github.com/tiangolo/fastapi/issues/290?email_source=notifications&email_token=AAINSPVOB4IZJF4K2FEVVUDPY3DZBA5CNFSM4HTAJOIKYY3PNVWWK3TUL52HS4DFVREXG43VMVBW63LNMVXHJKTDN5WW2ZLOORPWSZGODW5XGHA#issuecomment-498823964,
or mute the thread
https://github.com/notifications/unsubscribe-auth/AAINSPX5SJWXDCU5SMBYOPTPY3DZBANCNFSM4HTAJOIA
.

[davidrios]

Hi @charliegriefer

You don't need to set handlers for logging in your FastAPI app, the code can just be:

import logging

from fastapi import FastAPI

api = FastAPI()

logger = logging.getLogger("api")

@api.get("/")
def read_root():
    logger.debug("THIS IS A DEBUG LOG")
    logger.error("SOMETHING WENT VERY VERY WRONG")
    return {"Hello": "World"}

Then you set the logging level when starting uvicorn, like:

uvicorn qed.api:api --reload --log-level debug

When you run your application in a server, if it is Linux with systemd, it'll take care of saving the log to the journal and syslog, as well as timestamping it, then you can redirect to another file if you want. But you don't need to worry about that when developing, just at deployment time.

[charliegriefer]

Interesting. Thanks @davidrios !

Ultimately I did get it working, but I may have done more lifting than necessary. But it's outputting what we were looking for.

We did want different levels of output in different environments... so I have a function to set a logger that looks like this:

    logger = logging.getLogger(name)

    if not logger.handlers:
        logger.propagate = 0
        formatter = logging.Formatter("%(asctime)s - %(name)s - %(levelname)s - %(message)s")
        formatter.converter = time.gmtime
        console_handler = logging.StreamHandler()

        logger.setLevel(set_level(level))

        if env == "production":
            console_handler.setLevel(logging.ERROR)
        else:
            console_handler.setLevel(level)

        logger.addHandler(console_handler)
        console_handler.setFormatter(formatter)

        if env == "production":
            error_handler = logging.FileHandler("app_error.log")
            error_handler.setLevel(logging.ERROR)
            logger.addHandler(error_handler)
            error_handler.setFormatter(formatter)
    return logger

I was actually kind of digging starting uvicorn with log-level critical, just to suppress uvicorn's logging and keep it strictly to the app's info/debug information.

[davidrios]

It does look like more lifting than necessary 😂.

As far as I know, it's standard practice to just output the logging to stdout, then the environment that you're running should take care of setting the logging level, timestamping, saving to files, etc, otherwise you end up having to deal with a lot of commom problems in your app code that were already solved, like rotating the log files for instance.

About this code of yours, is it in a separate module and you are importing it in other places where you need logging? Because you don't need to do that. Generally what you would do is, in every module that you need logging, you just put the code:

import logging
logger = logging.getLogger(__name__)
...

And then to setup formatting, saving, etc, in the module that is the entry point to your application, that is executed before all other code, you put something like this:

import logging

formatter = logging.Formatter("%(asctime)s - %(name)s - %(levelname)s - %(message)s")
formatter.converter = time.gmtime

console_handler = logging.StreamHandler()

if env == "production":
    console_handler.setLevel(logging.ERROR)
else:
    console_handler.setLevel(level)

console_handler.setFormatter(formatter)

handlers = [console_handler]

if env == "production":
    error_handler = logging.FileHandler("app_error.log")
    error_handler.setLevel(logging.ERROR)
    error_handler.setFormatter(formatter)
    handlers.append(error_handler)

logging.basicConfig(handlers=handlers)

[charliegriefer]

I did put the code into a module. There are actually two different entry points to the app.

One is obviously via http and FastAPI.
There's another that processes the results of the API endpoint(s) being called.

Structure looks something like:

- myapp/
    - README.md
    - requirements.txt
    - processor.py (the processing entry point)
    - myapp/
        - api.py (the FAST api controller)
        - reporting.py (a module called by both the api and processor)
        - log.py (the logging module in question)

On myapp/api.py I have the line logger = log.set_logger("dev", "api", "info")
On processor.py I have the line logger = log.set_logger("dev", "report_processor", "info")

So having the two entry points was the motivating factor behind the separate module.

Like I said above, I'm new to all of this. I've written a few python scripts here and there, but this is my first actual app. I appreciate the guidance so far and I am absolutely open to hearing any suggestions that you might want to throw my way :)

Thanks!

[euri10]

glad you solved it !

matter of taste I guess, I do all the logging setup through a logging.yml
and load it with logging.config.dictConfig

that way you can have a logging.yml for for your diverse envs, and the yaml
is rather easy to edit.

one other advantage is that you can change the log level through the api
on the fly, setting up a few methods within a dedicated fastapi router,
will try to make a post about but if you search through the gitter chat you
may find snippets I posted there.

[euri10]

ok so basically I'm using this, in a applog package

import logging.config
import os

import yaml


def read_logging_config(default_path="logging.yml", env_key="LOG_CFG"):
    path = default_path
    value = os.getenv(env_key, None)
    if value:
        path = value
    if os.path.exists(path):
        with open(path, "rt") as f:
            logging_config = yaml.safe_load(f.read())
        return logging_config
    else:
        return None


def setup_logging(logging_config, default_level=logging.INFO):
    if logging_config:
        logging.config.dictConfig(logging_config)
    else:
        logging.basicConfig(level=default_level)

you use it wherever your entrypint is this way

from applog.utils import read_logging_config, setup_logging

logconfig_dict = read_logging_config("applog/logging.yml")
setup_logging(logconfig_dict)

should you need, you can pass env another file than the default logging.yml for your dev / prod environements

logging.yml looks like this:

version: 1
disable_existing_loggers: False
formatters:
    simple:
        format: "%(asctime)s - %(name)s - %(lineno)d - %(levelname)s - %(message)s"
handlers:
    console:
        class: logging.StreamHandler
        level: DEBUG
        formatter: simple
        stream: ext://sys.stdout
    info_file_handler:
        class: logging.handlers.RotatingFileHandler
        level: INFO
        formatter: simple
        filename: applog/info.log
        maxBytes: 10485760 # 10MB
        backupCount: 20
        encoding: utf8
    error_file_handler:
        class: logging.handlers.RotatingFileHandler
        level: ERROR
        formatter: simple
        filename: applog/errors.log
        maxBytes: 10485760 # 10MB
        backupCount: 20
        encoding: utf8
loggers:
    uvicorn:
        level: INFO
        handlers: [console]
        propagate: no
    gunicorn:
        level: INFO
        handlers: [console]
        propagate: no
root:
    level: INFO
    handlers: [console]

[tiangolo]

Welcome here @charliegriefer! I'm glad to hear you are using FastAPI in your first projects :tada:

One of the main ideas is to make it easy to use even for new people in Python. So, if you find missing concepts or things that you think could be explained better, don't hesitate to let me know :smile:

Thanks @euri10 and @davidrios for the help here! :tada:

[loikled]

I have the same issue, I ported some code to fastAPI and my logging configuration did nothing, then was called two times when I applied it to logging.getLogger('uvicorn').

After reading the code of uvicorn I found that there is a setting --log-config for the logging config file:
https://www.uvicorn.org/settings/.

Here you can override the config for the whole app.

[lukaszdudek-silvair]

FWIW, when using gunicorn-uvicorn-fastapi Docker image, I've used the following steps to get my app logs:

• provide a logger instance for the app & plugging it in gunicorn.error logger:

# app/env.py
APP_NAME = "my-service"
LOG_LEVEL = os.getenv("LOG_LEVEL", "DEBUG")
LOGGER = logging.getLogger(f"gunicorn.error.{APP_NAME}")
LOGGER.setLevel(LOG_LEVEL)

• reuse this instance anywhere logs are needed
• set LOG_LEVEL env var for containers (whichever way you run them - we use docker-compose for local development & AWS ECS for anything beyond).

Hope it helps anyone.

[danieljfarrell]

@lukaszdudek-silvair I just tried this and it didn't work for me. I am also running using the Docker image.

I'm running like this,

sudo docker run -d -t -p 80:80 -e BIND="0.0.0.0:80" -e APP_MODULE="main:app" -e LOG_LEVEL="debug" -e WORKER_CLASS="uvicorn.workers.UvicornWorker" myimage

I've tried with and with the -t option too.

[lukaszdudek-silvair]

@danieljfarrell have you tried it with capitals: LOG_LEVEL=DEBUG? AFAIK logging doesn't use lowercase level names.
Also, the issue linked above is a great source of examples of how to deal with the problem.

[danieljfarrell]

@lukaszdudek-silvair thank you, I will try.

[loikled]

Some update on this, I'm using fastapi with uvicorn, and I just wanted to add the timestamp in the log format, and if possible keep the nice coloring they provide.

I discovered that uvicorn assigns colors based on the levelprefix attribute, it colorizes it and replaces with the string level.
You can import the uvicorn config and customize the default formatter.

Here is the simplest way I found to customize the formatting and keep colorization:

import uvicorn
from uvicorn.config import LOGGING_CONFIG
from fastapi import FastAPI

app = FastAPI()

def run():
    LOGGING_CONFIG["formatters"]["default"]["fmt"] = "%(asctime)s [%(name)s] %(levelprefix)s %(message)s"
    uvicorn.run(app)

if __name__ == '__main__':
    run()

Result: