Intermittent Client AttributeError with Django integration

[ccorbacho]

Describe the bug:

We are sometimes seeing this traceback via Sentry coming from the elasticapm agent with the Django integration:

AttributeError: 'Client' object has no attribute 'get_data_from_request'
  File "elasticapm/contrib/django/middleware/__init__.py", line 179, in process_response
    elasticapm.set_context(
  File "elasticapm/traces.py", line 848, in set_context
    data = data()
  File "elasticapm/contrib/django/middleware/__init__.py", line 180, in <lambda>
    lambda: self.client.get_data_from_request(request, constants.TRANSACTION), "request"

To Reproduce

Environment (please complete the following information)

• OS: Linux
• Python version: 3.8.9
• Framework and version [e.g. Django 2.1]: Django 3.1.7
• APM Server version: 7.6
• Agent version: 6.1.1

Additional context

There is nothing else in the Sentry exception that gives more context - from the exception and a quick look at the agent code, I imagine there must be some code path that allows the base Client object to be passed through instead of DjangoClient when using the Django integration?

Most of these exceptions (according to Sentry) are coming from requests to a container health check endpoint, which doesn't make any DB connections or do anything with models, it's just a simple view that returns a string to confirm that Gunicorn is up and running and can serve requests.

[ccorbacho]

From reviewing the Sentry data, this only started after we upgraded the ElasticAPM Python client from 6.0.0 to 6.1.0.

[myrodgkim]

I got the same error.

Current setup

OS: Linux Container
Python version: 3.7.7
Framework and version [e.g. Django 2.1]: Django 2.2.16
APM Server version: 7.9.1
Agent version: 6.1.2

Additionally, Transaction metadata doesn't show service.framework.name and service.framework.version and User and etc.

Working setup (before upgrading to 6.1.2)

I was using agent 5.8.0. it worked fine. except

# this isn't working, only email is updated. user_id, username is missing.
elasticapm.set_user_context(username=user.name, email=user.email, user_id=user.id)
# the URL is called from third party, and called without authorization header. So, I manually get user info from post data, and wanted to inject into elasticapm.

So, I upgraded to 6.1.2

[ccorbacho]

My suspicion is that the changes in #1043 are the root cause of this bug.

The old implementation of elasticapm.contrib.django.get_client() before this change was much more defensive, and would check if the cached object was of the expected type passed in (i.e. DjangoClient), and replace it if it was not.

In the PR above, that has been refactored so if there is any cached client object, the code always returns that - even if somehow the Client object has been instantiated incorrectly with the base 'Client' object and not DjangoClient (which is presumably happening somehow).

@basepi Can you comment on the above? I think the code before your PR was handling a case where somehow the global client object is being instantiated or changed to the wrong type. On our environments here, we are seeing huge numbers of the stack trace above since we deployed 6.1.1 with your change.

[beniwohli]

Hey @ccorbacho and @myrodgkim, thanks for reporting this issue, and sorry about the slow reply! I think your analysis is spot on!

One of the places where we may instantiate another agent is elasticapm.handlers.logging.LoggingHandler and elasticapm.contrib.django.handlers.LoggingHandler. Are you per chance using one of those in your logging setup? If yes, would you mind posting your (redacted) logging configuration here?

[beniwohli]

I pushed a small change to a branch (#1158) that logs the stack trace when the client is set more than once. This could help debugging where the "naked" Client instance is created. You can install it by running something like

pip install https://github.com/beniwohli/apm-agent-python/archive/refs/heads/log-set_client-with-stack.zip\#egg\=elastic-apm\=\=100

It's logged at DEBUG level, using the elasticapm logger, so you might have to update your logging configuration to see the message.

If you could try to run this in a dev environment and report back any stack traces, that would help a lot!

[ccorbacho]

@beniwohli In settings.py we do the following:

LOGGING['loggers']['elasticapm'] = {'handlers': ['console'], 'level': 'INFO', 'propagate': False}

[ccorbacho]

@beniwohli I got to the bottom of this on our side, using your debug package to find the problem.

It was a bug in our code - we had a decorator for non-Django code, that instantiated a Client object, and that wasn't checking that the global ElasticAPM Client object existed. With the old version of ElasticAPM, this was just working because the old get_client() behaviour would see the wrong type and reset it. We've fixed it to not do this now, and it seems the error has stopped completely.

I'm going to close this (as clearly the bug is on our side), but I think it would be a good idea to change the debug about re-initializing the Client object to a warning level message, and add the stack trace by default, so that any client code can spot and fix this (I'm guessing eventually this should raise an exception in a future release, as I can't see why client code should be trying to re-initialize the Client object).