Polyconseil/django-cid

Not able to log with: KeyError: 'cid' ... Arguments: ()

izmailoff opened this issue · 3 comments

Hi, I might have come across a bug, please help me to validate this issue.

Environment:

Python 3.6
django-cid==2.0
django==2.2.8

Apache with mod_wsgi

I followed installation and configuration docs step by step. Getting an error when trying to log with CID:

--- Logging error ---
Traceback (most recent call last):
  File "/usr/lib/python3.6/logging/__init__.py", line 994, in emit
    msg = self.format(record)
  File "/usr/lib/python3.6/logging/__init__.py", line 840, in format
    return fmt.format(record)
  File "/usr/lib/python3.6/logging/__init__.py", line 580, in format
    s = self.formatMessage(record)
  File "/usr/lib/python3.6/logging/__init__.py", line 549, in formatMessage
    return self._style.format(record)
  File "/usr/lib/python3.6/logging/__init__.py", line 391, in format
    return self._fmt % record.__dict__
KeyError: 'cid'
Call stack:
  File "...mysite/lib/python3.6/site-packages/django/core/handlers/wsgi.py", line 141, in __call__
    response = self.get_response(request)
  File "...mysite/lib/python3.6/site-packages/django/core/handlers/base.py", line 75, in get_response
    response = self._middleware_chain(request)
  File "...mysite/lib/python3.6/site-packages/django/core/handlers/exception.py", line 34, in inner
    response = get_response(request)
  File "...mysite/lib/python3.6/site-packages/cid/middleware.py", line 38, in __call__
    response = self.get_response(request)
  File "...mysite/lib/python3.6/site-packages/django/core/handlers/exception.py", line 34, in inner
    response = get_response(request)
  File "...mysite/lib/python3.6/site-packages/django/core/handlers/base.py", line 113, in _get_response
    response = wrapped_callback(request, *callback_args, **callback_kwargs)
  File "...mysite/lib/python3.6/site-packages/django/utils/decorators.py", line 142, in _wrapped_view
    response = view_func(request, *args, **kwargs)
  File "...mysite/myapis/some_apis.py", line 14, in do_something
    log.info(f'META!!!!: {request.META}.')

Somehow CID is not able to find the header which is set by Apache. To troubleshoot I print headers from a django view in 2 ways:

  1. log.info(f'HEADERS!!!!: {request.headers}.') gives: 'X-Correlation-Id': 'WGZkYUYxZXRGc3h0NGtmRldJSlRzUUFBQ UFN'

  2. log.info(f'META!!!!: {request.META}.') gives: 'HTTP_X_CORRELATION_ID': 'WGZkYUYxZXRGc3h0NGtmRldJSlRzUUFBQUFN'

So the header is clearly present in the request. I tried both settings:
CID_HEADER = 'X-Correlation-Id'
or
CID_HEADER = 'HTTP_X_CORRELATION_ID'
and got the same error.

The rest of the Django settings is the same as in instructions:

'formatters': {
        'default': {
            'format': '[cid: %(cid)s] - %(asctime)s - %(name)s - %(levelname)s - %(threadName)s - %(message)s',
        },
...
    'handlers': {
        'console': {
            'class': 'logging.StreamHandler',
            'formatter': 'default',
        },
...
'filters': {
        'correlation': {
            '()': 'cid.log.CidContextFilter'
        },
    },
...
'mysite': {
            'level': LOGLEVEL,
            'handlers': ['console'],
            'filters': ['correlation'],
            'propagate': True,
        },

Thanks,
Alex

dbaty commented

Hello.

I am afraid I cannot reproduce this issue. I tried by tweaking the sandbox project included in django-cid.

A few ideas:

  • double check that your view is really using the mysite logger that you defined in your settings. For example, try to tweak the log level (in your view or in the settings) to make sure that the log messages are shown (or not shown) accordingly;

  • double check your settings, perhaps by looking at the differences between your settings and the settings of the sandbox project. I know it can be tedious on a real, big project.

Hi @dbaty , sorry for the late reply. I suspect Django is not configuring logging correctly in multithreaded application. I didn't get around to debug it properly yet, but I'm planning to do it shortly. Please keep this issue open for now so we can comment on it.

Apologies, not able to troubleshoot this at the moment. Will close the ticket. If I manage to get clear details I'll reopen if needed. Thanks!