Struggling to get Django Logging and Tracing working

[proffalken]

Hi all, I'm trying to log Open Telemetry log data data from Django to Loki so I can get the traceid's required to look up stuff in Tempo and I'm struggling to get the logging library working

At the moment, my logging conf dict looks like this:

# Logging
LOGGING = {
    'version': 1,
    'disable_existing_loggers': False,
    'formatters': {
        'standard': {
            'format': '[%(asctime)s] {%(module)s} [%(levelname)s] [trace_id=%(otelTraceID)s span_id=%(otelSpanID)s resource.service.name=%(otelServiceName)s] - %(message)s',
            'datefmt': '%d-%m-%Y %H:%M:%S'
        },
    },
    'handlers': {
        'console': {
            'level': 'INFO',
            'class': 'logging.StreamHandler',
            'formatter': 'standard',
        },
        'loki': {
            'level': 'INFO',
            'class': 'logging_loki.LokiHandler',
            'url': "https://loki.server/loki/api/v1/push",
            'tags': {"app": "mventory", "env": "dev"},
            'version': "1",
        },
    },
    'loggers': {
        'root': {
            'handlers': ['loki', 'console'],
            'level': 'DEBUG',
            'propagate': True,
        },
        'django': {
            'handlers': ['loki', 'loki'],
            'level': 'DEBUG',
            'propagate': True,
        }
    }
}

And my manage.py looks like this:

#!/usr/bin/env python
"""Django's command-line utility for administrative tasks."""
import os
import sys

from opentelemetry.instrumentation.django import DjangoInstrumentor

def main():
    """Run administrative tasks."""
    os.environ.setdefault('DJANGO_SETTINGS_MODULE', 'mventory.settings')
    os.environ.setdefault("OPENTELEMETRY_PYTHON_DJANGO_INSTRUMENT", "True")
    DjangoInstrumentor().instrument()

    try:
        from django.core.management import execute_from_command_line
    except ImportError as exc:
        raise ImportError(
            "Couldn't import Django. Are you sure it's installed and "
            "available on your PYTHONPATH environment variable? Did you "
            "forget to activate a virtual environment?"
        ) from exc
    execute_from_command_line(sys.argv)


if __name__ == '__main__':
    main()

I'm pretty sure I've got my env vars setup correctly too:

export DJANGO_SETTINGS_MODULE=mventory.settings
export OTEL_PYTHON_LOG_CORRELATION="true"
export OTEL_PYTHON_DJANGO_TRACED_REQUEST_ATTRS='path_info,content_type'
export OTEL_RESOURCE_ATTRIBUTES="service.name=mventory, environment=test"
export OTEL_TRACES_EXPORTER="otlp"
export OTEL_EXPORTER_OTLP_ENDPOINT="otlpgrpc.server"
export OTEL_PYTHON_DJANGO_INSTRUMENT="True"

Logging to Loki or the console without the Open telemetry fields works fine via the python loki logger, but as soon as I add in the Open Telemetry fields it dies claiming that they don't exist:

--- Logging error ---
Traceback (most recent call last):
  File "/usr/lib/python3.9/logging/__init__.py", line 434, in format
    return self._format(record)
  File "/usr/lib/python3.9/logging/__init__.py", line 430, in _format
    return self._fmt % record.__dict__
KeyError: 'otelTraceID'

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/lib/python3.9/logging/__init__.py", line 1083, in emit
    msg = self.format(record)
  File "/usr/lib/python3.9/logging/__init__.py", line 927, in format
    return fmt.format(record)
  File "/usr/lib/python3.9/logging/__init__.py", line 666, in format
    s = self.formatMessage(record)
  File "/usr/lib/python3.9/logging/__init__.py", line 635, in formatMessage
    return self._style.format(record)
  File "/usr/lib/python3.9/logging/__init__.py", line 436, in format
    raise ValueError('Formatting field not found in record: %s' % e)
ValueError: Formatting field not found in record: 'otelTraceID'

Obviously this is because the logged isn't being initialised properly (if at all?), but I can't for the life of me work out where I should be putting the call to logging.basicConfig() as that appears to be exactly what the config-dict is for!

Have I missed a vitally important part of the OTEL docs somewhere?

[srikanthccv]

https://opentelemetry-python-contrib.readthedocs.io/en/latest/instrumentation/logging/logging.html

logging.basicConfig() can be called to set a global logging level and format. Only the first ever call has any effect on the global logger. Any subsequent calls have no effect and do not override a previously configured global logger

If your code or some other library/framework you are using calls logging.basicConfig before this integration is enabled, then this integration’s logging format will not be used and log statements will not contain tracing context. For this reason, you’ll need to make sure this integration is enabled as early as possible in the service lifecycle or your framework is configured to use a logging format with placeholders for tracing context.

I believe somewhere in your application basicConfig called before opentelemetry instrumentation.

[proffalken]

@lonewolf3739 thanks, this is the part in which I'm struggling - I can't find the bit in Django that calls logging.basicConfig, or at least I can find it in the code but there doesn't appear to be any documentation on how to override it and asking in the forums has just led to silence!

I'll keep looking for answers, as long as I know I'm on the right track!

[srikanthccv]

If I were you I would modify my python source in my virtualenv and raise exception in logging.basicConfig and look at the stack trace.

[proffalken]

Good idea, thanks, I'll give that a go

[github-actions]

This issue was marked stale due to lack of activity. It will be closed in 30 days.