Duplicate logs when use logging.basicConfig in application

[guyskk]

Checklist

• The bug is reproducible against the latest release or master.
• There are no similar issues or pull requests to fix it yet.

Describe the bug

When use logging.basicConfig to config logging in application, uvicorn logs will duplicate in console.

Steps to reproduce the bug

app.py:

import logging
from fastapi import FastAPI

logging.basicConfig(level=logging.INFO)

app = FastAPI(debug=True)

run it:

uvicorn app:app

Expected behavior

expect no duplicate logs.

Actual behavior

uvicorn.error logs duplicated:

INFO:     Started server process [85610]
INFO:uvicorn.error:Started server process [85610]
INFO:     Waiting for application startup.
INFO:uvicorn.error:Waiting for application startup.
INFO:     Application startup complete.
INFO:uvicorn.error:Application startup complete.
INFO:     Uvicorn running on http://127.0.0.1:8000 (Press CTRL+C to quit)
INFO:uvicorn.error:Uvicorn running on http://127.0.0.1:8000 (Press CTRL+C to quit)

Debugging material

I think the uvicorn logger should not propagate, because it already handled by uvicorn handler. And the behavior of gunicorn is no duplicate logs.

Add "propagate": False to https://github.com/encode/uvicorn/blob/master/uvicorn/config.py#L107 can fix the issue.

"uvicorn": {"handlers": ["default"], "level": "INFO", "propagate": False},

Environment

Running uvicorn 0.15.0 with CPython 3.9.7 on Darwin

Additional context

Maybe related: #614

[euri10]

yes sounds sensible, fancy throwing a PR @guyskk ?

[guyskk]

@euri10 👌 here is the PR: #1288

[gretkierewicz]

...

Debugging material

I think the uvicorn logger should not propagate, because it already handled by uvicorn handler. And the behavior of gunicorn is no duplicate logs.

Add "propagate": False to https://github.com/encode/uvicorn/blob/master/uvicorn/config.py#L107 can fix the issue.
...

Adding propagate = False is not a fix. It turs off all uvicorn's logs.

[yuval-illumex]

Any Update on this one? It's really annoying :(

[matthew-viglione]

Has anyone identified a useful workaround in the meantime?

[guyskk]

Adding propagate = False is not a fix. It turs off all uvicorn's logs.

@gretkierewicz That's not correct, propagate = False just stop propagate logs to ancestors, the log message still handled by uvicorn log handers.

Python Docs also note that If you attach a handler to a logger and one or more of its ancestors, it may emit the same record multiple times. :

https://docs.python.org/3/library/logging.html#logging.Logger.propagate

propagate
If this attribute evaluates to true, events logged to this logger will be passed to the handlers of higher level (ancestor) loggers, in addition to any handlers attached to this logger. Messages are passed directly to the ancestor loggers’ handlers - neither the level nor filters of the ancestor loggers in question are considered.

If this evaluates to false, logging messages are not passed to the handlers of ancestor loggers.

The constructor sets this attribute to True.

Note
If you attach a handler to a logger and one or more of its ancestors, it may emit the same record multiple times. In general, you should not need to attach a handler to more than one logger - if you just attach it to the appropriate logger which is highest in the logger hierarchy, then it will see all events logged by all descendant loggers, provided that their propagate setting is left set to True. A common scenario is to attach handlers only to the root logger, and to let propagation take care of the rest.

[bachya]

@matthew-viglione My workaround in the meantime has been:

uvicorn_logger = logging.getLogger("uvicorn")
uvicorn_logger.removeHandler(uvicorn_logger.handlers[0])

[Kludex]

• This was closed by Set propagate to False on "uvicorn" logger #1288. It will be available on uvicorn version 0.19.0.