gunicorn icon indicating copy to clipboard operation
gunicorn copied to clipboard

Gunicorn 20.0.4 Print Server Log on STDERR

Open Nitrosito opened this issue 4 years ago • 9 comments

Hi I used Gunicorn 20.0.4 conterized and running on GKE on Google, the problem is:

Server Logs Print into /dev/stderr , and Google Stackdriver (or google monitoring) interpret as ERROR LOG (logic)

My parameters to run Gunicorn:

exec gunicorn -w 3 -b 0.0.0.0:3000 --enable-stdio-inheritance --log-level debug --timeout 1000 --threads 3  --access-logfile - --error-logfile - handler:app

access-logfile with "-" for print access.log into stdout error-logifle with "-" for print error.log into stderr

Why server logs print on STDERR instead of STDOUT? for example, if i set gunicorn log level to info.. all logs print into stderr.. same for other log levels on gunicorn

Nitrosito avatar Nov 09 '20 11:11 Nitrosito

I see, by default, only 2 handler.. one for error and one for access log on gunicorn:

CONFIG_DEFAULTS = dict(
        version=1,
        disable_existing_loggers=False,

        loggers={
            "root": {"level": "INFO", "handlers": ["console"]},
            "gunicorn.error": {
                "level": "INFO",
                "handlers": ["error_console"],
                "propagate": True,
                "qualname": "gunicorn.error"
            },

            "gunicorn.access": {
                "level": "INFO",
                "handlers": ["console"],
                "propagate": True,
                "qualname": "gunicorn.access"
            }
        },
        handlers={
            "console": {
                "class": "logging.StreamHandler",
                "formatter": "generic",
                "stream": "sys.stdout"
            },
            "error_console": {
                "class": "logging.StreamHandler",
                "formatter": "generic",
                "stream": "sys.stderr"
            },
        },
        formatters={
            "generic": {
                "format": "%(asctime)s [%(process)d] [%(levelname)s] %(message)s",
                "datefmt": "[%Y-%m-%d %H:%M:%S %z]",
                "class": "logging.Formatter"
            }
        }
)

Source: https://github.com/mjjbell/gunicorn/blob/master/gunicorn/glogging.py

I create a logging.ini

[loggers]
keys=root, gunicorn.error, gunicorn.access

[handlers]
keys=console, error_console

[formatters]
keys=generic

[logger_root]
level=INFO
handlers=console

[logger_gunicorn.error]
level=INFO
handlers=error_console
propagate=0
qualname=gunicorn.error

[logger_gunicorn.access]
level=INFO
handlers=console
propagate=0
qualname=gunicorn.access

[handler_console]
class=StreamHandler
formatter=generic
args=(sys.stdout, )

[handler_error_console]
class=StreamHandler
formatter=generic
args=(sys.stdout, )

[formatter_generic]
format=%(asctime)s [%(process)d] [%(levelname)s] %(message)s
datefmt=%Y-%m-%d %H:%M:%S %Z
class=logging.Formatter

all logs go to /dev/stdout... I need to check how i can redirect to stderr only WARN,ERROR,CRITICAL

Nitrosito avatar Nov 09 '20 12:11 Nitrosito

I have the same problem. Gunicorn is logging everything into stderr and this is makes our monitoring (Datadog) explode with errors.

Screenshot 2021-08-18 at 16 27 07

If I just redirect them to stdout, we're losing information on actual errors.

Any tips on how to solve this?

rokcarl avatar Aug 18 '21 14:08 rokcarl

I think I solved it with this code. The output I get is now properly sent to stdout/stderr, but the solution is pretty convoluted. If anyone has any improvements over it, I'd be glad to hear them. That said, I think this is more of a fault with Python logging than Gunicorn. I mean, such a simple / obvious requirement: send normal messages to stdout, send errors to stderr, yet people struggle.

Screenshot 2021-08-19 at 11 08 34

BTW, if you notice above, the logs like Starting gunicorn 20.0.4 are sent to gunicorn.error. That is weird.

rokcarl avatar Aug 19 '21 09:08 rokcarl

If I am not mistaken, the problem seems quite clear to me: apart from access logs, everything else is logged through self.error_log (gunicorn.error) which outputs to stderr.

@rokcarl approach makes sense to me, I'll try to apply it to Gunicorn's glogging.py.

mindflayer avatar Feb 23 '22 21:02 mindflayer

Any updates on this?

ayyoubelamrani4 avatar Mar 10 '22 09:03 ayyoubelamrani4

Encountering this same issue now

thenayr avatar Mar 31 '22 22:03 thenayr

Encountering this same issue now

Gunicorn would need to fix this but for now the solution proposed by @rokcarl worked for me 🙌🏼

ayyoubelamrani4 avatar Apr 01 '22 05:04 ayyoubelamrani4

My PR uses the same approach used by @rokcarl. Not sure why they did not consider it. https://github.com/benoitc/gunicorn/pull/2752

mindflayer avatar Apr 01 '22 07:04 mindflayer

I made a small internal package to address this that mixes @mindflayer's and @rokcarl's solution. I can't provide you with a pip install, but you can either make your own or just add this as a separate file.

# gunicorn.conf.py
import gunicorn_logging_helper
logconfig_dict = gunicorn_logging_helper.GUNICORN_LOG_CONFIG
# gunicorn_logging_helper/__init__.py
import sys
import logging
__all__ = [
    'InfoMessageFilter',
    'ErrorMessageFilter',
    'GUNICORN_LOG_CONFIG'
]

class InfoMessageFilter(logging.Filter):
    def filter(self, record: logging.LogRecord) -> bool:
        msg = record.getMessage()
        if "GET /health/" in msg:
            return False
        return record.levelno <= logging.INFO


class ErrorMessageFilter(logging.Filter):
    def filter(self, record: logging.LogRecord) -> bool:
        return record.levelno > logging.INFO


GUNICORN_LOG_CONFIG = {
    "filters": {
        "require_message_is_info": {
            "()": "gunicorn_logging_helper.InfoMessageFilter",
        },
        "require_message_is_error": {
            "()": "gunicorn_logging_helper.ErrorMessageFilter",
        },
    },
    "handlers": {
        "console_stdout": {
            "level": "DEBUG",
            "filters": ["require_message_is_info"],
            "class": "logging.StreamHandler",
            "stream": sys.stdout,
        },
        "console_stderr": {
            "level": "DEBUG",
            "filters": ["require_message_is_error"],
            "class": "logging.StreamHandler",
            "stream": sys.stderr,
        },
    },
    "loggers": {
        "": {
            "handlers": ["console_stdout", "console_stderr"],
            "level": "INFO",
            "propagate": False
        },
        "gunicorn": {
            "handlers": ["console_stdout"],
            "level": "INFO",
            "propagate": False
        },
        "gunicorn.access": {
            "handlers": ["console_stdout"],
            "level": "INFO",
            "propagate": False
        },
        "gunicorn.error": {
            "handlers": ["console_stdout", "console_stderr"],
            "level": "INFO",
            "propagate": False
        },
    },
    "root": {
        "level": "INFO",
        "handlers": ["console_stdout", "console_stderr"],
    },
}

pedrospdc avatar Jul 20 '22 11:07 pedrospdc