Python JSON logger logs extra fields even if they're not included in format

[fgimian]

Hello,

This library outputs all extra data all the time, even when such fields don't exist in the format string.

I used a very minimal format to demonstrate the problem.

[formatter_default_json]
class = pythonjsonlogger.jsonlogger.JsonFormatter
format = %(asctime)s

some uvicorn output with this config:

{"asctime": "2020-09-12 22:52:48,944", "color_message": "Finished server process [\u001b[36m%d\u001b[0m]"}
{"asctime": "2020-09-12 22:52:48,944"}
{"asctime": "2020-09-12 22:52:48,944", "color_message": "Finished server process [\u001b[36m%d\u001b[0m]"}
{"asctime": "2020-09-12 22:52:49,024"}
{"asctime": "2020-09-12 22:52:49,024"}

Similarly with the access logs:

{"asctime": "2020-09-12 22:53:19,895", "status_code": 200, "scope": {"type": "http", "asgi": {"version": "3.0", "spec_version": "2.1"}, "http_version": "1.1", "server": ["127.0.0.1", 8000], "client": ["127.0.0.1", 58918], "scheme": "http", "method": "GET", "root_path": "", "path": "/", "raw_path": "b'/'", "query_string": "b''", "headers": [["b'user-agent'", "b'curl/7.29.0'"], ["b'host'", "b'localhost:8000'"], ["b'accept'", "b'*/*'"]], "fastapi_astack": "<contextlib.AsyncExitStack object at 0x7f208c8e8460>", "app": "<fastapi.applications.FastAPI object at 0x7f208d6bc430>", "router": "<fastapi.routing.APIRouter object at 0x7f208d6bc580>", "endpoint": "<function root at 0x7f208c8e4820>", "path_params": {}}}

You can see that these are all extra fields in uvicorn's source code:

repos/uvicorn/uvicorn/config.py:            extra={"color_message": color_message},
repos/uvicorn/uvicorn/main.py:        logger.info(message, process_id, extra={"color_message": color_message})
repos/uvicorn/uvicorn/main.py:            extra={"color_message": color_message},
repos/uvicorn/uvicorn/main.py:                extra={"color_message": color_message},
repos/uvicorn/uvicorn/protocols/http/h11_impl.py:                    extra={"status_code": status_code, "scope": self.scope},
repos/uvicorn/uvicorn/protocols/http/httptools_impl.py:                    extra={"status_code": status_code, "scope": self.scope},
repos/uvicorn/uvicorn/supervisors/basereload.py:        logger.info(message, extra={"color_message": color_message})
repos/uvicorn/uvicorn/supervisors/basereload.py:        logger.info(message, extra={"color_message": color_message})
repos/uvicorn/uvicorn/supervisors/multiprocess.py:        logger.info(message, extra={"color_message": color_message})
repos/uvicorn/uvicorn/supervisors/multiprocess.py:        logger.info(message, extra={"color_message": color_message})

Is there any way to exclude these fields from output via an INI config file at present?

Thanks Fotis

[ssheng]

I don't see an answer posted either here or in https://github.com/madzak/python-json-logger/issues/78. I will share my investigation and workaround.

JsonFormatter accepts a reserved_attrs parameter. The value of the parameter defaults to RESERVED_ATTRS. You can add additional attributes but make sure you append the original list. If not, all the ignored attributes by default will be added to the log entry.

[florimondmanca]

Same situation as OP with Uvicorn's custom record attrs being forwarded through although not mentioned in format string.

A code example of the suggestion above:

# myproject/logging.py
from pythonjsonlogger import jsonlogger

class JsonFormatter(jsonlogger.JsonFormatter):
    def __init__(self, *args, **kwargs):
        kwargs["reserved_attrs"] = ["color_message", *jsonlogger.RESERVED_ATTRS]
        super().__init__(*args, **kwargs)

Then in config:

[formatter_default_json]
class = myprojectt.logging.JsonFormatter
format = %(asctime)s