[QUESTION] How to do logging in a FastApi container, any logging does not appear

[PunkDork21]

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

[slhck]

I have a similar issue. Using this image, I don't see any FastAPI logs on STDOUT in Docker Compose.

The app is something like this:

from fastapi.logger import logger
…
logger.info("Booted up")

if __name__ == "__main__":
    import uvicorn

    uvicorn.run("main:app", host="0.0.0.0", port=3002, reload=True, debug=True)

When I run it with python3 app/main.py, I see a quite detailed log:

INFO: Uvicorn running on http://0.0.0.0:3002 (Press CTRL+C to quit)
INFO: Started reloader process [99565]
INFO: Booted up
INFO: Started server process [99581]
INFO: Waiting for application startup.
INFO: Application startup complete.

But when I run the app in Docker Compose with LOG_LEVEL=debug set in the environment, and using the start_reload.sh entrypoint, I only see:

INFO: Uvicorn running on http://0.0.0.0:80 (Press CTRL+C to quit)
INFO: Started reloader process [1]
INFO: Started server process [9]
INFO: Waiting for application startup.
DEBUG: None - ASGI [1] Started
DEBUG: None - ASGI [1] Sent {'type': 'lifespan.startup'}
DEBUG: None - ASGI [1] Received {'type': 'lifespan.startup.complete'}

[slhck]

Umair, I'm not sure if that is the same issue. When a Docker container writes to STDOUT and is running in the background (that is, detached), you can only see that via logs.

[JCHHeilmann]

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.

[tyler46]

@JCHHeilmann have you had a look on this issue?

[JCHHeilmann]

@tyler46 yes , and I've just tried it that way again. The info log doesn't show up without setting the LOG_LEVEL to debug. But the default is info, so it should. Or am I missing something?

[slhck]

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.

[slhck]

PS: I got this idea from this blog post: https://medium.com/@trstringer/logging-flask-and-gunicorn-the-manageable-way-2e6f0b8beb2f

[janheindejong]

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?

[slhck]

@janheindejong You have not set the logging handler (logger.handlers = gunicorn_logger.handlers). Does that fix the issue?

[janheindejong]

Hmm... am I not using the gunicorn logger? This line basically makes the logger variable point to the gunicorn one, right?

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

It's not that I'm not getting any output from the logger (see the Hello! line). It's just that the HTTP requests are not shown, which they are if I run the app outside the container.

[slhck]

Well, if you set logger to be the gunicorn logger, you can pass your info logs through it, and they will appear. However, FastAPI itself will not know about that and still sends its (HTTP header) logs to its own logger. That means you have to tell FastAPI to use the gunicorn logger handlers. Please try adding that line and see if it works.

[janheindejong]

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.

[slhck]

Hm, do you need the explicit import of fastapi.logger? I thought it worked without that — at least it did for my example. To be honest, I am not sure how this is all supposed to work internally. I just fumbled around with it until it worked. Perhaps you can try using my setup? I set the handlers differently.

[janheindejong]

Hmm... yeah I'm afraid that doesn't work. There's no instance of logger yet if I use your example. How did you create the instance?

[slhck]

That would be:

from fastapi.logger import logger

Sorry for missing that.

[janheindejong]

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 [email protected] 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 .

[itaymining]

i also have this problem.. any new?

[slhck]

@itaymining Have you tried my solution from above?

[itaymining]

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...

[HedgeShot]

I got the same problem occurring since yesterday. Before that, I could see everything in the logs (routes called, response code etc). Now i only see print() after I do some change in the code & the app auto-reloads... I don't even see errors on "internal server error" when calling a broken route. Very strange!

EDIT: I was import "logging" module to use on a few endpoint & i guess the config was messing with the fastapi logger. Removing this fixed my issue.

[JCHHeilmann]

I'm also still having this issue. I've stopped using this docker image as a result.

Actually it might be an issue with uvicorn. I have build my own minimal "start fast-api with uvicorn" docker image and it had the same problem.

[bcb]

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

--access-logfile -

[janheindejong]

I also think it is a gunicorn thing... I also posted it here: https://github.com/tiangolo/fastapi/issues/1268

[jacob-vincent]

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!

[itaymining]

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!

[bcb]

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.

[gsph]

https://github.com/tiangolo/fastapi/issues/1276#issuecomment-615877177

[JHBalaji]

@bcb Maybe this implementation And there is this.

[ms042087]

The above solution does not work for me. Anyone has other solution? Thanks!

docker-compose.yml

version: "3"
services:
  api:
    build:
      context: ./
      dockerfile: Dockerfile
    environment:
      - DEBUG = 1
      - PYTHONUNBUFFERED = 1
      - LOGLEVEL = DEBUG
    image: result/latest

main.py

from fastapi import FastAPI
from fastapi.logger import logger
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)

app = FastAPI()
@app.get("/")
def dashboard():
        return{"Dashboard":"Homepage"}

[pawamoy]

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