posts/unify-logging-for-a-gunicorn-uvicorn-app/

[utterances-bot]

Unify Python logging for a Gunicorn/Uvicorn/FastAPI application - pawamoy's website

Findings, thoughts, tutorials, work. Pieces of my mind!

https://pawamoy.github.io/posts/unify-logging-for-a-gunicorn-uvicorn-app/

[ashokc]

Very useful write up. I am using pretty much your set up to generate a consistent looking logs. Thank you.

Couple of comments.

'error_log' should be 'error_logger' and the 'LOG_LEVEL' will stick.

self.error_logger.setLevel(GUNICORN_LOG_LEVEL)
self.access_logger.setLevel(GUNICORN_LOG_LEVEL)

And we can have different levels (APP_LOG_LEVEL & GUNICORN_LOG_LEVEL) in order to get better control... say 'debug' for app vs 'info' for gunicorn.

First we comment out (in 'main')

# logging.root.setLevel(APP_LOG_LEVEL)

just so we do not get unwanted extra logs from 3rd party packages...

app_logger = logging.getLogger('app')
app_logger.setLevel(APP_LOG_LEVEL)

[pawamoy]

Hi @ashokc, thanks!

'error_log' should be 'error_logger' and the 'LOG_LEVEL' will stick.

Ha, thank you very much!

just so we do not get unwanted extra logs from 3rd party packages...

Of course. In my case I did want the extra logs from all 3rd party packages 😄

[trallnag]

Your blogpost helped me a lot, thanks. Though it's interesting that for me the Uvicorn handlers all show up in logging.root.manager.loggerDict.keys(). I don't have to declare them manually. Here are my dependencies:

[tool.poetry.dependencies]
python = "^3.9"
loguru = "^0.5.3"
prettyprinter = "^0.18.0"
fastapi = "^0.61.1"
requests = "^2.24.0"
dynaconf = {extras = ["yaml"], version = "^3.1.2"}
uvicorn = "^0.12.2"

[trallnag]

*And I don't use Gunicorn workers

[pawamoy]

Oh, uvicorn 0.12.2, the latest version, I guess they have fixed their logging config so the loggers are children of the root one (I was following such an issue on their GitHub repo).

Also yeah, I got rid of gunicorn myself, and the config is much lighter then 🙂

I think I'll update my post to reflect this. Maybe I'll also add the version without gunicorn!

Anyway, glad it helped you!

[trallnag]

Btw what did the trick for me in the end was a combination of setting the interception handler from your blog post as the only Händler in logging.basicConfig and passing / overriding the default LOGGING_CONFIG Uvicorn is using with a dict that contains all the loggers Uvicorn relies on (uvicorn.error and so on) while removing the handlers from it. So it's logs get propagated up to the root logger and the interception handler.

Without the second part everything by Uvicorn was logged twice for me (once in Uvicorn default format and then again through the interception handler) even after looping through all loggers and setting the handlers to the interception handler like in your blog post.

If of interest, here are the two relevant py files:

https://github.com/trallnag/prometheus-webhook-proxy/blob/master/prometheus_webhook_proxy/main.py

https://github.com/trallnag/prometheus-webhook-proxy/blob/master/prometheus_webhook_proxy/config/logger.py

[ghost]

To support more than 2 levels of nesting for loggers, I defined the following:

def get_ancestors(logger_name):
    segments = logger_name.split(".")
    return [".".join(segments[0:n+1]) for n in range(len(segments))]

and changed the handler setting to this:

    done = set()
    logger_names = [
        *logging.root.manager.loggerDict.keys(),
        "gunicorn.access",
        "gunicorn.error",
        "uvicorn.access",
        "uvicorn.error",
    ]
    for name in logger_names:
        if name not in done:
            for ancestor in get_ancestors(name):
                done.add(ancestor)
            logging.getLogger(name).handlers = [intercept_handler]

Note that "gunicorn" and "uvicorn" are no longer in the list since their children are already there.

[pawamoy]

Thanks for sharing your solution @syk0saje!

To everyone: I've added a Uvicorn-only version to the post.

[ketanpatil3]

Tiny bit optimisation in while loop use substring for comparison[11:15] than using whole string.
subStr = logging.file[11:15]
amazing if we could remove the while loop :)

[pawamoy]

Hi @ketanpatil3, thanks! I'm not sure to get it though. Do you mean the while loop can be removed in favor of your snippet? In any case, you might want to chat with @Delgan as this code comes directly from his loguru project's documentation 🙂

[ketanpatil3]

Tiny change in the code. You don't have to compare the whole string. Tiny portion is enough: ```python substr = logging.__file__[11:15] while frame.f_code.co_filename[11:15] == substr ```

[pawamoy]

Arf, wanted to edit your comment to properly format the code, but email replies do not support MarkDown... sorry 😅
And thanks for the explanation.

[ketanpatil3]

Hi, Do you know how to contextualize information? extra = {'app':'hello','name':'myname'} logger.configure(extra=extra) #using loguru logger mylog = logging.getLogger("gunicorn.error") mylog.info('testing') mylog.error('testing error') I get the below output 2021-02-06 21:25:03.086 | INFO | __main__:run_app:125 - testing 2021-02-06 21:25:03.086 | ERROR | __main__:run_app:126 - testing error How to make it extra information in the output? I need to change the format for the above and add {extra}

…

On Sat, Feb 6, 2021 at 6:22 PM Timothée Mazzucotelli < ***@***.***> wrote: Arf, wanted to edit your comment to properly format the code, but email replies do not support MarkDown... sorry 😅 And thanks for the explanation. — You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub <#17 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AEH6WJ2JKZ2KBZWJQXFBXKDS5U3PBANCNFSM4RKYCJQQ> .

[Delgan]

Hi @pawamoy and @ketanpatil3. :)

I'm not sure of what the substr = logging.__file__[11:15] is mean to represent. The idea behind the while loop is to find the calling frame which happens to be the frame just before internal functions of builtin logging module. This is very similar to what is done in CPython actually.

It's safer to compare the whole path rather than trying to optimize comparison with a substring, because others unrelated files may actually have the same name, technically. Also, I think the slicing operation may actually be slower than comparing the whole string.

[pawamoy]

Also, I think the slicing operation may actually be slower than comparing the whole string.

I was thinking the same thing when trying to understand @ketanpatil3's suggestion. Thanks for chiming in @Delgan 🙂

@ketanpatil3 about your question on how to contextualize information, you'll have better luck asking on loguru's issue tracker, I'm not an expert here 🙂 @Delgan do you have a gitter or something for your project? Maybe you could enable discussions as well.

[Winand]

@pawamoy you mention that you got rid of gunicorn. But in Uvicorn Deployment they say: "Run uvicorn ... for local development. Run gunicorn ... for production." Do you use uvicorn's workers?
I'm trying to write my first web service with fastapi (containerized) and i'm stuck with logging now. It works fine with uvicorn but I fail to intercept gunicorn's logs started from terminal (gunicorn -k uvicorn.workers.UvicornWorker). So it's essential to start gunicorn from Python script?

[pawamoy]

At work we are deploying our apps in a Kubernetes cluster. The scaling is done using pods, therefore I only need 1 uvicorn worker per pod/container. If you are deploying your app on a bare server, then gunicorn might help, but it is not required.

[Winand]

This code works for me for both Uvicorn(0.15) and Gunicorn(20.1)+Uvicorn.

def init(lvl: str="INFO"):
    logger.configure(handlers=[
        {"sink": sys.stderr, "format": log_format, "level": lvl}
    ])
    intercept_handler = InterceptHandler()
    # level=NOTSET - loguru controls actual level
    logging.basicConfig(handlers=[intercept_handler], level=logging.NOTSET)
    for name in logging.root.manager.loggerDict.keys():
        _logger = logging.getLogger(name)
        if _logger.name.startswith("gunicorn"):
            _logger.handlers = [intercept_handler]
        else:
            # By default uvicorn.access has a handler and doesn't propagate
            # (uvicorn.access controls INFO messages on requests)
            _logger.propagate = True
            _logger.handlers = []

But it doesn't catch exceptions during main module loading. I have to use logger.catch in certain places, where an exception may happen during startup.

[esteban-gs]

I'm using the Uvicorn option only. This is a stupid question, but how do I actually log?

[pawamoy]

You can log things with standard logging.

https://docs.python.org/3/howto/logging.html#logging-basic-tutorial

In your library code:

import logging

logger = logging.getLogger(__name__)
logger.debug(msg)
logger.info(msg)
logger.warning(msg)
logger.error(msg)
logger.critical(msg)

Only, ONLY in the command line entry point (the highest possible):

import logging

logging.basicConfig(filename='example.log', encoding='utf-8', level=logging.DEBUG)
# more logging configuration

---

You can also log things with third-party libs, like loguru:

https://loguru.readthedocs.io/en/stable/overview.html#suitable-for-scripts-and-libraries

from loguru import logger

logger.debug(msg)
logger.info(msg)
logger.warning(msg)
logger.error(msg)
logger.critical(msg)

[AlyanQ]

Hey everyone, I was having a lot of problems logging properly with gunicorn + uvicorn workers but this guide helped me out a ton. One problem I'm having currently is that after changing the errorlog and accesslog to direct to logfiles, the logs aren't being written to the logfiles, they just show up in the terminal. I don't mind having the logs in the terminal but having them stored in a logfile would be nice. Anyone have any solutions? I followed the guide above exactly (for gunicorn+uvicorn)

[AlyanQ]

Nevermind, figured it out. Leaving it here for anyone else who faces the same issue. You must change the line logger.configure(handlers=[{"sink": 'sys.stdout', "serialize": JSON_LOGS}]) to logger.configure(handlers=[{"sink": 'YOUR_LOGFILE, "serialize": JSON_LOGS}])

[GroverChouT]

I figured out that I can combine your two solutions for gunicorn and uvicorn into one:

class GunicornLogger(Logger):
    def setup(self, cfg) -> None:
        handler = InterceptHandler()

        # Add log handler to logger and set log level
        self.error_log.addHandler(handler)
        self.error_log.setLevel(settings.LOG_LEVEL)
        self.access_log.addHandler(handler)
        self.access_log.setLevel(settings.LOG_LEVEL)

        # Configure logger before gunicorn starts logging
        logger.configure(handlers=[{"sink": sys.stdout, "level": settings.LOG_LEVEL}])


def configure_logger() -> None:
    logging.root.handlers = [InterceptHandler()]
    logging.root.setLevel(settings.LOG_LEVEL)

    # Remove all log handlers and propagate to root logger
    for name in logging.root.manager.loggerDict.keys():
        logging.getLogger(name).handlers = []
        logging.getLogger(name).propagate = True

    # Configure logger (again) if gunicorn is not used
    logger.configure(handlers=[{"sink": sys.stdout, "level": settings.LOG_LEVEL}])

Call configure_logger() at very top:

configure_logger()
app = FastAPI()

And use following command line to start it up:

# gunicorn
gunicorn some.package.main:app -k uvicorn.workers.UvicornWorker --logger-class some.package.logger.GunicornLogger

# uvicorn
uvicorn some.package.main:app

Thanks!

[dishwad]

This helped me a ton, thank you! I just needed to modify configure_logger() a bit to get this to work:

# Remove all log handlers and propagate to root logger
for name in logging.root.manager.loggerDict.keys():
    # Do not remove gunicorn loggers
    if "gunicorn" not in name:
        logging.getLogger(name).handlers = []
        logging.getLogger(name).propagate = True

[pawamoy]

Nice, thanks for sharing!

[Winand]

🤔my example above worked for me without creating additional class and passing it to --logger-class

[dreinon]

Hi! I'm using the uvicorn-only version and I have a problem with reload.
I have set reload to True in the server config, and I get the following log right after initializing the server:
INFO: Will watch for changes in these directories: ['parent/child/subchild']
but then it does not reload on any changes on that path parent/child/subchild.

Any idea on how to make reload work? Thanks!

[pawamoy]

I actually have the same problem 😕
I didn't get the time to investigate yet. Maybe an issue should be open on unicorn's bugtracker (if there's not already one)

[pawamoy]

OK, found a solution: encode/uvicorn#1206 (comment) 🙂

[sandys]

there is a related bug here - benoitc/gunicorn#2339

…

On Mon, 4 Jul 2022 at 12:04, Timothée Mazzucotelli ***@***.***> wrote: I actually have the same problem 😕 I didn't get the time to investigate yet. Maybe an issue should be open on unicorn's bugtracker (if there's not already one) — Reply to this email directly, view it on GitHub <#36 (reply in thread)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AAASYUYS3CGT2WXITJUA2HDVSKAZDANCNFSM52RQLQGA> . You are receiving this because you commented.Message ID: <pawamoy/pawamoy. ***@***.***>

[rfleschenberg]

Thanks! I think you should also set the loguru log level explicitly so it honors the env var:

    # configure loguru
    logger.configure(
        handlers=[{"sink": sys.stdout, "serialize": JSON_LOGS, "level": LOG_LEVEL}]
    )

[pawamoy]

Good idea, thanks!

[arturschulz]

If you're getting logging:callHandlers:1706 instead of the actual logger name and function, go the the loguru documentation, and use the newest version of the InterceptHandler class.

[pawamoy]

Thanks! I've updated the post with the new intercept handler 🙂

[dishwad]

This is my setup:
https://gist.github.com/dishwad/c9b24ee7f9c5c710bae4c2f31d8667a7