Duplicate log messages from RequestMiddleware without explicitly adding logger

[kieran-sf]

Hello hope you are doing well,

I am doing some overhaulling to logging system in my application and I have noticed that I am getting duplicate logs from the RequestMiddleware when I don't add it explictily to my logging config loggers.

The duplicate logs look like this:

My formatted log
timestamp='2024-12-19T20:16:50.602239Z' level='info' event='request_started' logger='django_structlog.middlewares.request' request='GET /api/projects/fit4/' user_agent='PostmanRuntime/7.37.3' ip='172.18.0.1' request_id='f36ec852-455b-4635-9111-b52e3635479b' filename='request.py' module='request' lineno=201 func_name='prepare' pathname='/usr/local/lib/python3.9/site-packages/django_structlog/middlewares/request.py' inspected=True

The duplicate
{'request': 'GET /api/projects/fit4/', 'user_agent': 'PostmanRuntime/7.37.3', 'event': 'request_started', 'ip': '172.18.0.1', 'request_id': 'f36ec852-455b-4635-9111-b52e3635479b', 'logger': 'django_structlog.middlewares.request', 'level': 'info', 'timestamp': '2024-12-19T20:16:50.602239Z', 'filename': 'request.py', 'module': 'request', 'lineno': 201, 'func_name': 'prepare', 'pathname': '/usr/local/lib/python3.9/site-packages/django_structlog/middlewares/request.py', 'inspected': True}

My django settings look like:

    MIDDLEWARE = (
        "my_app.core.middleware.cookie_stuff",
        "django_guid.middleware.guid_middleware",
        "django_structlog.middlewares.RequestMiddleware",
        ...
    )

@property
    def LOGGING(self):
        return {
            "version": 1,
            "disable_existing_loggers": False,
            "root": {
                "handlers": ["console"],
                "level": "INFO"
            },
            "formatters": {
                "kv": {
                    "()": structlog.stdlib.ProcessorFormatter,
                    "processors": [
                        structlog.stdlib.ProcessorFormatter.remove_processors_meta,
                        structlog.processors.KeyValueRenderer(key_order=['timestamp', 'level', 'event', 'logger'])
                    ],
                    "foreign_pre_chain": [
                        structlog.stdlib.ExtraAdder()
                    ]
                }
            },
            "handlers": {
                "console": {
                    "class": "logging.StreamHandler",
                    "formatter": "kv",
                },
                "null": {
                    "class": "logging.NullHandler"
                }
            },
            "loggers": {
                "django_structlog": {
                    "level": "INFO",
                },
                # "django_structlog.middlewares": {
                #     "level": "INFO",
                # },
                # Uncommentting this removes the duplication
                # "django_structlog.middlewares.request": {
                #     "level": "INFO",
                # },
                "my_app": {
                    "level": "INFO",
                },
                "celery": {
                    "level": "INFO",
                },
            }
        }

    base_structlog_processors = [
        structlog.contextvars.merge_contextvars,
        structlog.stdlib.add_logger_name,
        structlog.stdlib.add_log_level,
        structlog.stdlib.filter_by_level,
        # Perform %-style formatting.
        structlog.stdlib.PositionalArgumentsFormatter(),
        # Add a timestamp in ISO 8601 format.
        structlog.processors.TimeStamper(fmt="iso"),
        structlog.processors.StackInfoRenderer(),
        # If some value is in bytes, decode it to a unicode str.
        structlog.processors.UnicodeDecoder(),
        # Add callsite parameters.
        structlog.processors.CallsiteParameterAdder(
            {
                structlog.processors.CallsiteParameter.FILENAME,
                structlog.processors.CallsiteParameter.FUNC_NAME,
                structlog.processors.CallsiteParameter.LINENO,
                structlog.processors.CallsiteParameter.MODULE,
                structlog.processors.CallsiteParameter.PATHNAME,
            }
        ),
    ]

    base_structlog_formatter = [structlog.stdlib.ProcessorFormatter.wrap_for_formatter]

    structlog.configure_once(
        processors=base_structlog_processors + base_structlog_formatter,  # type: ignore
        logger_factory=structlog.stdlib.LoggerFactory(),
        cache_logger_on_first_use=True,
    )

Now I am still a logging novice so this could very well be a misconfiguration on my end but understanding of the logging system was that since I am already adding django_structlog to my loggers and it doesn't have its own handler but uses the root logger then any sub path of django_structlog should all be flowing through my formatting.

Thanks for your time.

[jrobichaud]

maybe you need to add "propagate": False

See: this issue: #483 (comment)

[kieran-sf]

Oh I do have the django loggers in my config but the duplicate is coming from the django_structlog.middlewares.request logger. Adding "propagate": False to either of the 3 django_structlog stops all the middleware logging.

"django.request": {
      "handlers": ["null"],
      "propagate": False,
  },
  "django.server": {
      "handlers": ["null"],
      "propagate": False,
  },

This is a reordered version slimmed down version of the duplicate requests

My formatted log
timestamp='2024-12-19T20:16:50.602239Z' event='request_started' logger='django_structlog.middlewares.request' request_id='f36ec852-455b-4635-9111-b52e3635479b' 

The duplicate
{'timestamp': '2024-12-19T20:16:50.602239Z', 'event': 'request_started', 'logger': 'django_structlog.middlewares.request', 'request_id': 'f36ec852-455b-4635-9111-b52e3635479b'}

[jrobichaud]

in your code (or any of your library) do you do:

import logging

logging.info("something")

As noted in this issue, the root logger breaks logging in some situations:
#274

[kieran-sf]

I don't see any in my code base, but looking at the other bug it seems like any library I import could be doing this. I tired following that bug and changing my config:

"": {
          "handlers": ["null"],
          "level": "INFO",
      },
      "django_structlog": {
          "level": "INFO",
          "handlers": ["console"]
      },
      "my_app": {
          "handlers": ["console"],
          "level": "INFO",
      },

I also tried setting disable_existing_loggers both True and False I am still getting the duplicates. It is also happening with the celery receivers.

I don't imagine you know a good way to see where this other root logger might be originating?

I appreciate you taking time out of your day to look at this thank you.

[jrobichaud]

try to isolate the problem by methodically:
1: remove apps from installed apps and commenting code using third party library.
2: check if the problem still occur
3: repeat

In the end only the problem will remain.

[jrobichaud]

To debug I would put a breakpoint exactly at these lines:
https://github.com/python/cpython/blob/8d61a71f9c81619e34d4a30b625922ebc83c561b/Lib/logging/__init__.py#L2167
https://github.com/python/cpython/blob/8d61a71f9c81619e34d4a30b625922ebc83c561b/Lib/logging/__init__.py#L2183
https://github.com/python/cpython/blob/8d61a71f9c81619e34d4a30b625922ebc83c561b/Lib/logging/__init__.py#L2201
https://github.com/python/cpython/blob/8d61a71f9c81619e34d4a30b625922ebc83c561b/Lib/logging/__init__.py#L2211
https://github.com/python/cpython/blob/8d61a71f9c81619e34d4a30b625922ebc83c561b/Lib/logging/__init__.py#L2221
https://github.com/python/cpython/blob/8d61a71f9c81619e34d4a30b625922ebc83c561b/Lib/logging/__init__.py#L2231