InterfaceError: connection already closed with Django and Gunicorn

[jeanlucmongrain]

I'm using pypy 1.8 on a Django 1.3.1 with psycopg2-ctypes 2.4.4 on PostgreSQL 9.1 This is running from Gunicorn, 2 workers. I very frequently get the following, like 66% of all requests:

Traceback (most recent call last):
  File "/usr/local/src/kontactsport.pypy/env/site-packages/gunicorn/workers/sync.py", line 99, in handle_request
    respiter = self.wsgi(environ, resp.start_response)
  File "/usr/local/src/kontactsport.pypy/env/site-packages/django/contrib/staticfiles/handlers.py", line 68, in __call__
    return self.application(environ, start_response)
  File "/usr/local/src/kontactsport.pypy/env/site-packages/django/core/handlers/wsgi.py", line 274, in __call__
    signals.request_finished.send(sender=self.__class__)
  File "/usr/local/src/kontactsport.pypy/env/site-packages/django/dispatch/dispatcher.py", line 172, in send
    response = receiver(signal=self, sender=sender, **named)
  File "/usr/local/src/kontactsport.pypy/env/site-packages/django/db/__init__.py", line 85, in close_connection
    conn.close()
  File "/usr/local/src/kontactsport.pypy/env/site-packages/django/db/backends/__init__.py", line 244, in close
    self.connection.close()
  File "/usr/local/src/kontactsport.pypy/env/site-packages/psycopg2ct/_impl/connection.py", line 38, in check_closed_
    raise exceptions.InterfaceError('connection already closed')
InterfaceError: connection already closed

my settings.py section for database is simply:

DATABASES = {
    'default': {
        'ENGINE': 'django.db.backends.postgresql_psycopg2',
        'NAME': 'dbname',
        'USER': 'dbuser',
        'PASSWORD': 'dbpass',
        'HOST': '127.0.0.1',
        'PORT': '5432',
        #'autocommit': True
    }
}

Nothing shows in PostgreSQL logs.

I went down to a single Gunicorn worker, still happening. and if I run it without gunicorn, and simply runserver 127.0.0.1:$portbehindnginx

It never raise that exception again.

I'm not sure if it's psycopg2-ctypes related.

there is something that look like this here:

https://code.djangoproject.com/ticket/15802

This is my first pypy + django 1.3 + psycopg2-ctypes deployment.

All my previous one were on cpython + django 1.2 + psycopg2 and I never encouter that problem before

[dvarrazzo]

In the next version close() should be idempotent, fixing this sort of bug. However It should be checked why it is happening, as it's not supposed to.

Please apply the following patch to psycopg2ct, which should log where each close() is invoked, and let's take a look who is closing the same connection twice.

diff --git a/psycopg2ct/_impl/connection.py b/psycopg2ct/_impl/connection.py
index 962e1a2..3c52845 100644
--- a/psycopg2ct/_impl/connection.py
+++ b/psycopg2ct/_impl/connection.py
@@ -151,9 +151,15 @@ class Connection(object):
         self._close()

     @check_closed
-    def close(self):
+    def close_really(self):
         return self._close()

+    def close(self):
+        import traceback
+        print "closing connection", self, "closed:", self._closed
+        traceback.print_stack()
+        return self.close_really()
+
     @check_closed
     @check_async
     @check_tpc

[jeanlucmongrain]

2012-03-04 11:11:39 [11825] [INFO] Starting gunicorn 0.14.0
2012-03-04 11:11:39 [11825] [INFO] Listening at: http://127.0.0.1:5001 (11825)
2012-03-04 11:11:39 [11825] [INFO] Using worker: sync
2012-03-04 11:11:39 [11835] [INFO] Booting worker with pid: 11835
2012-03-04 11:11:39 [11836] [INFO] Booting worker with pid: 11836
2012-03-04 11:11:44 [11836] [ERROR] Error handling request
Traceback (most recent call last):
  File "/usr/local/src/kontactsport.pypy/env/site-packages/gunicorn/workers/sync.py", line 99, in handle_request
    respiter = self.wsgi(environ, resp.start_response)
  File "/usr/local/src/kontactsport.pypy/env/site-packages/django/contrib/staticfiles/handlers.py", line 68, in __call__
    return self.application(environ, start_response)
  File "/usr/local/src/kontactsport.pypy/env/site-packages/django/core/handlers/wsgi.py", line 274, in __call__
    signals.request_finished.send(sender=self.__class__)
  File "/usr/local/src/kontactsport.pypy/env/site-packages/django/dispatch/dispatcher.py", line 172, in send
    response = receiver(signal=self, sender=sender, **named)
  File "/usr/local/src/kontactsport.pypy/env/site-packages/django/db/__init__.py", line 85, in close_connection
    conn.close()
  File "/usr/local/src/kontactsport.pypy/env/site-packages/django/db/backends/__init__.py", line 244, in close
    self.connection.close()
  File "/usr/local/src/kontactsport.pypy/env/site-packages/psycopg2ct/_impl/connection.py", line 161, in close
    return self.close_really()
  File "/usr/local/src/kontactsport.pypy/env/site-packages/psycopg2ct/_impl/connection.py", line 38, in check_closed_
    raise exceptions.InterfaceError('connection already closed')
InterfaceError: connection already closed
, in run
    self.manage_workers()
  File "/usr/local/src/kontactsport.pypy/env/site-packages/gunicorn/arbiter.py", line 428, in manage_workers
    self.spawn_workers()
  File "/usr/local/src/kontactsport.pypy/env/site-packages/gunicorn/arbiter.py", line 479, in spawn_workers
    self.spawn_worker()
  File "/usr/local/src/kontactsport.pypy/env/site-packages/gunicorn/arbiter.py", line 453, in spawn_worker
    worker.init_process()
  File "/usr/local/src/kontactsport.pypy/env/site-packages/gunicorn/workers/base.py", line 103, in init_process
    self.run()
  File "/usr/local/src/kontactsport.pypy/env/site-packages/gunicorn/workers/sync.py", line 36, in run
    self.handle(client, addr)
  File "/usr/local/src/kontactsport.pypy/env/site-packages/gunicorn/workers/sync.py", line 71, in handle
    self.handle_request(req, client, addr)
  File "/usr/local/src/kontactsport.pypy/env/site-packages/gunicorn/workers/sync.py", line 99, in handle_request
    respiter = self.wsgi(environ, resp.start_response)
  File "/usr/local/src/kontactsport.pypy/env/site-packages/django/contrib/staticfiles/handlers.py", line 68, in __call__
    return self.application(environ, start_response)
  File "/usr/local/src/kontactsport.pypy/env/site-packages/django/core/handlers/wsgi.py", line 274, in __call__
    signals.request_finished.send(sender=self.__class__)
  File "/usr/local/src/kontactsport.pypy/env/site-packages/django/dispatch/dispatcher.py", line 172, in send
    response = receiver(signal=self, sender=sender, **named)
  File "/usr/local/src/kontactsport.pypy/env/site-packages/django/db/__init__.py", line 85, in close_connection
    conn.close()
  File "/usr/local/src/kontactsport.pypy/env/site-packages/django/db/backends/__init__.py", line 244, in close
    self.connection.close()
  File "/usr/local/src/kontactsport.pypy/env/site-packages/psycopg2ct/_impl/connection.py", line 160, in close
    traceback.print_stack()
closing connection <psycopg2ct._impl.connection.Connection object at 0x0000000005b277f0> closed: True
  File "app_main.py", line 662, in entry_point
  File "app_main.py", line 610, in run_command_line
  File "app_main.py", line 51, in run_toplevel
  File "/usr/local/src/kontactsport.pypy/kontactsports/manage.py", line 11, in <module>
    execute_manager(settings)
  File "/usr/local/src/kontactsport.pypy/env/site-packages/django/core/management/__init__.py", line 438, in execute_manager
    utility.execute()
  File "/usr/local/src/kontactsport.pypy/env/site-packages/django/core/management/__init__.py", line 379, in execute
    self.fetch_command(subcommand).run_from_argv(self.argv)
  File "/usr/local/src/kontactsport.pypy/env/site-packages/django/core/management/base.py", line 191, in run_from_argv
    self.execute(*args, **options.__dict__)
  File "/usr/local/src/kontactsport.pypy/env/site-packages/django/core/management/base.py", line 220, in execute
    output = self.handle(*args, **options)
  File "/usr/local/src/kontactsport.pypy/env/site-packages/gunicorn/management/commands/run_gunicorn.py", line 100, in handle
    DjangoApplicationCommand(options, admin_media_path).run()
  File "/usr/local/src/kontactsport.pypy/env/site-packages/gunicorn/app/base.py", line 129, in run
    Arbiter(self).run()
  File "/usr/local/src/kontactsport.pypy/env/site-packages/gunicorn/arbiter.py", line 156, in run
    self.manage_workers()
  File "/usr/local/src/kontactsport.pypy/env/site-packages/gunicorn/arbiter.py", line 428, in manage_workers
    self.spawn_workers()
  File "/usr/local/src/kontactsport.pypy/env/site-packages/gunicorn/arbiter.py", line 479, in spawn_workers
    self.spawn_worker()
  File "/usr/local/src/kontactsport.pypy/env/site-packages/gunicorn/arbiter.py", line 453, in spawn_worker
    worker.init_process()
  File "/usr/local/src/kontactsport.pypy/env/site-packages/gunicorn/workers/base.py", line 103, in init_process
    self.run()
  File "/usr/local/src/kontactsport.pypy/env/site-packages/gunicorn/workers/sync.py", line 36, in run
    self.handle(client, addr)
  File "/usr/local/src/kontactsport.pypy/env/site-packages/gunicorn/workers/sync.py", line 71, in handle
    self.handle_request(req, client, addr)
  File "/usr/local/src/kontactsport.pypy/env/site-packages/gunicorn/workers/sync.py", line 99, in handle_request
    respiter = self.wsgi(environ, resp.start_response)
  File "/usr/local/src/kontactsport.pypy/env/site-packages/django/contrib/staticfiles/handlers.py", line 68, in __call__
    return self.application(environ, start_response)
  File "/usr/local/src/kontactsport.pypy/env/site-packages/django/core/handlers/wsgi.py", line 274, in __call__
    signals.request_finished.send(sender=self.__class__)
  File "/usr/local/src/kontactsport.pypy/env/site-packages/django/dispatch/dispatcher.py", line 172, in send
    response = receiver(signal=self, sender=sender, **named)
  File "/usr/local/src/kontactsport.pypy/env/site-packages/django/db/__init__.py", line 85, in close_connection
    conn.close()
  File "/usr/local/src/kontactsport.pypy/env/site-packages/django/db/backends/__init__.py", line 244, in close
    self.connection.close()
  File "/usr/local/src/kontactsport.pypy/env/site-packages/psycopg2ct/_impl/connection.py", line 160, in close
    traceback.print_stack()

this happens on the 2nd page load. I don't see that the connection was closed on 1st page load.

[dvarrazzo]

I've created a test project with django 1.3.1, psycopg2ct 2.4.4 and run it with gunicorn 0.14.1, and have not been able to reproduce the problem.

Please provide a tarball containing a project showing the bug, including the command used to run the server.

[mvantellingen]

Django 1.3.x only supports psycopg2 up till 2.4.1 due to a bug in their transaction handling iirc. Perhaps we should make a psycopg2ct 2.4.1 specifically for those running django 1.3

[dvarrazzo]

I think what you mean is the problem created by connection.autocommit() which is only a problem to run the django test suite.: https://code.djangoproject.com/ticket/16250

If you want to work around it it's enough to drop the method autocommit from the connection. It's python, you can monkeypatch it :) Just add in the documentation the suggestion to do "del psycopg2.extension.connection.autocommit" (untested).

[jeanlucmongrain]

@dvarrazzo do you mean doing something like:

my psycopg2.py:

from psycopg2ct import compat
compat.register()

import psycopg2
del psycopg2.extensions.connection.autocommit

?

because I tried and still got the error

[dvarrazzo]

@bclermont: sorry, in the above comment I was referring to @mvantellingen suggesting we should have psycopg2ct 2.4.1, non to your problem.

As I said, please provide a complete tarball with all the script required to reproduce your bug, as I'm not able to do it myself and I don't have enough gunicorn insight to get what's possibly going wrong.

[blackhand]

i have this problem with CPython and Psycopg2 and Pypy 1.8 and psycopg2-ctypes then i presume that the bug is psycopg2 related

with the new psycopg2 2.4.5 the problem disapear in my two apps tunder CPython that have the problem, maybe upgrading psycopg2-ctypes to 2.4.5 version can work ? i check the changelog and find this:

"The close() methods on connections and cursors don't raise exceptions if called on already closed objects."

http://initd.org/psycopg/articles/tag/release/

maybe this is the problem ?

[dvarrazzo]

The problem for me is not in psycopg but in the program calling it. However we have made close() idempotent just because that's something that can happen and there is not a real reason to be anal in raising an exception (it is an overly strict interpretation of the DBAPI; other objects in pythonland, e.g. files, have close() idempotent).

So yeah, your problem may go as soon as psycopg2-ctypes catches up with psycopg2-c.