Queries crash on expired connection in pool.

[tim.tadh]

I have a low traffic website that I maintain for my Universities ACM student chapter. It wasn't visited in a while since it was the summer. When I visited the site it had an error. However, when I refreshed it worked fine. This has happened before. Upon investigating the stack trace, it appears to be OurSQL trying to use a dead connection to the MySQL database. This might only be a problem for a low traffic site, but I thought I should report it any way. If you need any more information I would be happy to oblige.

- Ubuntu 10.10
- mysqld Ver 5.1.49-1ubuntu8.1 for debian-linux-gnu on x86_64 ((Ubuntu))
- mysql Ver 14.14 Distrib 5.1.49, for debian-linux-gnu (x86_64) using readline 6.1
- oursql.__version__ => '0.9.2'

crashing query:
(SQL Alchemy)
Session.query.filter(
                        func.timestampdiff(text('MINUTE'),
                            Session.last_update,
                            datetime.utcnow()) > self.timeout
                        ).delete(False)

related model:
CREATE TABLE IF NOT EXISTS `session` (
  `id` int(11) NOT NULL AUTO_INCREMENT,
  `key` varchar(64) COLLATE utf8_bin DEFAULT NULL,
  `sig` tinyblob,
  `sigkey` tinyblob,
  `micro` tinyblob,
  `csrf` tinyblob,
  `user_id` int(11) DEFAULT NULL,
  `last_update` datetime DEFAULT NULL,
  PRIMARY KEY (`id`),
  UNIQUE KEY `ix_session_key` (`key`),
  KEY `user_id` (`user_id`),
  KEY `ix_session_last_update` (`last_update`)
) ENGINE=InnoDB DEFAULT CHARSET=utf8 COLLATE=utf8_bin AUTO_INCREMENT=3179 ;

--
-- Dumping data for table `session`
--

## Note I slightly sanitized these rows to remove the sensitive private session information.

INSERT INTO `session` (`id`, `key`, `sig`, `sigkey`, `micro`, `csrf`, `user_id`, `last_update`) VALUES
(3177, '36e7afddea1ee9d792a78311088ef6533262dc4e80b2db5b8d84c816712258d5', 0xd3529078bb69fcc88a8d2178fc2462f119d2ae3a279f998206486f21c3bd0d4c, 0x5040dae9187c9efbb16df682acd11c229ae7d655b5d55a9d4d88d63021f9e113, 0x0cad0f, NULL, NULL, '2011-08-31 13:22:26'),
(3178, '502874eee83fc787c5201e4d7e8788decd59850b0e04516885cc3d12da5a9d4d', 0x5a9d4d67cb057c3012a7a570374b26fb0ca712ee8b1b287bca49bdfeda0df206, 0x132a73ba9ad042b837a5a9d4d1546b5ff9fac5d20a63441d9505ce499805b6c0, 0xeca881, NULL, 1, '2011-08-31 13:42:02');

traceback:

[20110831-09:24AM] [forhireapp] [ERROR] Exception on / [GET]
Traceback (most recent call last):
  File "/home/deploy/apps/hackerweb/env/lib/python2.7/site-packages/flask/app.py", line 876, in wsgi_app
    rv = self.dispatch_request()
  File "/home/deploy/apps/hackerweb/env/lib/python2.7/site-packages/flask/app.py", line 695, in dispatch_request
    return self.view_functions[rule.endpoint](**req.view_args)
  File "./lib/supersession.py", line 78, in catcher
    session = self.getsession()
  File "./lib/supersession.py", line 66, in getsession
    self.clear_old_sessions()
  File "./lib/supersession.py", line 36, in clear_old_sessions
    ).delete(False)
  File "/usr/local/lib/python2.7/dist-packages/SQLAlchemy-0.6.6-py2.7.egg/sqlalchemy/orm/query.py", line 2143, in delete
    result = session.execute(delete_stmt, params=self._params)
  File "/usr/local/lib/python2.7/dist-packages/SQLAlchemy-0.6.6-py2.7.egg/sqlalchemy/orm/session.py", line 719, in execute
    return self._connection_for_bind(engine, close_with_result=True).execute(
  File "/usr/local/lib/python2.7/dist-packages/SQLAlchemy-0.6.6-py2.7.egg/sqlalchemy/orm/session.py", line 660, in _connection_for_bind
    return self.transaction._connection_for_bind(engine)
  File "/usr/local/lib/python2.7/dist-packages/SQLAlchemy-0.6.6-py2.7.egg/sqlalchemy/orm/session.py", line 343, in _connection_for_bind
    transaction = conn.begin()
  File "/usr/local/lib/python2.7/dist-packages/SQLAlchemy-0.6.6-py2.7.egg/sqlalchemy/engine/base.py", line 1017, in begin
    self.__transaction = RootTransaction(self)
  File "/usr/local/lib/python2.7/dist-packages/SQLAlchemy-0.6.6-py2.7.egg/sqlalchemy/engine/base.py", line 1554, in __init__
    self.connection._begin_impl()
  File "/usr/local/lib/python2.7/dist-packages/SQLAlchemy-0.6.6-py2.7.egg/sqlalchemy/engine/base.py", line 1076, in _begin_impl
    self._handle_dbapi_exception(e, None, None, None, None)
  File "/usr/local/lib/python2.7/dist-packages/SQLAlchemy-0.6.6-py2.7.egg/sqlalchemy/engine/base.py", line 1074, in _begin_impl
    self.engine.dialect.do_begin(self.connection)
  File "/usr/local/lib/python2.7/dist-packages/SQLAlchemy-0.6.6-py2.7.egg/sqlalchemy/dialects/mysql/oursql.py", line 101, in do_begin
    connection.cursor().execute('BEGIN', plain_query=True)
  File "cursor.pyx", line 107, in oursql.Cursor.execute (oursqlx/oursql.c:15745)
  File "cursor.pyx", line 70, in oursql.Cursor._new_query (oursqlx/oursql.c:15397)
  File "query.pyx", line 137, in oursql._Query.__cinit__ (oursqlx/oursql.c:14254)
  File "query.pyx", line 154, in oursql._Query._raise_error (oursqlx/oursql.c:14506)
  File "connection.pyx", line 180, in oursql.Connection._raise_error (oursqlx/oursql.c:5440)
OperationalError: (OperationalError) (2006, 'MySQL server has gone away', None) None None

[Stephen Thorne (jerub)]

I've just made a commit to a branch here: lp:~jerub/oursql/reconnect that will allow you to connect with Connection(..., autoreconnect=True). Please test this branch and see if it solves your problem.

If it does, I will release 0.9.3 with this option available.

[András Veres-Szentkirályi (vsza)]

I had the same problem with django-oursql (https://github.com/dcramer/django-oursql), and this branch fixed it, thanks! The following line needs to be added as a workaround into django-oursql's mysql_oursql/standard/base.py, right before connect(): kwargs['autoreconnect'] = True

[András Veres-Szentkirályi (vsza)]

I also opened an issue related to this on django-oursql's GitHub page: https://github.com/dcramer/django-oursql/issues/9

[Stephen Hu (goodruck)]

stephen, thanks very much for the fix, when will 0.9.3 be released? and i'm curious as i've been running 0.9.2 for awhile now and why this wasn't available before; perhaps my app architecture is not optimal?

i run the following:
mysql -> oursql -> sqlalchemy -> tornado web -> supervisord

supervisord is a python utility that basically allows me to run a set of tornado processes as daemons so i noticed that after 8 hours, the mysql connection seems to go stale and my app doesn't respond.

i set the sqlalchemy connection parameter called pool_recycle=3600, but i imagine 0.9.2 doesn't pass this down to the mysql layer.

perhaps my architecture is just completely wrong. anyway, thanks for the excellent work, keep it up.

[Stephen Thorne (jerub)]

0.9.3 was just released. Could you make a seperate bug to look into the pool_recycle=3600 issue if that's important to you. Thanks!

[Stephen Hu (goodruck)]

done, here's the link to the bug:

https://bugs.launchpad.net/oursql/+bug/906183