madzak / python-json-logger

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

Bug in newest versions. #166

Closed jakobdo closed 1 year ago

jakobdo commented 1 year ago

Hello, when updating from 2.0.4 => 2.05 and 2.0.6, I get this error:

File "c:\Users\username\projects\project_name.venv\Lib\site-packages\pythonjsonlogger\jsonlogger.py", line 243, in format self.add_fields(log_record, record, message_dict) File "c:\Users\username\projects\project_name.venv\Lib\site-packages\pythonjsonlogger\jsonlogger.py", line 191, in add_fields self._perform_rename_log_fields(log_record) File "c:\Users\username\projects\project_name.venv\Lib\site-packages\pythonjsonlogger\jsonlogger.py", line 195, in _perform_rename_log_fields log_record[new_field_name] = log_record[old_field_name]


KeyError: 'extras'

It has worked perfect until 2.0.4, but both 2.0.5 and 2.0.6 throws above error.

And the code "calling" this code, is as simple as:

```python
# The setup
from pythonjsonlogger.jsonlogger import JsonFormatter

def get_json_formatter(extras: Dict = None):
    """
    Return JSON formatter
    :param extras: additional log record parameters
    :return: JsonFormatter object
    """
    # More info:
    # https://github.com/madzak/python-json-logger
    # https://web.archive.org/web/20201130054012/https://wtanaka.com/node/8201
    return JsonFormatter(
        "%(timestamp)%(level)%(message)%(name)",
        rename_fields={
            "timestamp": "t",
            "level": "l",
            "message": "m",
            "name": "s",
            "extras": "o",
        },
        static_fields=extras
    )

#The "call"
self.logger.info("Started...")
```

I know this is not perfect "bug" report, but feel free to ask for more info.
madzak commented 1 year ago

Hey there, what version of python are you running?

jakobdo commented 1 year ago

Python 3.11 OS: Windows

madzak commented 1 year ago

What is an example of the extras dict?

jakobdo commented 1 year ago
extras = {
    "BatchUuid": str(batch_uuid),
    "DataUuid": str(output_uuid),
    "ProcessorUuid": str(processor_uuid),
    "SubprocessID": str(subprocess_id)
}
formatter = get_json_formatter(extras)
madzak commented 1 year ago

So, it seems the problem here is "extras": "o" doesn't exist as a key but the formatter is attempting to rename it since you included it in rename_fields. static_fields will merge the Dict you provide with the current Dict that log record is working with, so if you want to rename the keys in extras = {} you need to explicitly add the key in rename_fields.

Example log:

{"t": null, "l": null, "m": "KEYERROR message", "s": "logging-test-13", "BatchUuid": "batchuuid", "DataUuid": "datauuid", "ProcessorUuid": "processoruuid", "SubprocessID": "subprocessid"}

If instead you want to maintain the Dict defined in extras you would modify your formatter like so:

def get_json_formatter(extras: Dict = None):
    """
    Return JSON formatter
    :param extras: additional log record parameters
    :return: JsonFormatter object
    """
    # More info:
    # https://github.com/madzak/python-json-logger
    # https://web.archive.org/web/20201130054012/https://wtanaka.com/node/8201
    return JsonFormatter(
        "%(timestamp)%(level)%(message)%(name)",
        rename_fields={
            "timestamp": "t",
            "level": "l",
            "message": "m",
            "name": "s",
            "extras": "o",
        },
        static_fields={"extras":extras}
    )

giving output like so:

{"t": null, "l": null, "m": "KEYERROR REPORT", "s": "logging-test-50", "o": {"BatchUuid": "batchuuid", "DataUuid": "datauuid", "ProcessorUuid": "processoruuid", "SubprocessID": "subprocessid"}}

The change from v2.0.4 to v2.0.6 iterate over the keys when requesting a rename, and with extras not being the key it will throw a KeyError. It should be noted that Logging generally silences errors as noted in the docstring of handleError in LogRecord class: "If raiseExceptions is false, exceptions get silently ignored. This is what is mostly wanted for a logging system - most users will not care about errors in the logging system, they are more interested in application errors."

jakobdo commented 1 year ago

Thanks for details. I will give it a try tomorrow.