Gunicorn duplicates logs

[klaipher]

I need to run gunicorn directly from code, because my app has its own CLI. Also, I want to make all log the same format. Before that I used loguru, but I had got the same problem, when I try to pass logconfig_dict. I thought the problem was in loguru and try to rewrite code to pure python and gunicorn and I have got the same bug.

Python 3.8.5 gunicorn 20.0.4 Ubuntu 20.04.1 LTS (GNU/Linux 5.4.0-59-generic x86_64)

import gunicorn.app.base

GUNICORN_LOGGING_FORMAT = dict(
    formatters={
        "generic": {
            "format": "%(levelname)s %(funcName)s %(lineno)d %(message)s"
        }
    }
)


def app(environ, start_response):
    """Simplest possible application object"""
    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])


class GunicornApplication(gunicorn.app.base.BaseApplication):

    def __init__(self, app, options=None):
        self.options = options or {}
        self.application = app
        super().__init__()

    def load_config(self):
        config = {key: value for key, value in self.options.items()
                  if key in self.cfg.settings and value is not None}
        for key, value in config.items():
            self.cfg.set(key.lower(), value)

    def load(self):
        return self.application


options = {
    "loglevel": "info",
    "logconfig_dict": GUNICORN_LOGGING_FORMAT

}
GunicornApplication(app, options=options).run()

[benoitc]

you are probably passing to 2 handlers the lpg by overrwriting the doc like you do. The right handler to overwrite is gunicorn.error . Maybe https://docs.gunicorn.org/en/stable/deploy.html#logging will help.

[klaipher]

you are probably passing to 2 handlers the lpg by overrwriting the doc like you do. The right handler to overwrite is gunicorn.error . Maybe https://docs.gunicorn.org/en/stable/deploy.html#logging will help.

GUNICORN_LOGGING_FORMAT = dict(
    root={"level": "INFO", "handlers": []},
    formatters={
        "generic": {
            "format": "%(levelname)s %(funcName)s %(lineno)d %(message)s"
        }
    }
)

I didn't understand your answer and what must I do. "handlers": [] I did that. Now it does not duplicate log. I would be glad if you could show me how to do it right. I want the format of all the gunicorn logs to match my format

[benoitc]

First you probably shouldn't change directly the logs format until. This can be done like with any server by using an external toolthat will feed your logging system. There will be a way in next release to change this format directly but it's not supported yet.

But if you really want to do it you need to replace the gunicorn.errors handler format. Have a look on the doc but also here to see what to override. Hope it helps.

[benoitc]

@klaipher any news? did you manage to fix your issue with the suggestion above?

[klaipher]

@klaipher any news? did you manage to fix your issue with the suggestion above?

No, all in all I use my solution, because any overriding of logging settings without overriding root handlers leads to duplicating logs

[benoitc]

I tested it. Replacing the format for different handler works. Another simple way to do it is to override the logging class by your own. as the note suggest it is not advised to interfere with gunicorn logging. It would be better to patch Gunicorn to provide a way to change this format like it is done for the access log.

[dbalabka]

@benoitc I might be wrong, but it seem that Gunicorn has a bug in Logger configuration. The default configuration in CONFIG_DEFAULTS constant contains "propagate": True, https://github.com/benoitc/gunicorn/blob/master/gunicorn/glogging.py#L57 https://github.com/benoitc/gunicorn/blob/master/gunicorn/glogging.py#L64

In the same time in the class constructor there is hardcoded logic to set propagate to False: https://github.com/benoitc/gunicorn/blob/master/gunicorn/glogging.py#L187 https://github.com/benoitc/gunicorn/blob/master/gunicorn/glogging.py#L189

If a developer doesn't provide logconfig_dict or logconfig propagation is disabled and CONFIG_DEFAULTS will be ignored: https://github.com/benoitc/gunicorn/blob/master/gunicorn/glogging.py#L231 https://github.com/benoitc/gunicorn/blob/master/gunicorn/glogging.py#L243

In the above example, @klaipher provides logconfig_dict:

options = {
    "loglevel": "info",
    "logconfig_dict": GUNICORN_LOGGING_FORMAT

}
GunicornApplication(app, options=options).run()

@klaipher see duplicates logs because console renders logs from stdout and stderr.

@benoitc you already have fixed the similar issue in: https://github.com/benoitc/gunicorn/issues/574 by disabling propagate in the class constructor: https://github.com/benoitc/gunicorn/commit/141aa9d4cf6ac50386e022a08c742e28d8c17905

I have prepared pull request that from my POV should fix this issue: https://github.com/benoitc/gunicorn/pull/2499

[tilgovi]

I think @dbalabka is correct and I have thought about this change before but forgot to ever make it. Our dictionary config defaults could match our defaults, where we disable propagation.

On the other hand, dictionary config is advanced and explicit configuration. The least surprising thing might be to leave propagation at the Python default (True) as we have it now. Probably both decisions are likely to surprise some users.

[dbalabka]

@tilgovi I see your point and the worries about that this bug became a feature. Still, I would like to suggest to change the default behaviour because it is a bug and you agreed with it. The question is how to change it properly w/o affect existing users.

One way it to bump major version of gunicorn and put the note into release notes about BC break. Still, I think it is not BC break and not much people override the whole config and even less expect logs propagation. We can check using Github search. Just quick search shows that there are multiple cases when people disabled propagation: https://github.com/search?q=logconfig_dict+%22propagate+False%22&type=code

Another way is to refactor handlers. You need only one handler on the root level. It is incorrect to set multiple handlers with enabled propagation: https://github.com/benoitc/gunicorn/blob/master/gunicorn/glogging.py#L56 https://github.com/benoitc/gunicorn/blob/master/gunicorn/glogging.py#L63 https://github.com/benoitc/gunicorn/blob/master/gunicorn/glogging.py#L52

It is how handlers should be set up according to Python documentation and that why propagate is enabled by default:

 ...A common scenario is to attach handlers only to the root logger, and to let propagation take care of the rest....

If I understand correctly, there might be two scenarios:

1. Root-level handlers only with enabled propagation.
2. Dedicated handlers for each logger with disabled propagation.

[nihalsharma]

Somehow, I am facing this duplication thing. I have tried all the possible ways to stop this, but I always see duplicates INFO statements. The issue is when an exception occurs, the info is printed twice, otherwise, it's fine. I am not sure how to solve this.

[GuillaumeDesforges]

Had double logs. This answer helped me: https://github.com/benoitc/gunicorn/issues/2250#issuecomment-582513267

[james77777778]

I also faced the duplicated logs and I fixed by following:

# logconfig_dict: remove handlers of root
logconfig_dict = dict(
    version=1,
    disable_existing_loggers=False,
    root={'level': 'INFO', 'handlers': []},
    formatters={
        'generic': {
            'format': '%(asctime)s [%(process)d] [%(levelname)s] %(message)s',
            'datefmt': '[%Y-%m-%d %H:%M:%S %z]',
            'class': 'logging.Formatter'
        }
    },
    loggers={
        'gunicorn.error': {
            'level': 'INFO',
            'handlers': ['console'],
            'propagate': False,
            'qualname': 'gunicorn.error'
        }
    },
    handlers={
        'console': {
            'class': 'logging.StreamHandler',
            'formatter': 'generic',
            'stream': 'ext://sys.stdout'
        }
    }
)

Finally, I didn't see duplicated logs from docker container logs.

[VP2405]

Had the same problem. Passing from gunicorn==20.0.0 to gunicorn==20.0.4 solved the issue.