#24 timeouts/tracebacks @ mysql session selects; f5 lb pair used

[Nick Silkey]

Saw some of our filelocker 2.4.1 instances were spewing tracebacks. After a restart, they eventually began to throw tracbacks again some 90m later. These hosts sit behind an f5 load balancer pair which reverse proxies client reqs to Apaches fronting filelocker instances.

Does anyone out there have a successful installation of Filelocker behind a reverse proxy/load balancer?

[rs253@vm-fileprdapp-03 ~]$ tail -f /var/log/filelocker/filelocker.error.log
[14/Jun/2011:10:58:33] ENGINE Listening for SIGUSR1.
[14/Jun/2011:10:58:33] ENGINE Bus STARTING
[14/Jun/2011:10:58:33] ENGINE Forking once.
[14/Jun/2011:10:58:33] ENGINE Forking twice.
[14/Jun/2011:10:58:33] ENGINE Daemonized to PID: 26512
[14/Jun/2011:10:58:33] ENGINE PID 26512 written to '/opt/filelocker/filelocker.pid'.
[14/Jun/2011:10:58:33] ENGINE Started monitor thread '_TimeoutMonitor'.
[14/Jun/2011:10:58:33] ENGINE Serving on 0.0.0.0:8080
[14/Jun/2011:10:58:33] ENGINE Bus STARTED
[14/Jun/2011:10:59:06] ENGINE Started monitor thread 'Monitor'.
[14/Jun/2011:12:30:48] Traceback (most recent call last):
File "/usr/lib/python2.6/site-packages/cherrypy/_cpwsgi.py", line 79, in setapp
s, h, b = self.get_response()
File "/usr/lib/python2.6/site-packages/cherrypy/_cpwsgi.py", line 219, in get_response
response = self.request.run(meth, path, qs, rproto, headers, rfile)
File "/usr/lib/python2.6/site-packages/cherrypy/_cprequest.py", line 567, in run
raise cherrypy.TimeoutError()
TimeoutError

<SNIP>

[14/Jun/2011:12:30:48] Traceback (most recent call last):
File "/usr/lib/python2.6/site-packages/cherrypy/_cprequest.py", line 98, in run
hook()
File "/usr/lib/python2.6/site-packages/cherrypy/_cprequest.py", line 58, in call
return self.callback(self.kwargs)
File "/usr/lib/python2.6/site-packages/cherrypy/lib/sessions.py", line 636, in init
cherrypy.serving.session = sess = storage_class(id, kwargs)
File "/misc/filesw01/filelocker/22/core/dao/MySQLDAO.py", line 1319, in init
Session.init(self, id, **kwargs)
File "/usr/lib/python2.6/site-packages/cherrypy/lib/sessions.py", line 79, in init
self.regenerate()
File "/usr/lib/python2.6/site-packages/cherrypy/lib/sessions.py", line 101, in regenerate
if self._exists():
File "/misc/filesw01/filelocker/22/core/dao/MySQLDAO.py", line 1344, in _exists
rows = self.execute('SELECT data, expiration_time FROM session WHERE id=%s', (self.id,))
File "/misc/filesw01/filelocker/22/core/dao/MySQLDAO.py", line 1397, in execute
self.rebuild_connection()
File "/misc/filesw01/filelocker/22/core/dao/MySQLDAO.py", line 1335, in rebuild_connection
cherrypy.thread_data.db = cherrypy.thread_data.fl.db.get_db()
AttributeError: '_ThreadData' object has no attribute 'fl'

<SNIP>

[14/Jun/2011:12:30:48] HTTP
Request Headers:
X-FORWARDED-SERVER: vm-fileprdapp-03.web.yale.internal
HOST: localhost:8080
CONNECTION: Keep-Alive
Remote-Addr: 127.0.0.1
X-FORWARDED-HOST:
X-FORWARDED-FOR: 172.28.51.6
[14/Jun/2011:12:30:48] HTTP Traceback (most recent call last):
File "/usr/lib/python2.6/site-packages/cherrypy/_cprequest.py", line 598, in respond
self.hooks.run('before_request_body')
File "/usr/lib/python2.6/site-packages/cherrypy/_cprequest.py", line 98, in run
hook()
File "/usr/lib/python2.6/site-packages/cherrypy/_cprequest.py", line 58, in call
return self.callback(self.kwargs)
File "/usr/lib/python2.6/site-packages/cherrypy/lib/sessions.py", line 636, in init
cherrypy.serving.session = sess = storage_class(id, kwargs)
File "/misc/filesw01/filelocker/22/core/dao/MySQLDAO.py", line 1319, in init
Session.init(self, id, **kwargs)
File "/usr/lib/python2.6/site-packages/cherrypy/lib/sessions.py", line 79, in init
self.regenerate()
File "/usr/lib/python2.6/site-packages/cherrypy/lib/sessions.py", line 101, in regenerate
if self._exists():
File "/misc/filesw01/filelocker/22/core/dao/MySQLDAO.py", line 1344, in _exists
rows = self.execute('SELECT data, expiration_time FROM session WHERE id=%s', (self.id,))
File "/misc/filesw01/filelocker/22/core/dao/MySQLDAO.py", line 1397, in execute
self.rebuild_connection()
File "/misc/filesw01/filelocker/22/core/dao/MySQLDAO.py", line 1335, in rebuild_connection
cherrypy.thread_data.db = cherrypy.thread_data.fl.db.get_db()
AttributeError: '_ThreadData' object has no attribute 'fl'

-nick

[Nick Silkey]

MySQLDAO.py eating it trying to SELECT on session table? This lone table is my only table using the InnoDB engine.

mysql> select table_name, engine from information_schema.tables where
-> table_schema = 'filetstdb00';
+-------------------------+--------+
| table_name | engine |
+-------------------------+--------+
| attribute | MyISAM |
| audit_log | MyISAM |
| cli_key | MyISAM |
| config | MyISAM |
| deletion_queue | MyISAM |
| file | MyISAM |
| group_membership | MyISAM |
| group_permission | MyISAM |
| groups | MyISAM |
| hidden_share | MyISAM |
| message | MyISAM |
| message_recipient | MyISAM |
| permission | MyISAM |
| private_attribute_share | MyISAM |
| private_group_share | MyISAM |
| private_share | MyISAM |
| public_share | MyISAM |
| session | InnoDB |
| upload_ticket | MyISAM |
| user | MyISAM |
| user_permission | MyISAM |
+-------------------------+--------+
21 rows in set (0.00 sec)

Sure enough, MySQLDAO.py creates this table with the InnoDB engine:

http://filelocker2.svn.sourceforge.net/viewvc/filelocker2/trunk/core/dao/MySQLDAO.py?revision=527&view=markup

1568 CREATE TABLE session (
1569 id varchar(40) NOT NULL,
1570 data text DEFAULT NULL,
1571 expiration_time DATETIME DEFAULT NULL,
1572 PRIMARY KEY (id) ) ENGINE=InnoDB
1573 """]

I assume this is due to the need for locked reads in the below?

http://filelocker2.svn.sourceforge.net/viewvc/filelocker2/trunk/core/dao/MySQLDAO.py?revision=527&view=markup

1394 def acquire_lock(self):
1395 """Acquire an exclusive lock on the currently-loaded session data."""
1396 # MySQL doesn't have row level locking for the MyISAM style db
1397 self.locked = True
1398 self.execute('SELECT id FROM session WHERE id=%s LOCK IN SHARE MODE',
1399 (self.id,))

-nick

[Anonymous]

Seeing the same thing sitting behind apache. Changed tools.sessions.storage_type="ram" from = db to see if that helps. I'll be implementing some haproxy lb's, I'll let you know how that goes.

[Nick Silkey]

I also figured that setting sessions to db was the culprit, which is pretty essential if you want to have > 1 node behind a reverse proxy.

How will you perform session management if you put sessions in ram + front multiple filelocker nodes with haproxy? Large persistence/affinity window?

[Anonymous]

So haproxy will do client/server affinity by source ip or cookie. It would not be ideal as a front end failure would kill all sessions for those users, but at least they could start a new session on another front end.

[Mike Burns]

FYI. We're also seeing the same traceback with multiple filelocker nodes and tools.sessions.storage_type="db" using Filelocker 2.4.5, CherryPy 3.1.2, and RHEL 6.2. We would like to see a resolution to this problem.