python-json-logger

python-json-logger copied to clipboard

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

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.

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