elastic
django dbapi2 instumentation results in InterfaceError connection already closed
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.
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
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.