uvicorn-gunicorn-fastapi-docker: [QUESTION] How to do logging in a FastApi container, any logging does not appear

Description I have another project that utilizes fast api using gunicorn running uvicorn workers and supervisor to keep the api up. Recently I came across the issue that none of my logs from files that are not the fast api app are coming through. Initially I tried making an adhoc script to see if it works as well as changing the levels of the logging. I only had success if I set the logging to be at the DEBUG level.

I put together another small project to test out if I would run into this problem with a clean slate and I still couldn’t get logging working with a standard

import logging

log = logging.getLogger(__name__)
log.setLevel(logging.INFO)
log.info('help!')

Other steps I took was chmod-ing the /var/log/ directory in case it was a permissions issue but I had no luck. Has anyone else ran into this or have recommendations on how they implemented logging?

Additional context For context I put up the testing repo here: https://github.com/PunkDork21/fastapi-git-test Testing it would be like:

docker-compose up -d
docker exec -it git-test_web_1 bash
python3 ./appy.py

The most of the files are similar to what I have in my real project

About this issue

  • Original URL
  • State: closed
  • Created 5 years ago
  • Reactions: 64
  • Comments: 53 (1 by maintainers)

Most upvoted comments

I finally solved it!

First, make sure you set the environment variable LOG_LEVEL to debug, e.g. in your Docker-Compose file.

Now in your actual FastAPI app, add this code below the imports:

from fastapi.logger import logger
# ... other imports
import logging

gunicorn_logger = logging.getLogger('gunicorn.error')
logger.handlers = gunicorn_logger.handlers
if __name__ != "main":
    logger.setLevel(gunicorn_logger.level)
else:
    logger.setLevel(logging.DEBUG)

This way, if your app is loaded via gunicorn, you can tell the logger to use gunicorn’s log level instead of the default one. Because if gunicorn loads your app, FastAPI does not know about the environment variable directly; you will have to manually override the log level.

The else branch is for when you run the app directly, in which case I assume debug logging will be required.

I tested this with the version where the command /start-reload.sh is specified in the Docker-Compose config, as well as the one where it is left out, and of course running the app directly.

I’ve struggled with this for the past few days as well, and only just figured it out. The HTTP request info is stored in the uvicorn.access logs. In order to see that information when running uvicorn via gunicorn (lots of unicorns here!), you’ll need the following snippet in your main.py

import logging
from fastapi.logger import logger as fastapi_logger

gunicorn_error_logger = logging.getLogger("gunicorn.error")
gunicorn_logger = logging.getLogger("gunicorn")
uvicorn_access_logger = logging.getLogger("uvicorn.access")
uvicorn_access_logger.handlers = gunicorn_error_logger.handlers

fastapi_logger.handlers = gunicorn_error_logger.handlers

if __name__ != "__main__":
    fastapi_logger.setLevel(gunicorn_logger.level)
else:
    fastapi_logger.setLevel(logging.DEBUG)

This will allow the gunicorn.error logger to handle the uvicorn.access logger, thus allowing the HTTP request information to come through. You don’t even need to add --access-log - in the gunicorn command (but thank you for the suggestion, @bcb!) Big, huge thanks to @slhck and @bcb for pointing me in this direction. I hope that this helps others!

any easy way to do it?

Above solution doesn’t work for me.

Also this solution ties the application code too closely to the deployment method.

We shouldn’t be referencing gunicorn/uvicorn in the code.

You can also take advantage of yaml configuration to propagate logs to the root handler. Basically use the root handler along with a fileHandler and a streamHandler, then propagate the uvicorn one (I propagate the error, but you can also propagate the access):

version: 1
disable_existing_loggers: false

formatters:
  standard:
    format: "%(asctime)s - %(levelname)s - %(message)s"

handlers:
  console:
    class: logging.StreamHandler
    formatter: standard
    level: INFO
    stream: ext://sys.stdout

  file:
    class: logging.handlers.WatchedFileHandler
    formatter: standard
    filename: mylog.log
    level: INFO


loggers:
  uvicorn:
    error:
      propagate: true

root:
  level: INFO
  handlers: [console, file]
  propagate: no

Then at app startup:

logging.config.dictConfig('config.yml')

small modification to dictConfig

# pip install PyYAML
import yaml

with open('config.yml') as f:
    config = yaml.load(f, Loader=yaml.FullLoader)
    logging.config.dictConfig(config)

Nice, @pawamoy! I also had to do a deep-dive into the inner workings of logger… and like yourself, still have a few unresolved mysteries (why are the gunicorn and uvicorn loggers not children of root?!).

I ended up with the following logging config JSON, that seems to work if you set it in your main.py. Slightly less advanced, but it works…

{ 
    "version": 1, 
    "formatters": {
        "default": { 
            "format": "%(asctime)s - %(process)s - %(name)s - %(levelname)s - %(message)s"
        }
    },
    "handlers": {
        "console": {
            "formatter": "default", 
            "class": "logging.StreamHandler",
            "stream": "ext://sys.stdout", 
            "level": "DEBUG"
            }
    },
    "root": {
            "handlers": ["console"], 
            "level": "DEBUG" 
    }, 
    "loggers": {
        "gunicorn": {
            "propagate": true
        },
        "uvicorn": {
            "propagate": true
        },
        "uvicorn.access": {
            "propagate": true
        }
    }
}

This issue is still pretty popular. It took me a while to figure this out, so in case it helps other folks:

The default setting for Uvicorn access logs is to write them to STDOUT. However, the default setting for Gunicorn access logs is to discard them without writing them anywhere.

On the other hand, the default setting for Gunicorn error logs is to stream to STDERR.

When running Uvicorn as a worker class for Gunicorn, Uvicorn will attach its logs properly to Gunicorn’s access and error loggers, but unless you have configured the access log to write somewhere you will never see them. It is easy to be confused by this because the default behaviors for Uvicorn/Gunicorn are opposite so the logs just seem to disappear.

Given all of this if you re-use the handlers from Gunicorn’s error logger for your access logs, you will see output, but it will be STDERR output (or wherever the error logger is configured to go). This probably isn’t what you want.

Instead configure the Gunicorn access logger location and your uvicorn/app logs should start showing up. If you are trying to get them to show up in your console, use “-” to send them to STDOUT.

The problem with the solution going around here is that it breaks logging when gunicorn isn’t being used. It also doesn’t affect the root handler, which is what a lot of modules are going to be using.

Here’s the version I use which tries to resolve those issues as well-

import logging
from fastapi.logger import logger as fastapi_logger

if "gunicorn" in os.environ.get("SERVER_SOFTWARE", ""):
    '''
    When running with gunicorn the log handlers get suppressed instead of
    passed along to the container manager. This forces the gunicorn handlers
    to be used throughout the project.
    '''

    gunicorn_logger = logging.getLogger("gunicorn")
    log_level = gunicorn_logger.level

    root_logger = logging.getLogger()
    gunicorn_error_logger = logging.getLogger("gunicorn.error")
    uvicorn_access_logger = logging.getLogger("uvicorn.access")

    # Use gunicorn error handlers for root, uvicorn, and fastapi loggers
    root_logger.handlers = gunicorn_error_logger.handlers
    uvicorn_access_logger.handlers = gunicorn_error_logger.handlers
    fastapi_logger.handlers = gunicorn_error_logger.handlers

    # Pass on logging levels for root, uvicorn, and fastapi loggers
    root_logger.setLevel(log_level)
    uvicorn_access_logger.setLevel(log_level)
    fastapi_logger.setLevel(log_level)

You can also take advantage of yaml configuration to propagate logs to the root handler. Basically use the root handler along with a fileHandler and a streamHandler, then propagate the uvicorn one (I propagate the error, but you can also propagate the access):

version: 1
disable_existing_loggers: false

formatters:
  standard:
    format: "%(asctime)s - %(levelname)s - %(message)s"

handlers:
  console:
    class: logging.StreamHandler
    formatter: standard
    level: INFO
    stream: ext://sys.stdout

  file:
    class: logging.handlers.WatchedFileHandler
    formatter: standard
    filename: mylog.log
    level: INFO


loggers:
  uvicorn:
    error:
      propagate: true

root:
  level: INFO
  handlers: [console, file]
  propagate: no

Then at app startup:

logging.config.dictConfig('config.yml')

I’m not using this repo, but adding this to the gunicorn command worked for me:

--access-logfile -

Hmm… I’m having a similar problem, and can’t really figure out how to deal with this.

This is my script:

import logging

from fastapi import FastAPI

app = FastAPI()
logger = logging.getLogger("gunicorn.error")

@app.get("/")
async def root():
    logger.info("Hello!")
    return "Hello, world!"

Running this directly with the following command:

uvicorn main:app

Gives the following output:

INFO:     Uvicorn running on http://127.0.0.1:8000 (Press CTRL+C to quit)
INFO:     Started reloader process [21232]
INFO:     Started server process [12508]
INFO:     Waiting for application startup.
INFO:     Application startup complete.
INFO:     Hello!
INFO:     127.0.0.1:51701 - "GET / HTTP/1.1" 200
INFO:     127.0.0.1:51760 - "GET /123 HTTP/1.1" 404

Running it in the tiangolo/uvicorn-gunicorn-fastapi:python3.7 container gives the following output.

[2020-04-13 14:14:31 +0000] [1] [INFO] Starting gunicorn 20.0.4
[2020-04-13 14:14:31 +0000] [1] [INFO] Listening at: http://0.0.0.0:80 (1)
[2020-04-13 14:14:31 +0000] [1] [INFO] Using worker: uvicorn.workers.UvicornWorker
[2020-04-13 14:14:31 +0000] [8] [INFO] Booting worker with pid: 8
[2020-04-13 14:14:31 +0000] [9] [INFO] Booting worker with pid: 9
[2020-04-13 14:14:31 +0000] [8] [INFO] Started server process [8]
[2020-04-13 14:14:31 +0000] [8] [INFO] Waiting for application startup.
[2020-04-13 14:14:31 +0000] [8] [INFO] Application startup complete.
[2020-04-13 14:14:31 +0000] [9] [INFO] Started server process [9]
[2020-04-13 14:14:31 +0000] [9] [INFO] Waiting for application startup.
[2020-04-13 14:14:31 +0000] [9] [INFO] Application startup complete.
[2020-04-13 14:14:40 +0000] [9] [INFO] Hello!

I’m missing the actual HTTP requests in this case. Don’t know if this is a big deal, not very experienced with building web-services yet. Is there a particular reason for not showing the HTTP requests in the console output?

I’ve tried adding the gunicorn handlers and level to the fastapi_logger, but that didn’t work (see code below).

from fastapi import FastAPI
from fastapi.logger import logger as fastapi_logger

app = FastAPI()
logger = logging.getLogger("gunicorn.error")
fastapi_logger.handlers = logger.handlers
fastapi_logger.setLevel(logger.level)


@app.get("/")
async def root():
    logger.info("Hello!")
    return "Hello, world!"

Note that the Hello! log does get shown.

OK, I found that most of the solutions here do not work for me if unmodified, but I figured out what works for me, here it is:

if "gunicorn" in os.environ.get("SERVER_SOFTWARE", ""):
    gunicorn_error_logger = logging.getLogger("gunicorn.error")
    gunicorn_logger = logging.getLogger("gunicorn")

    fastapi_logger.setLevel(gunicorn_logger.level)
    fastapi_logger.handlers = gunicorn_error_logger.handlers
    root_logger.setLevel(gunicorn_logger.level)

    uvicorn_logger = logging.getLogger("uvicorn.access")
    uvicorn_logger.handlers = gunicorn_error_logger.handlers
else:
    # https://github.com/tiangolo/fastapi/issues/2019
    LOG_FORMAT2 = "[%(asctime)s %(process)d:%(threadName)s] %(name)s - %(levelname)s - %(message)s | %(filename)s:%(lineno)d"
    logging.basicConfig(level=logging.INFO, format=LOG_FORMAT2)

This works for both uvicorn standalone and gunicorn with uvicorn workers:

uvicorn app:app --port 3000 --reload --log-level info
gunicorn -w 4 -k uvicorn.workers.UvicornWorker app:app -b 127.0.0.1:3000

Ah yes… well… if I use your code, and if I use logger in my code, it does indeed work. The problem is that I’m still not seeing the FastAPI logger output (e.g. GET / HTTP/1.1 200).

On Tue, Apr 14, 2020 at 2:26 PM Werner Robitza notifications@github.com wrote:

That would be:

from fastapi.logger import logger

Sorry for missing that.

— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub https://github.com/tiangolo/uvicorn-gunicorn-fastapi-docker/issues/19#issuecomment-613412781, or unsubscribe https://github.com/notifications/unsubscribe-auth/AHHINZZC65JQW4LYZ547F4DRMRJAPANCNFSM4JEOLYQQ .

Any news on this issue? I’m having the same problem and can’t really find a solution anywhere. When using the same setup as @slhck warning and error logs get through, but nothing below that And they are also not formatted like the other logs. So logger.warning("Connected - warning") gets logged out as Connected - warning instead of something like [2020-03-27 17:17:45 +0000] [9] [WARNING] Connected - warning.

Use this script to run your app in a Docker container?

I haven’t played too much with this image, but I have historically solved the problem like this:

import logging

# Configure the root log level and ensure all logs are sent to Gunicorn's error log.
gunicorn_error_logger = logging.getLogger("gunicorn.error")
# (you could probably just use = instead extend below)
logging.root.handlers.extend(gunicorn_error_logger.handlers)
logging.root.setLevel(gunicorn_error_logger.level)

This will set the all loggers to the same level as you configure in Gunicorn and ensure that all loggers end up in the Gunicorn error logs.

Normally I would place this s a post_fork in the Gunicorn config but you should be able to place it at the start of your application code too.

I’ve struggled with this for the past few days as well, and only just figured it out. The HTTP request info is stored in the uvicorn.access logs. In order to see that information when running uvicorn via gunicorn (lots of unicorns here!), you’ll need the following snippet in your main.py

import logging
from fastapi.logger import logger as fastapi_logger

gunicorn_error_logger = logging.getLogger("gunicorn.error")
gunicorn_logger = logging.getLogger("gunicorn")
uvicorn_access_logger = logging.getLogger("uvicorn.access")
uvicorn_access_logger.handlers = gunicorn_error_logger.handlers

fastapi_logger.handlers = gunicorn_error_logger.handlers

if __name__ != "__main__":
    fastapi_logger.setLevel(gunicorn_logger.level)
else:
    fastapi_logger.setLevel(logging.DEBUG)

This will allow the gunicorn.error logger to handle the uvicorn.access logger, thus allowing the HTTP request information to come through. You don’t even need to add --access-log - in the gunicorn command (but thank you for the suggestion, @bcb!) Big, huge thanks to @slhck and @bcb for pointing me in this direction. I hope that this helps others!

Thanks allot! it works for me!

Yes, but it won’t show the 'HTTP-GET/POST" from fastapi routes… it will only logs i put inside routes. but not native fastapi logs…

One shall make use of logging configuration via YAML https://gist.github.com/alencodes/37d590e98db7c7d2dc46cc24e708ea38

import logging
logger = logging.getLogger('CORE')
logger.info('CORE started!')
2021-09-23 13:40:21,464 INFO     CORE            CORE started!
2021-09-23 13:40:21,466 INFO     uvicorn.error   Started server process [11064]
2021-09-23 13:40:21,466 INFO     uvicorn.error   Waiting for application startup.
2021-09-23 13:40:21,467 INFO     uvicorn.error   Application startup complete.
2021-09-23 13:40:21,468 INFO     uvicorn.error   Uvicorn running on http://127.0.0.1:8000 (Press CTRL+C to quit)

I’ve struggled with this for the past few days as well, and only just figured it out. The HTTP request info is stored in the uvicorn.access logs. In order to see that information when running uvicorn via gunicorn (lots of unicorns here!), you’ll need the following snippet in your main.py

import logging
from fastapi.logger import logger as fastapi_logger

gunicorn_error_logger = logging.getLogger("gunicorn.error")
gunicorn_logger = logging.getLogger("gunicorn")
uvicorn_access_logger = logging.getLogger("uvicorn.access")
uvicorn_access_logger.handlers = gunicorn_error_logger.handlers

fastapi_logger.handlers = gunicorn_error_logger.handlers

if __name__ != "__main__":
    fastapi_logger.setLevel(gunicorn_logger.level)
else:
    fastapi_logger.setLevel(logging.DEBUG)

This will allow the gunicorn.error logger to handle the uvicorn.access logger, thus allowing the HTTP request information to come through. You don’t even need to add --access-log - in the gunicorn command (but thank you for the suggestion, @bcb!) Big, huge thanks to @slhck and @bcb for pointing me in this direction. I hope that this helps others!

Thanks allot! it works for me!

I wanted to report that I came across this problem and this solution worked for me. I also wanted to try @pawamoy run.py but I’m not sure how to integrate it with @tiangolo fastapi Docker image.

@pawamoy

Ill have to sit and look through this all again, because those changes, break my poetry run, and they break the docker deployment as well. Docker builds, but I can no longer access anything.

Thanks for the guide though.

I wrote a solution here (and the same thing, explained a bit more, in this blog post)