Error (psycopg2.InterfaceError) connection already closed

[exiledonamarginalisland]

Ghini 1.0.86 on kubuntu 17.04 LTS 64 bit on PostgresSQL.

Steps to reproduce the behaviour

• connect to a PostgreSQL database;
• click on home, then
• click on any of the three Species links in the right hand menu.
• and repeat.

every second time, you will get this pop-up window:

The error is:

(psycopg2.InterfaceError) connection already closed

This is the trace:

Traceback (most recent call last):
  File "/home/kt529/.virtualenvs/ghide/local/lib/python2.7/site-packages/ghini.desktop-1.0.86-py2.7.egg/bauble/__init__.py", line 192, in command_handler
    last_handler(cmd, arg)
  File "/home/kt529/.virtualenvs/ghide/local/lib/python2.7/site-packages/ghini.desktop-1.0.86-py2.7.egg/bauble/view.py", line 1484, in __call__
    self.view.search(arg)
  File "/home/kt529/.virtualenvs/ghide/local/lib/python2.7/site-packages/ghini.desktop-1.0.86-py2.7.egg/bauble/view.py", line 805, in search
    self.session.rollback()
  File "build/bdist.linux-x86_64/egg/sqlalchemy/orm/session.py", line 754, in rollback
    self.transaction.rollback()
  File "build/bdist.linux-x86_64/egg/sqlalchemy/orm/session.py", line 419, in rollback
    transaction._rollback_impl()
  File "build/bdist.linux-x86_64/egg/sqlalchemy/orm/session.py", line 449, in _rollback_impl
    t[1].rollback()
  File "build/bdist.linux-x86_64/egg/sqlalchemy/engine/base.py", line 1563, in rollback
    self._do_rollback()
  File "build/bdist.linux-x86_64/egg/sqlalchemy/engine/base.py", line 1601, in _do_rollback
    self.connection._rollback_impl()
  File "build/bdist.linux-x86_64/egg/sqlalchemy/engine/base.py", line 670, in _rollback_impl
    self._handle_dbapi_exception(e, None, None, None, None)
  File "build/bdist.linux-x86_64/egg/sqlalchemy/engine/base.py", line 1341, in _handle_dbapi_exception
    exc_info
  File "build/bdist.linux-x86_64/egg/sqlalchemy/util/compat.py", line 199, in raise_from_cause
    reraise(type(exception), exception, tb=exc_tb)
  File "build/bdist.linux-x86_64/egg/sqlalchemy/engine/base.py", line 668, in _rollback_impl
    self.engine.dialect.do_rollback(self.connection)
  File "build/bdist.linux-x86_64/egg/sqlalchemy/engine/default.py", line 420, in do_rollback
    dbapi_connection.rollback()
InterfaceError: (psycopg2.InterfaceError) connection already closed

opinions

It seems that the connection closes between one operation and the next, and ghini has difficulties in reopening it.

[mfrasca]

(is this deterministically so as you say? in which screen were you before inserting the species?)

never mind, I saw that. please check the edited description, if it's the same you observe over there. than you for reporting!

[mfrasca]

the one I described how to reproduce starts like this:

Traceback (most recent call last):
  File "/usr/lib/python2.7/threading.py", line 801, in __bootstrap_inner
    self.run()
  File "/home/mario/.virtualenvs/ghide-1.0-dev/lib/python2.7/site-packages/ghini.desktop-1.0.87-py2.7.egg/bauble/plugins/plants/__init__.py", line 90, in run
    value, = ssn.execute(self.query).first()

[mfrasca]

Corrado, questo succede con 1.0, giusto? ho una patch per 3.1, se vuoi provarla. (3.1-dev)

[mfrasca]

@RoDuth have you ever had this problem? since a specific version? or in some specific setting? or it sounds totally new to you?

[RoDuth]

Sorry for the late reply on this (finally looking at all my notifications)...

Yes, on osx and ghini-1.0.87 I get this error

Must say I have not noticed it before, but then I have not had need to do those steps before.

connect to a PostgreSQL database; click on home, then click on any of the three Species links in the right hand menu. and repeat.

I'll try to git bisect it tomorrow.

[mfrasca]

I'll try to git bisect it tomorrow.

:+1:

[RoDuth]

well bisect didn't get me anywhere, as far back as the feature was introduced gave me errors with a postgres database...

changing: https://github.com/Ghini/ghini.desktop/blob/7da320338a39784d57f8fd565b7e48b136a419a3/bauble/view.py#L805

to

            try:
                self.session.rollback()
            except Exception, e:
                logger.debug('unhandled %s(%s) while attempting to rollback',
                             type(e).__name__, e)

seems to work though.

[mfrasca]

hey, thanks for looking into it. this is a very funny patch. how can it be that after ignoring a session.rollback because of an exception, the session is again usable? I mean I'm not doubting it helps, but I would like to understand what is going on.

[RoDuth]

not really sure and no not a fan of try except either. Nor can I see why psycopg2 would report that the socket is shut down. Losing the connection even when the database is on localhost? But then I didn't trace it back further, not a lot of time.

If it helps here are the scratchy notes from earlier in the evolution of this feature while trying to find a starting point for a bisect (i got the same error but also a few other random one so gave up.):

8ab48612 errors here seem more random... often getting a few goes before an error is thrown e09ed3f5 errors here are random still, seems if I'm quick at hitting home its OK but if I delay a little I get cursor already closed error but then if I wait for the 'counting records' to finish all seems ok also.

Occassional error from around 1.0.56 (maybe others?)

(sqlalchemy.exc.InvalidRequestError) Can't reconnect until invalid transaction is rolled back [SQL: u'SELECT tagged_obj.obj_id AS tagged_obj_obj_id, tagged_obj.obj_class AS tagged_obj_obj_class, tagged_obj.tag_id AS tagged_obj_tag_id, tagged_obj.id AS tagged_obj_id, tagged_obj._created AS tagged_objcreated, tagged_obj._last_updated AS tagged_objlast_updated \nFROM tagged_obj \nWHERE tagged_obj.obj_class = %(obj_class_1)s AND tagged_obj.obj_id = %(obj_id_1)s'] [parameters: [immutabledict({})]]

> Traceback (most recent call last):
>   File "/Users/rodem/.pyenvs/ghini.desktop/lib/python2.7/site-packages/bauble-1.0.56-py2.7.egg/bauble/__init__.py", line 181, in command_handler
>     last_handler(cmd, arg)
>   File "/Users/rodem/.pyenvs/ghini.desktop/lib/python2.7/site-packages/bauble-1.0.56-py2.7.egg/bauble/view.py", line 1441, in __call__
>     self.view.search(arg)
>   File "/Users/rodem/.pyenvs/ghini.desktop/lib/python2.7/site-packages/bauble-1.0.56-py2.7.egg/bauble/view.py", line 838, in search
>     self.update_bottom_notebook()
>   File "/Users/rodem/.pyenvs/ghini.desktop/lib/python2.7/site-packages/bauble-1.0.56-py2.7.egg/bauble/view.py", line 606, in update_bottom_notebook
>     objs = klass.attached_to(row)
>   File "/Users/rodem/.pyenvs/ghini.desktop/lib/python2.7/site-packages/bauble-1.0.56-py2.7.egg/bauble/plugins/tag/__init__.py", line 308, in attached_to
>     return [i.tag for i in qto.all()]
>   File "build/bdist.macosx-10.11-x86_64/egg/sqlalchemy/orm/query.py", line 2399, in all
>     return list(self)
>   File "build/bdist.macosx-10.11-x86_64/egg/sqlalchemy/orm/query.py", line 2516, in __iter__
>     return self._execute_and_instances(context)
>   File "build/bdist.macosx-10.11-x86_64/egg/sqlalchemy/orm/query.py", line 2531, in _execute_and_instances
>     result = conn.execute(querycontext.statement, self._params)
>   File "build/bdist.macosx-10.11-x86_64/egg/sqlalchemy/engine/base.py", line 914, in execute
>     return meth(self, multiparams, params)
>   File "build/bdist.macosx-10.11-x86_64/egg/sqlalchemy/sql/elements.py", line 323, in _execute_on_connection
>     return connection._execute_clauseelement(self, multiparams, params)
>   File "build/bdist.macosx-10.11-x86_64/egg/sqlalchemy/engine/base.py", line 1010, in _execute_clauseelement
>     compiled_sql, distilled_params
>   File "build/bdist.macosx-10.11-x86_64/egg/sqlalchemy/engine/base.py", line 1078, in _execute_context
>     None, None)
>   File "build/bdist.macosx-10.11-x86_64/egg/sqlalchemy/engine/base.py", line 1341, in _handle_dbapi_exception
>     exc_info
>   File "build/bdist.macosx-10.11-x86_64/egg/sqlalchemy/util/compat.py", line 199, in raise_from_cause
>     reraise(type(exception), exception, tb=exc_tb)
>   File "build/bdist.macosx-10.11-x86_64/egg/sqlalchemy/engine/base.py", line 1071, in _execute_context
>     conn = self._revalidate_connection()
>   File "build/bdist.macosx-10.11-x86_64/egg/sqlalchemy/engine/base.py", line 391, in _revalidate_connection
>     "Can't reconnect until invalid "
> StatementError: (sqlalchemy.exc.InvalidRequestError) Can't reconnect until invalid transaction is rolled back [SQL: u'SELECT tagged_obj.obj_id AS tagged_obj_obj_id, tagged_obj.obj_class AS tagged_obj_obj_class, tagged_obj.tag_id AS tagged_obj_tag_id, tagged_obj.id AS tagged_obj_id, tagged_obj._created AS tagged_obj__created, tagged_obj._last_updated AS tagged_obj__last_updated \nFROM tagged_obj \nWHERE tagged_obj.obj_class = %(obj_class_1)s AND tagged_obj.obj_id = %(obj_id_1)s'] [parameters: [immutabledict({})]]

Less common but another error from 1.0.56

(psycopg2.InterfaceError) connection already closed [SQL: u'select count(*) from species'] [parameters: [{}]]

> Traceback (most recent call last):
>   File "/Users/rodem/.pyenvs/ghini.desktop/lib/python2.7/site-packages/bauble-1.0.56-py2.7.egg/bauble/__init__.py", line 181, in command_handler
>     last_handler(cmd, arg)
>   File "/Users/rodem/.pyenvs/ghini.desktop/lib/python2.7/site-packages/bauble-1.0.56-py2.7.egg/bauble/ui.py", line 101, in __call__
>     self.view.update()
>   File "/Users/rodem/.pyenvs/ghini.desktop/lib/python2.7/site-packages/bauble-1.0.56-py2.7.egg/bauble/ui.py", line 82, in update
>     self.infobox.update()
>   File "/Users/rodem/.pyenvs/ghini.desktop/lib/python2.7/site-packages/bauble-1.0.56-py2.7.egg/bauble/plugins/plants/__init__.py", line 272, in update
>     "select count(*) from species").run()
>   File "/Users/rodem/.pyenvs/ghini.desktop/lib/python2.7/site-packages/bauble-1.0.56-py2.7.egg/bauble/plugins/plants/__init__.py", line 91, in run
>     value, = ssn.execute(self.query).first()
>   File "build/bdist.macosx-10.11-x86_64/egg/sqlalchemy/orm/session.py", line 1023, in execute
>     bind, close_with_result=True).execute(clause, params or {})
>   File "build/bdist.macosx-10.11-x86_64/egg/sqlalchemy/engine/base.py", line 914, in execute
>     return meth(self, multiparams, params)
>   File "build/bdist.macosx-10.11-x86_64/egg/sqlalchemy/sql/elements.py", line 323, in _execute_on_connection
>     return connection._execute_clauseelement(self, multiparams, params)
>   File "build/bdist.macosx-10.11-x86_64/egg/sqlalchemy/engine/base.py", line 1010, in _execute_clauseelement
>     compiled_sql, distilled_params
>   File "build/bdist.macosx-10.11-x86_64/egg/sqlalchemy/engine/base.py", line 1078, in _execute_context
>     None, None)
>   File "build/bdist.macosx-10.11-x86_64/egg/sqlalchemy/engine/base.py", line 1341, in _handle_dbapi_exception
>     exc_info
>   File "build/bdist.macosx-10.11-x86_64/egg/sqlalchemy/util/compat.py", line 199, in raise_from_cause
>     reraise(type(exception), exception, tb=exc_tb)
>   File "build/bdist.macosx-10.11-x86_64/egg/sqlalchemy/engine/base.py", line 1073, in _execute_context
>     context = constructor(dialect, self, conn, *args)
>   File "build/bdist.macosx-10.11-x86_64/egg/sqlalchemy/engine/default.py", line 556, in _init_compiled
>     self.cursor = self.create_cursor()
>   File "build/bdist.macosx-10.11-x86_64/egg/sqlalchemy/dialects/postgresql/psycopg2.py", line 464, in create_cursor
>     return self._dbapi_connection.cursor()
>   File "build/bdist.macosx-10.11-x86_64/egg/sqlalchemy/pool.py", line 852, in cursor
>     return self.connection.cursor(*args, **kwargs)
> InterfaceError: (psycopg2.InterfaceError) connection already closed [SQL: u'select count(*) from species'] [parameters: [{}]]

[mfrasca]

when you say »evolution of this feature«, what are you referring to? is it the "counting records"?

[RoDuth]

no the items on the home screen (total, in use, unused...) but I do think that the counting records may have something to do with it. (running in different threads?)

[mfrasca]

definitely running in different threads yes, you don't want to do database stuff on the main (GUI) thread. in popular platforms as Android this was made impossible. I have a possibly better solution (NullPool), but I am not even sure it works at all, since it looks like running fine in production, but it fails ALL tests in testing. check #133