apm-agent-python

apm-agent-python copied to clipboard

Describe the bug: django requests are failing because dbapi2 instumentation seems to result in an InterfaceError Exception, Exception Value: connection already closed

Traceback:

File "/opt/venv/lib/python3.9/site-packages/django/db/backends/base/base.py" in _cursor
  237.             return self._prepare_cursor(self.create_cursor(name))

File "/opt/venv/lib/python3.9/site-packages/django/utils/asyncio.py" in inner
  33.             return func(*args, **kwargs)

File "/opt/venv/lib/python3.9/site-packages/django/db/backends/postgresql/base.py" in create_cursor
  236.             cursor = self.connection.cursor()

File "/opt/venv/lib/python3.9/site-packages/elasticapm/instrumentation/packages/dbapi2.py" in cursor
  263.         return self.cursor_proxy(self.__wrapped__.cursor(*args, **kwargs), self._self_destination_info)

The above exception (connection already closed) was the direct cause of the following exception:

File "/opt/venv/lib/python3.9/site-packages/django/core/handlers/exception.py" in inner
  47.                 response = get_response(request)

File "/opt/venv/lib/python3.9/site-packages/django/core/handlers/base.py" in _get_response
  181.                 response = wrapped_callback(request, *callback_args, **callback_kwargs)

File "/usr/local/lib/python3.9/contextlib.py" in inner
  79.                 return func(*args, **kwds)

File "/opt/venv/lib/python3.9/site-packages/django/views/decorators/csrf.py" in wrapped_view
  54.         return view_func(*args, **kwargs)

File "/opt/venv/lib/python3.9/site-packages/django/views/generic/base.py" in view
  70.             return self.dispatch(request, *args, **kwargs)

File "/opt/venv/lib/python3.9/site-packages/rest_framework/views.py" in dispatch
  509.             response = self.handle_exception(exc)

File "/opt/venv/lib/python3.9/site-packages/rest_framework/views.py" in handle_exception
  469.             self.raise_uncaught_exception(exc)

File "/opt/venv/lib/python3.9/site-packages/rest_framework/views.py" in raise_uncaught_exception
  480.         raise exc

File "/opt/venv/lib/python3.9/site-packages/rest_framework/views.py" in dispatch
  506.             response = handler(request, *args, **kwargs)

File "/code/utils/decorators.py" in decorated_method
  73.             return old_method(self, request, serializer)

File "/code/api/views.py" in post
  177.             serializer.update(my_user, serializer.validated_data)

File "/code/api/serializers.py" in update
  683.             device = Device.objects.get(tracking_id=my_user.tracking_id,

File "/opt/venv/lib/python3.9/site-packages/django/db/models/manager.py" in manager_method
  85.                 return getattr(self.get_queryset(), name)(*args, **kwargs)

File "/opt/venv/lib/python3.9/site-packages/django/db/models/query.py" in get
  431.         num = len(clone)

File "/opt/venv/lib/python3.9/site-packages/django/db/models/query.py" in __len__
  262.         self._fetch_all()

File "/opt/venv/lib/python3.9/site-packages/django/db/models/query.py" in _fetch_all
  1324.             self._result_cache = list(self._iterable_class(self))

File "/opt/venv/lib/python3.9/site-packages/django/db/models/query.py" in __iter__
  51.         results = compiler.execute_sql(chunked_fetch=self.chunked_fetch, chunk_size=self.chunk_size)

File "/opt/venv/lib/python3.9/site-packages/django/db/models/sql/compiler.py" in execute_sql
  1173.             cursor = self.connection.cursor()

File "/opt/venv/lib/python3.9/site-packages/django/utils/asyncio.py" in inner
  33.             return func(*args, **kwargs)

File "/opt/venv/lib/python3.9/site-packages/django/db/backends/base/base.py" in cursor
  259.         return self._cursor()

File "/opt/venv/lib/python3.9/site-packages/django/db/backends/base/base.py" in _cursor
  237.             return self._prepare_cursor(self.create_cursor(name))

File "/opt/venv/lib/python3.9/site-packages/django/db/utils.py" in __exit__
  90.                 raise dj_exc_value.with_traceback(traceback) from exc_value

File "/opt/venv/lib/python3.9/site-packages/django/db/backends/base/base.py" in _cursor
  237.             return self._prepare_cursor(self.create_cursor(name))

File "/opt/venv/lib/python3.9/site-packages/django/utils/asyncio.py" in inner
  33.             return func(*args, **kwargs)

File "/opt/venv/lib/python3.9/site-packages/django/db/backends/postgresql/base.py" in create_cursor
  236.             cursor = self.connection.cursor()

File "/opt/venv/lib/python3.9/site-packages/elasticapm/instrumentation/packages/dbapi2.py" in cursor
  263.         return self.cursor_proxy(self.__wrapped__.cursor(*args, **kwargs), self._self_destination_info)

Exception Type: InterfaceError at /api/xyz
Exception Value: connection already closed

To Reproduce

I don't know how to reproduce, this doesn't happen very often like once or twice a day

Environment (please complete the following information)

• OS: debian bullseye
• Python version: 3.9
• Framework and version: Django 3.2.13
• Agent version: 6.8.1

Note: This error appeared first time after upgrading from elastic-apm==6.6.1 to elastic-apm==6.7.2.

Does the error occur regularly enough that you're confident it wasn't happening at all in 6.6.1? I'm wondering whether we should look at this as a regression or an implementation bug.

Yes, 6.6.1 version run over 3 months, no errors. Just to be sure I will be downgrading to 6.6.1 I'll let you know the result after some time. On another note, I tried disabling dbapi2 by setting environment to SKIP_INSTRUMENT_DBAPI2=True, but I still get the same exception.

Thanks for the confirmation.

I am having a similar problem. I have downgraded the elasticapm version in my environment to 6.6.1 but am still experiencing the issue.

Describe the bug

Occasionally calls are failing with either InterfaceError('connection already closed') or OperationalError('SSL SYSCALL error: EOF detected\n'). Stack trace can be found here.

Reproducing

Unfortunately this is similar behavior, as in not reliably reproducable. It mostly (95%) happens with code that runs at night when there has been a couple of hours of low to no usage on the system if that helps. I wasn't yet able to verify if either of the two errors disappear once I completely disable elasticapm, that is another point on my troubleshooting list.

Environment

OS: debian bullseye (inside of a container)
Python version: 3.8.13
Framework and version: Django 3.2.14
Agent version: 6.6.1 and 6.9.1 confirmed

Can confirm issue still happens after downgrading to 6.6.1.

After diving this a bit, I don't think it's a bug in our agent.

In our dbapi2 instrumentation, we wrap the Connection and the Cursor objects so we can create spans when queries are executed through the cursor.

Django is requesting a cursor object from the postgres connection:

cursor = self.connection.cursor()

Our ConnectionProxy object passes that through to the wrapped connection (self.__wrapped__.cursor(*args, **kwargs)):

https://github.com/elastic/apm-agent-python/blob/a81a90f1ffd256a974bdd6206e778d47179fc407/elasticapm/instrumentation/packages/dbapi2.py#L265-L266

At which point postgres throws the connection already closed error.

The presence of elasticapm in the stacktrace is a red herring, I think. Can you try removing the agent for a time and see if the problem persists?

Closing for now. Please keep me posted if you are having this issue with the agent present, and it goes away when you remove the agent. Otherwise I think it's worth trying to track down why the connection is closing unexpectedly.