Uvicorn: Duplicate logs when using root logger with 'gunicorn -k uvicorn.workers.UvicornWorker ...'

[tlc]

Here is a small test file with minimal gunicorn and uvicorn apps. But my real interest is the log statements at the top of the file.

import logging

logging.error('TEST 1 -- LOGGING ERROR')
logging.getLogger().error('TEST 2 -- ROOT LOGGER ERROR')
logging.getLogger('foo').error('TEST 3 -- FOO LOGGER ERROR')


# minimal gunicorn app
def appG(environ, start_response):
    data = b'Hello, World!\n'
    status = '200 OK'
    response_headers = [
        ('Content-type', 'text/plain'),
        ('Content-Length', str(len(data)))
    ]
    start_response(status, response_headers)
    return iter([data])


# minimal uvicorn app
async def appU(scope, receive, send):
    assert scope['type'] == 'http'
    await send({
        'type': 'http.response.start',
        'status': 200,
        'headers': [
            [b'content-type', b'text/plain'],
        ]
    })
    await send({
        'type': 'http.response.body',
        'body': b'Hello, world!',
    })

The logs "work" when the file is run by gunicorn or uvicorn individually.

But when I use gunicorn and uvicorn together, I get doubled uvicorn logs.

$ gunicorn -k uvicorn.workers.UvicornWorker test3:appU
[2020-04-07 22:47:53 -0400] [16015] [INFO] Starting gunicorn 20.0.4
[2020-04-07 22:47:53 -0400] [16015] [INFO] Listening at: http://127.0.0.1:8000 (16015)
[2020-04-07 22:47:53 -0400] [16015] [INFO] Using worker: uvicorn.workers.UvicornWorker
[2020-04-07 22:47:53 -0400] [16018] [INFO] Booting worker with pid: 16018
ERROR:root:TEST 1 -- LOGGING ERROR
ERROR:root:TEST 2 -- ROOT LOGGER ERROR
ERROR:foo:TEST 3 -- FOO LOGGER ERROR
[2020-04-07 22:47:53 -0400] [16018] [INFO] Started server process [16018]
INFO:uvicorn.error:Started server process [16018]
[2020-04-07 22:47:53 -0400] [16018] [INFO] Waiting for application startup.
INFO:uvicorn.error:Waiting for application startup.
[2020-04-07 22:47:53 -0400] [16018] [INFO] ASGI 'lifespan' protocol appears unsupported.
INFO:uvicorn.error:ASGI 'lifespan' protocol appears unsupported.
[2020-04-07 22:47:53 -0400] [16018] [INFO] Application startup complete.
INFO:uvicorn.error:Application startup complete.

Note the last several lines are double logged with different formats. (Two handlers?)

FYI,

$ pip freeze |grep corn
gunicorn==20.0.4
uvicorn==0.11.3

I'd love a work around for both gunicorn -k uvicorn.workers.UvicornWorker ... and uvicorn ... that has an inheritable root logger.

[tlc]

Here is the work around I came up with for uniform gunicorn style logging with gunicorn -k uvicorn.workers.UvicornWorker ... and uvicorn ....

import logging


def config_logging(level=logging.INFO):

    # When run by 'uvicorn ...', a root handler is already
    # configured and the basicConfig below does nothing.
    # To get the desired formatting:
    logging.getLogger().handlers.clear()

    # 'uvicorn --log-config' is broken so we configure in the app.
    #   https://github.com/encode/uvicorn/issues/511
    logging.basicConfig(
        # match gunicorn format
        format='%(asctime)s [%(process)d] [%(levelname)s] %(message)s',
        datefmt='[%Y-%m-%d %H:%M:%S %z]',
        level=level)

    # When run by 'gunicorn -k uvicorn.workers.UvicornWorker ...',
    # These loggers are already configured and propogating.
    # So we have double logging with a root logger.
    # (And setting propagate = False hurts the other usage.)
    logging.getLogger('uvicorn.access').handlers.clear()
    logging.getLogger('uvicorn.error').handlers.clear()
    logging.getLogger('uvicorn.access').propagate = True
    logging.getLogger('uvicorn.error').propagate = True

[florimondmanca]

In terms of prior art, Uvicorn already updates its logging to use the handlers that Gunicorn provides:

https://github.com/encode/uvicorn/blob/fdb89e9cc942aaf38eb57b71172d02c868502aa3/uvicorn/workers.py#L20-L26

That being said… when I try out your repro snippet, the duplicate logs occur because of this line only:

logging.error('TEST 1 -- LOGGING ERROR')

Simplified repro example:

import logging
from starlette.applications import Starlette

logging.error('TEST')

app = Starlette()

$ gunicorn -k uvicorn.workers.UvicornWorker app:app
[2020-04-10 17:20:08 +0200] [60738] [INFO] Starting gunicorn 20.0.4
[2020-04-10 17:20:08 +0200] [60738] [INFO] Listening at: http://127.0.0.1:8000 (60738)
[2020-04-10 17:20:08 +0200] [60738] [INFO] Using worker: uvicorn.workers.UvicornWorker
[2020-04-10 17:20:08 +0200] [60740] [INFO] Booting worker with pid: 60740
ERROR:root:TEST
[2020-04-10 17:20:08 +0200] [60740] [INFO] Started server process [60740]
INFO:uvicorn.error:Started server process [60740]
[2020-04-10 17:20:08 +0200] [60740] [INFO] Waiting for application startup.
INFO:uvicorn.error:Waiting for application startup.
[2020-04-10 17:20:08 +0200] [60740] [INFO] Application startup complete.
INFO:uvicorn.error:Application startup complete.

It might be that calls to logging.error(), logging.info(), etc. set up the root logger, which gets uvicorn's logs alongside gunicorn, so they appear as duplicates. Not sure about this though…

[florimondmanca]

Yup, found the fix: add .propagate = False to uvicorn's loggers.

Gunicorn actually does this too:

https://github.com/benoitc/gunicorn/blob/8cb2bd2329a94c6f22f35f3ee5f1d725ab798101/gunicorn/glogging.py#L185-L189

This is required because I assume logging.xyz() adds a stream handler to the root logger, so having .propagate = True (the default) bubbles up uvicorn log records up to the root logger and shows them to stdout/stderr (besides being shown via uvicorn's own loggers).