search

madzak / python-json-logger

Json Formatter for the standard python logger
BSD 2-Clause "Simplified" License
1.7k stars 231 forks source link

Some errors fail to be json encoded #138

Closed fchastanet closed 1 year ago

fchastanet commented 2 years ago

Hello, I have this issue

Here my configuration

LOGGING = {
    "version": 1,
    "disable_existing_loggers": False,
    "formatters": {
        "json": {
            "()": "pythonjsonlogger.jsonlogger.JsonFormatter",
            "format": "%(asctime)s %(levelname)s %(message)s",
        }
    },
    "handlers": {
        "console": {
            "class": "logging.StreamHandler",
            "stream": sys.stderr,
            "formatter": "json",
        },
    },
    "root": {
        "handlers": ["console"],
        "level": "INFO",
    },
    "loggers": {
        "api": {
            "handlers": ["console"],
            "level": "INFO",
            "propagate": False,
        },
        "client.request": {
            "handlers": ["console"],
            "level": "INFO",
            "propagate": False,
        },
        "django": {
            "handlers": ["console"],
            "level": os.getenv("DJANGO_LOG_LEVEL", "ERROR"),
            "propagate": False,
        },
    },
}

Here the problematic use case

try:
    1 / 0
except ZeroDivisionError as e:
    # TypeError: not all arguments converted during string formatting
    logger.error(e, "test exception but logger called with invalid arguments")

The result is not json encoded

--- Logging error ---
Traceback (most recent call last):
  File "/usr/src/app/api/views/recommendations.py", line 88, in log_errors
    1 / 0
ZeroDivisionError: division by zero

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/local/lib/python3.9/logging/__init__.py", line 1083, in emit
    msg = self.format(record)
  File "/usr/local/lib/python3.9/logging/__init__.py", line 927, in format
    return fmt.format(record)
  File "/opt/venv/lib/python3.9/site-packages/pythonjsonlogger/jsonlogger.py", line 194, in format
    record.message = record.getMessage()
  File "/usr/local/lib/python3.9/logging/__init__.py", line 367, in getMessage
    msg = msg % self.args
TypeError: not all arguments converted during string formatting
Call stack:
  File "/usr/local/lib/python3.9/threading.py", line 912, in _bootstrap
    self._bootstrap_inner()
  File "/usr/local/lib/python3.9/threading.py", line 954, in _bootstrap_inner
    self.run()
  File "/usr/local/lib/python3.9/threading.py", line 892, in run
    self._target(*self._args, **self._kwargs)
  File "/usr/local/lib/python3.9/socketserver.py", line 683, in process_request_thread
    self.finish_request(request, client_address)
  File "/usr/local/lib/python3.9/socketserver.py", line 360, in finish_request
    self.RequestHandlerClass(request, client_address, self)
  File "/usr/local/lib/python3.9/socketserver.py", line 747, in __init__
    self.handle()
  File "/opt/venv/lib/python3.9/site-packages/django/core/servers/basehttp.py", line 172, in handle
    self.handle_one_request()
  File "/opt/venv/lib/python3.9/site-packages/django/core/servers/basehttp.py", line 197, in handle_one_request
    handler.run(self.server.get_app())
  File "/usr/local/lib/python3.9/wsgiref/handlers.py", line 137, in run
    self.result = application(self.environ, self.start_response)
  File "/opt/venv/lib/python3.9/site-packages/django/contrib/staticfiles/handlers.py", line 76, in __call__
    return self.application(environ, start_response)
  File "/opt/venv/lib/python3.9/site-packages/django/core/handlers/wsgi.py", line 133, in __call__
    response = self.get_response(request)
  File "/opt/venv/lib/python3.9/site-packages/django/core/handlers/base.py", line 130, in get_response
    response = self._middleware_chain(request)
  File "/opt/venv/lib/python3.9/site-packages/django/core/handlers/exception.py", line 47, in inner
    response = get_response(request)
  File "/usr/src/app/core/middlewares/ThreadLocal.py", line 55, in __call__
    response = self.get_response(request)
  File "/opt/venv/lib/python3.9/site-packages/django/core/handlers/exception.py", line 47, in inner
    response = get_response(request)
  File "/usr/src/app/core/camel_case_query_params_middleware.py", line 18, in __call__
    response = self.get_response(request)
  File "/opt/venv/lib/python3.9/site-packages/django/core/handlers/exception.py", line 47, in inner
    response = get_response(request)
  File "/opt/venv/lib/python3.9/site-packages/django/utils/deprecation.py", line 114, in __call__
    response = response or self.get_response(request)
  File "/opt/venv/lib/python3.9/site-packages/django/core/handlers/exception.py", line 47, in inner
    response = get_response(request)
  File "/opt/venv/lib/python3.9/site-packages/django/utils/deprecation.py", line 114, in __call__
    response = response or self.get_response(request)
  File "/opt/venv/lib/python3.9/site-packages/django/core/handlers/exception.py", line 47, in inner
    response = get_response(request)
  File "/opt/venv/lib/python3.9/site-packages/django/utils/deprecation.py", line 114, in __call__
    response = response or self.get_response(request)
  File "/opt/venv/lib/python3.9/site-packages/django/core/handlers/exception.py", line 47, in inner
    response = get_response(request)
  File "/opt/venv/lib/python3.9/site-packages/django/utils/deprecation.py", line 114, in __call__
    response = response or self.get_response(request)
  File "/opt/venv/lib/python3.9/site-packages/django/core/handlers/exception.py", line 47, in inner
    response = get_response(request)
  File "/opt/venv/lib/python3.9/site-packages/django/utils/deprecation.py", line 114, in __call__
    response = response or self.get_response(request)
  File "/opt/venv/lib/python3.9/site-packages/django/core/handlers/exception.py", line 47, in inner
    response = get_response(request)
  File "/opt/venv/lib/python3.9/site-packages/django/utils/deprecation.py", line 114, in __call__
    response = response or self.get_response(request)
  File "/opt/venv/lib/python3.9/site-packages/django/core/handlers/exception.py", line 47, in inner
    response = get_response(request)
  File "/opt/venv/lib/python3.9/site-packages/django/utils/deprecation.py", line 114, in __call__
    response = response or self.get_response(request)
  File "/opt/venv/lib/python3.9/site-packages/django/core/handlers/exception.py", line 47, in inner
    response = get_response(request)
  File "/opt/venv/lib/python3.9/site-packages/django/utils/deprecation.py", line 114, in __call__
    response = response or self.get_response(request)
  File "/opt/venv/lib/python3.9/site-packages/django/core/handlers/exception.py", line 47, in inner
    response = get_response(request)
  File "/opt/venv/lib/python3.9/site-packages/django/core/handlers/base.py", line 181, in _get_response
    response = wrapped_callback(request, *callback_args, **callback_kwargs)
  File "/opt/venv/lib/python3.9/site-packages/django/views/decorators/csrf.py", line 54, in wrapped_view
    return view_func(*args, **kwargs)
  File "/opt/venv/lib/python3.9/site-packages/rest_framework/viewsets.py", line 125, in view
    return self.dispatch(request, *args, **kwargs)
  File "/opt/venv/lib/python3.9/site-packages/rest_framework/views.py", line 506, in dispatch
    response = handler(request, *args, **kwargs)
  File "/usr/src/app/api/views/recommendations.py", line 57, in error
    self.log_errors()
  File "/usr/src/app/api/views/recommendations.py", line 91, in log_errors
    logger.error(e, "test exception but logger called with invalid arguments")
Message: ZeroDivisionError('division by zero')
Arguments: ('test exception but logger called with invalid arguments',)
fchastanet commented 2 years ago

I fixed the issue using this sub class

class JsonFormatter(jsonlogger.JsonFormatter):
    def format(self, record):
        """
        fix issue https://github.com/madzak/python-json-logger/issues/138
        """
        # check if record.getMessage() would succeed
        if not isinstance(record.msg, dict):
            try:
                record.msg = {
                    "message": record.getMessage()
                }
            except Exception as ex:
                # ignore format exception
                if record.exc_info:
                    ex.__cause__ = record.exc_info
                outer_exception = Exception(
                    "Internal logging error : Unable to convert error message to string was raised " +
                    "during inner exception management",
                )
                outer_exception.__cause__ = ex
                try:
                    raise outer_exception
                except Exception as ex2:
                    # generate the tuple needed to format the exception
                    #record.exc_info = sys.exc_info()
                    record.exc_info = None
                    record.exc_text = traceback.format_exc()
                record.message = record.msg = {
                    "message": str(record.msg)
                }
                record.args = {}

        return super().format(record)

I'm not a python expert, I guess we can do better here

robviaas commented 1 year ago

You've thrown an exception while trying to call logger.error() itself, which bypasses the logging infrastructure and instead prints to stderr.

Specifically, the problem is on the last line. Logger.error doesn't take an exception as the first argument (msg) and a string as the second (*args):

try:
    1 / 0
except ZeroDivisionError as e:
    # TypeError: not all arguments converted during string formatting
    logger.error(e, "test exception but logger called with invalid arguments")

If you drop the e, it is fine:

...    logger.error("test exception but logger called with invalid arguments") 
{"asctime": "2022-10-25 06:31:00,387", "levelname": "ERROR", "message": "test exception but logger called with invalid arguments"}

Also possible to use the exception as an arg:

...     logger.error("test exception but logger called with invalid arguments: %s", e)
{"asctime": "2022-10-25 06:33:44,858", "levelname": "ERROR", "message": "test exception but logger called with invalid arguments: division by zero"}

Or probably best case, capture exc_info:

...     logger.error("test exception but logger called with invalid arguments: %s", e, exc_info=True)
{"asctime": "2022-10-25 06:41:44,785", "levelname": "ERROR", "message": "test exception but logger called with invalid arguments: division by zero", "exc_info": "Traceback (most recent call last):\n  File \"<stdin>\", line 2, in <module>\nZeroDivisionError: division by zero"}

Sorry this was too late to be helpful :|

mitom commented 1 year ago

I ran into this same issue and it took me a while to track down what entry was causing it because it was an infrequently logged thing happening at the same time as 10k other entries. By the logging error not being formatted, it didn't get properly parsed and each line became a separate entry in aggregation, which meant it was very difficult to track it down. The issue is certainly caused by the user (in this case, us) but I think the expectation that the json logger would handle it and emit the error in a json structure would still be valid.

There are 3 solutions I've found:

  1. set logging.raiseExceptions to False (ref)[https://docs.python.org/3/howto/logging.html#exceptions-raised-during-logging]. This is the recommended in production, although I think silently dropping them can be harmful, so I opted not to do this.
  2. Overwrite the (LogRecord)[https://docs.python.org/3/library/logging.html#logging.setLogRecordFactory] with a class that wraps getMessage in a try and updates the record if it fails. I found this limited and annoying, as you can't configure it with dictConfig (or I couldn't find a way) and it really only handles some issues, like providing the wrong number of arguments to a formatted log message (logger.info("hi %s", "thing1", "thing2")) - this happened to be my issue, but it's not exactly uniform.
  3. Do a similar thing as above and extend the formatter, this is what I ended up with - just in case it's useful for anyone: 
    
import logging
from pythonjsonlogger import jsonlogger

class ErrorHandlingJSONFormatter(jsonlogger.JsonFormatter): def format(self, record: logging.LogRecord) -> str: try: return super().format(record) except Exception as exc: record.msg = "Logging error" record.args = () record.levelno = logging.ERROR record.levelname = logging.getLevelName(logging.ERROR) record.exc_info = (type(exc), exc, exc.traceback)

        return super().format(record)


N.B. the above is still not uniformly handling every issue, it could still cause the original logging issue and it'd be probably nicer to create a new record and set only the arguments which we know for sure we can (relatively) safely set.
robviaas commented 1 year ago

A possibly simpler option is to override the handleError() method of a handler, per https://docs.python.org/3/library/logging.html#logging.Handler.handleError, but it would be required for every handler in your system, if you wanted to capture all of those log errors. It might be practical if you have only a single handler for aggregation. I've included that override, plus stdout/stderr capturing, and a global excepthook in the example below. You can experiment with them by commenting out some of the handlers. Not sure any one is the best solution (e.g. some multi-line output on stdout/stderr), but they cooperate with aggregation, and there seems to be a dearth of clear examples online.

import logging
import sys

from pythonjsonlogger import jsonlogger

# logging config setup (json output)
logger = logging.getLogger()
logHandler = logging.StreamHandler()
formatter = jsonlogger.JsonFormatter('%(asctime)s %(name)s %(message)s')
logHandler.setFormatter(formatter)
logger.addHandler(logHandler)

# set up redirect handlers
class StandardOut(object):
    def __init__(self, logname, loglevel):
        self.logger = logging.getLogger(logname)
        self.loglevel = loglevel

    def write(self, msg):
        """Strip to prevent extra spacing"""
        if (msg_clean := msg.strip()) not in ['', '\n']:
            self.logger.log(self.loglevel, msg_clean)

    def flush(self):
        pass

def handle_log_error(*args):
    logger.error('uncaught logging error', exc_info=True)

def handle_uncaught_exception(*args):
    logger.error('uncaught exception', exc_info=args)

# capture failures and std streams
sys.stdout = StandardOut('projname.daemon.stdout', logging.WARNING)
sys.stderr = StandardOut('projname.daemon.stderr', logging.ERROR)
logHandler.handleError = handle_log_error
sys.excepthook = handle_uncaught_exception

### tests

# actual logging
logger.warning('test regular logging')

# stdout, stderr
print('test stdout')
print('test stderr', file=sys.stderr)

# make a mistake with logging 
try:
    1 / 0
except ZeroDivisionError as e:
    # TypeError: not all arguments converted during string formatting
    logger.error(e, "test exception but logger called with invalid arguments")

# other unhandled error
raise RuntimeError("Test unhandled exception")
madzak commented 1 year ago

Great suggestions above!