apm-agent-python
apm-agent-python copied to clipboard
Published
20 hours ago •
elastic
elastic
TypeError in elasticapm.context.contextvars
I'm getting an unhandled TypeError from the set span method of the elasticapm.context.contextvars.ContextVar here
The spans variable is of type None and is throwing an unhandled exception.
I have been unable to find the root causes on this as it is happening in production sporadically without a clear way to reproduce it.
We are running this within a django/celery app with the following version numbers
django: 3.2.24 celery: 5.3.6 apm-agent-python: 6.20.0
Could we possibly add some type guards within this method or exception handling for this case?
Thanks, Jamie
Thanks for reporting, could you provide the stacktrace please? Feel free to remove any eventual information you don't want to share from the file paths.
Thanks for getting back so quickly, see a recent stack trace attatched: apm-exception.txt
2024-06-04T04:15:59.011Z Traceback (most recent call last):
2024-06-04T04:15:59.011Z File "/usr/local/lib/python3.11/site-packages/celery/app/trace.py", line 477, in trace_task
2024-06-04T04:15:59.011Z R = retval = fun(*args, **kwargs)
2024-06-04T04:15:59.011Z ^^^^^^^^^^^^^^^^^^^^
2024-06-04T04:15:59.011Z File "/usr/local/lib/python3.11/site-packages/celery_once/tasks.py", line 75, in __call__
2024-06-04T04:15:59.011Z return super(QueueOnce, self).__call__(*args, **kwargs)
2024-06-04T04:15:59.011Z ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2024-06-04T04:15:59.011Z File "/usr/local/lib/python3.11/site-packages/celery/app/trace.py", line 760, in __protected_call__
2024-06-04T04:15:59.011Z return self.run(*args, **kwargs)
2024-06-04T04:15:59.011Z ^^^^^^^^^^^^^^^^^^^^^^^^^
2024-06-04T04:15:59.011Z File "/usr/local/lib/python3.11/site-packages/celery/app/autoretry.py", line 38, in run
2024-06-04T04:15:59.011Z return task._orig_run(*args, **kwargs)
2024-06-04T04:15:59.011Z ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2024-06-04T04:15:59.011Z File "/usr/local/lib/python3.11/site-packages/elasticapm/traces.py", line 1079, in decorated
2024-06-04T04:15:59.011Z with self:
2024-06-04T04:15:59.011Z File "/usr/local/lib/python3.11/site-packages/elasticapm/traces.py", line 1085, in __enter__
2024-06-04T04:15:59.011Z return self.handle_enter(self.sync)
2024-06-04T04:15:59.011Z ^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2024-06-04T04:15:59.011Z File "/usr/local/lib/python3.11/site-packages/elasticapm/traces.py", line 1095, in handle_enter
2024-06-04T04:15:59.011Z return transaction.begin_span(
2024-06-04T04:15:59.011Z ^^^^^^^^^^^^^^^^^^^^^^^
2024-06-04T04:15:59.011Z File "/usr/local/lib/python3.11/site-packages/elasticapm/traces.py", line 351, in begin_span
2024-06-04T04:15:59.011Z return self._begin_span(
2024-06-04T04:15:59.011Z ^^^^^^^^^^^^^^^^^
2024-06-04T04:15:59.011Z File "/usr/local/lib/python3.11/site-packages/elasticapm/traces.py", line 319, in _begin_span
2024-06-04T04:15:59.011Z execution_context.set_span(span)
2024-06-04T04:15:59.011Z File "/usr/local/lib/python3.11/site-packages/elasticapm/context/contextvars.py", line 82, in set_span
2024-06-04T04:15:59.011Z self.elasticapm_spans_var.set(spans + (span,))
2024-06-04T04:15:59.011Z ~~~~~~^~~~~~~~~
2024-06-04T04:15:59.011Z TypeError: unsupported operand type(s) for +: 'NoneType' and 'tuple'
2024-06-04T04:15:59.011Z During handling of the above exception, another exception occurred:
2024-06-04T04:15:59.011Z Traceback (most recent call last):
2024-06-04T04:15:59.011Z File "/usr/local/lib/python3.11/site-packages/celery/app/trace.py", line 494, in trace_task
2024-06-04T04:15:59.011Z I, R, state, retval = on_error(task_request, exc)
2024-06-04T04:15:59.011Z ^^^^^^^^^^^^^^^^^^^^^^^^^^^
2024-06-04T04:15:59.011Z File "/usr/local/lib/python3.11/site-packages/celery/app/trace.py", line 399, in on_error
2024-06-04T04:15:59.011Z R = I.handle_error_state(
2024-06-04T04:15:59.011Z ^^^^^^^^^^^^^^^^^^^^^
2024-06-04T04:15:59.011Z File "/usr/local/lib/python3.11/site-packages/celery/app/trace.py", line 178, in handle_error_state
2024-06-04T04:15:59.011Z return {
2024-06-04T04:15:59.011Z ^
2024-06-04T04:15:59.011Z File "/usr/local/lib/python3.11/site-packages/celery/app/trace.py", line 230, in handle_failure
2024-06-04T04:15:59.011Z task.backend.mark_as_failure(
2024-06-04T04:15:59.011Z File "/usr/local/lib/python3.11/site-packages/celery/backends/base.py", line 167, in mark_as_failure
2024-06-04T04:15:59.011Z self.store_result(task_id, exc, state,
2024-06-04T04:15:59.011Z File "/usr/local/lib/python3.11/site-packages/celery/backends/base.py", line 526, in store_result
2024-06-04T04:15:59.011Z self._store_result(task_id, result, state, traceback,
2024-06-04T04:15:59.011Z File "/usr/local/lib/python3.11/site-packages/celery/backends/base.py", line 973, in _store_result
2024-06-04T04:15:59.011Z current_meta = self._get_task_meta_for(task_id)
2024-06-04T04:15:59.011Z ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2024-06-04T04:15:59.011Z File "/usr/local/lib/python3.11/site-packages/celery/backends/base.py", line 995, in _get_task_meta_for
2024-06-04T04:15:59.011Z meta = self.get(self.get_key_for_task(task_id))
2024-06-04T04:15:59.011Z ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2024-06-04T04:15:59.011Z File "/usr/local/lib/python3.11/site-packages/celery/backends/redis.py", line 376, in get
2024-06-04T04:15:59.011Z return self.client.get(key)
2024-06-04T04:15:59.011Z ^^^^^^^^^^^^^^^^^^^^
2024-06-04T04:15:59.011Z File "/usr/local/lib/python3.11/site-packages/redis/commands/core.py", line 1816, in get
2024-06-04T04:15:59.011Z return self.execute_command("GET", name)
2024-06-04T04:15:59.011Z ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2024-06-04T04:15:59.011Z File "/usr/local/lib/python3.11/site-packages/elasticapm/instrumentation/packages/base.py", line 213, in call_if_sampling
2024-06-04T04:15:59.011Z return self.call(module, method, wrapped, instance, args, kwargs)
2024-06-04T04:15:59.011Z ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2024-06-04T04:15:59.011Z File "/usr/local/lib/python3.11/site-packages/elasticapm/instrumentation/packages/redis.py", line 65, in call
2024-06-04T04:15:59.011Z with capture_span(wrapped_name, span_type="db", span_subtype="redis", span_action="query", leaf=True):
2024-06-04T04:15:59.011Z File "/usr/local/lib/python3.11/site-packages/elasticapm/traces.py", line 1085, in __enter__
2024-06-04T04:15:59.011Z return self.handle_enter(self.sync)
2024-06-04T04:15:59.011Z ^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2024-06-04T04:15:59.011Z File "/usr/local/lib/python3.11/site-packages/elasticapm/traces.py", line 1095, in handle_enter
2024-06-04T04:15:59.011Z return transaction.begin_span(
2024-06-04T04:15:59.011Z ^^^^^^^^^^^^^^^^^^^^^^^
2024-06-04T04:15:59.011Z File "/usr/local/lib/python3.11/site-packages/elasticapm/traces.py", line 351, in begin_span
2024-06-04T04:15:59.011Z return self._begin_span(
2024-06-04T04:15:59.011Z ^^^^^^^^^^^^^^^^^
2024-06-04T04:15:59.011Z File "/usr/local/lib/python3.11/site-packages/elasticapm/traces.py", line 319, in _begin_span
2024-06-04T04:15:59.011Z execution_context.set_span(span)
2024-06-04T04:15:59.011Z File "/usr/local/lib/python3.11/site-packages/elasticapm/context/contextvars.py", line 82, in set_span
2024-06-04T04:15:59.011Z self.elasticapm_spans_var.set(spans + (span,))
2024-06-04T04:15:59.011Z ~~~~~~^~~~~~~~~
2024-06-04T04:15:59.011Z TypeError: unsupported operand type(s) for +: 'NoneType' and 'tuple'
Is this log coming from celery workers right? What kind of workers are you using?
We also face a similar issue, it seems to happen when exceptions are raised and aren't properly caught - not sure if that's the exact reason, this is what I gather from our sentry events.
- Python 3.11.9
- Django 4.2.17
- Celery 5.3.1
- Elastic APM 6.23.0
I've created a pull request that'd handle the case where spans from the ContextVar is None, but I couldn't find a root cause for this to be able to make a more proper fix. Suggestions welcome if anyone has investigated this issue more in depth already
