740360 - balrog needs to make sure connections are always closed

Status: RESOLVED FIXED

(Release Engineering :: General, defect)

Description

[[e-mail] (:bhearsum)]

We hit an issue this morning where Rail's Balrog client was getting "Bad Status Line" error when making requests. After poking around the server I found that there was a bunch of seemingly hung httpd workers, as well as a bunch of open sockets. Here's everything I found:
- 21 connections to the mysql server in a CLOSE_WAIT state.
-- Sheeri looked at the mysql server, and found no connections from the aus4-dev node, so as far as that server is concerned those connections are dead
- ~50 connections to zlb nodes in a TIME_WAIT state (actual number varies a little bit)
- This exception in the application log:
ERROR:auslib.web.base:Exception on /releases/Firefox-mozilla-aurora-nightly-20120329042012/builds/Linux_x86-gcc3/kk [PUT]
Traceback (most recent call last):
  File "/usr/lib/python2.6/site-packages/flask/app.py", line 1292, in wsgi_app
    response = self.full_dispatch_request()
  File "/usr/lib/python2.6/site-packages/flask/app.py", line 1062, in full_dispatch_request
    rv = self.handle_user_exception(e)
  File "/usr/lib/python2.6/site-packages/flask/app.py", line 1060, in full_dispatch_request
    rv = self.dispatch_request()
  File "/usr/lib/python2.6/site-packages/flask/app.py", line 1047, in dispatch_request
    return self.view_functions[rule.endpoint](**req.view_args)
  File "/usr/lib/python2.6/site-packages/flask/views.py", line 56, in view
    return self.dispatch_request(*args, **kwargs)
  File "/usr/lib/python2.6/site-packages/flask/views.py", line 112, in dispatch_request
    return meth(*args, **kwargs)
  File "/data/www/aus4-admin-dev.allizom.org/aus4-admin/auslib/web/views/base.py", line 40, in put
    return self._put(*args, transaction=trans, **kwargs)
  File "/data/www/aus4-admin-dev.allizom.org/aus4-admin/auslib/web/views/base.py", line 40, in put
    return self._put(*args, transaction=trans, **kwargs)
  File "/data/www/aus4-admin-dev.allizom.org/aus4-admin/auslib/web/views/base.py", line 11, in decorated
    return f(*args, changed_by=username, **kwargs)
  File "/data/www/aus4-admin-dev.allizom.org/aus4-admin/auslib/web/views/base.py", line 24, in decorated
    if not db.permissions.hasUrlPermission(username, url, method, urlOptions=extra):
  File "/data/www/aus4-admin-dev.allizom.org/aus4-admin/auslib/db.py", line 752, in hasUrlPermission
    if self.select(where=[self.username==username, self.permission=='admin'], transaction=transaction):
  File "/data/www/aus4-admin-dev.allizom.org/aus4-admin/auslib/db.py", line 22, in convertRows
    for row in fn(*args, **kwargs):
  File "/data/www/aus4-admin-dev.allizom.org/aus4-admin/auslib/db.py", line 191, in select
    return query.execute().fetchall()
  File "/usr/lib/python2.6/site-packages/sqlalchemy/sql/expression.py", line 2667, in execute
    return e._execute_clauseelement(self, multiparams, params)
  File "/usr/lib/python2.6/site-packages/sqlalchemy/engine/base.py", line 2297, in _execute_clauseelement
    connection = self.contextual_connect(close_with_result=True)
  File "/usr/lib/python2.6/site-packages/sqlalchemy/engine/base.py", line 2334, in contextual_connect
    self.pool.connect(),
  File "/usr/lib/python2.6/site-packages/sqlalchemy/pool.py", line 210, in connect
    return _ConnectionFairy(self).checkout()
  File "/usr/lib/python2.6/site-packages/sqlalchemy/pool.py", line 371, in __init__
    rec = self._connection_record = pool._do_get()
  File "/usr/lib/python2.6/site-packages/sqlalchemy/pool.py", line 685, in _do_get
    (self.size(), self.overflow(), self._timeout))
TimeoutError: QueuePool limit of size 5 overflow 10 reached, connection timed out, timeout 30
ERROR:auslib.web.views.releases:Caught ISA 500 error.
DEBUG:auslib.web.views.releases:Balrog version is: 0.1.1
DEBUG:auslib.web.views.releases:Request path is: /releases/Firefox-mozilla-aurora-nightly-20120329042012/builds/Linux_x86-gcc3/kk
- Immediately before the above exception, a IndexError: list index out of range Exception, which is caused by bug 738755 (which has been fixed by not pulled onto the aus4-dev nodes yet)
- In the access log:
10.8.33.240 - stage-ffxbld [29/Mar/2012:06:43:25 -0700] "PUT /releases/Firefox-mozilla-central-dummy-nightly-20120329031156/builds/Linux_x86_64-gcc3/ko HTTP/1.1" 500 541 "-" "python-requests/0.10.8"
- In the error log:
[Thu Mar 29 06:43:55 2012] [error] [client 10.8.33.240] mod_wsgi (pid=9620): Exception occurred processing WSGI script '/data/www/aus4-admin-dev.allizom.org/aus4-admin/admin.wsgi'.
[Thu Mar 29 06:43:55 2012] [error] [client 10.8.33.240] Traceback (most recent call last):
[Thu Mar 29 06:43:55 2012] [error] [client 10.8.33.240]   File "/usr/lib/python2.6/site-packages/flask/app.py", line 1306, in __call__
[Thu Mar 29 06:43:55 2012] [error] [client 10.8.33.240]     return self.wsgi_app(environ, start_response)
[Thu Mar 29 06:43:55 2012] [error] [client 10.8.33.240]   File "/usr/lib/python2.6/site-packages/flask/app.py", line 1294, in wsgi_app
[Thu Mar 29 06:43:55 2012] [error] [client 10.8.33.240]     response = self.make_response(self.handle_exception(e))
[Thu Mar 29 06:43:55 2012] [error] [client 10.8.33.240]   File "/usr/lib/python2.6/site-packages/flask/app.py", line 1120, in make_response
[Thu Mar 29 06:43:55 2012] [error] [client 10.8.33.240]     return self.response_class.force_type(rv, request.environ)
[Thu Mar 29 06:43:55 2012] [error] [client 10.8.33.240]   File "/data/www/aus4-admin-dev.allizom.org/aus4-admin/vendor/lib/python/werkzeug/wrappers.py", line 711, in force_type
[Thu Mar 29 06:43:55 2012] [error] [client 10.8.33.240]     response = BaseResponse(*_run_wsgi_app(response, environ))
[Thu Mar 29 06:43:55 2012] [error] [client 10.8.33.240]   File "/data/www/aus4-admin-dev.allizom.org/aus4-admin/vendor/lib/python/werkzeug/test.py", line 818, in run_wsgi_app
[Thu Mar 29 06:43:55 2012] [error] [client 10.8.33.240]     app_iter = app(environ, start_response)
[Thu Mar 29 06:43:55 2012] [error] [client 10.8.33.240] TypeError: 'TimeoutError' object is not callable

Comment 1

[[e-mail] (:bhearsum)]

One thing we did find was that the admin application was pointed at a read-only database node. That node happened to be accidentally configured to be rw, but it makes me wonder if something else about this caused issues.

solarce changed that to point at the proper node and kicked apache, so at this point we're back to a working state. Not much more we can do unless the problem happens again.

Comment 2

[[e-mail] (:bhearsum)]

Catlee thought that ISA 500 errors might be somehow hanging up db connections or something like that. We tested this theory by running a couple of hundred requests that we know will generate 500 errors quickly, and indeed, we got the server hung up the same way again. I'm going to be getting sudo access to the nodes, and should be able to debug more efficiently with that. I'll see if i can figure out what's up!

Comment 3

[Brandon Burton [:solarce]]

sudo has been given via puppet changes.

Comment 4

[[e-mail] (:bhearsum)]

After a ton more debugging I finally figured out (with tons of help from arr, sheeri, solarce, and catlee) that the code that manages the Connection objects was never calling .close(), which makes perfect sense given the CLOSE_WAIT sockets.

After changing the application code to do that, I haven't been able to reproduce the problem.

One thing I'm still a bit unsure of is whether or not there's an issue with some networking equipment killing some connections. While debugging, sheeri found errors like this on the mysql server:
120330  9:48:20 [Warning] Aborted connection 30397518 to db: 'aus4_dev' user: 
                'aus4_dev' host: '10.8.70.207' (Got timeout reading communication packets)

And I'm not sure if those are explained by having too many open connections already. I don't think we need to debug that further for now, but if more issues crop up it's something to look into it.

Comment 5

[[e-mail] (:bhearsum)]

Attachment: ensure connections get closed in AUSTransaction context manager

I also switched insert/delete/update to use the context manager to simplify those sections of code.

Comment 6

[[e-mail] (:bhearsum)]

Attachment: pass engine to AUSTransaction

16:42 <@catlee> so are you sure you want transactions to always close their connections?
16:44 < bhearsum> pretty sure. an AUSTransaction is basically a Connection + Transaction - the 
                  connection is only held by the AUSTransaction
16:44 < bhearsum> i guess that could change at some point
16:45 < bhearsum> but the reason i wrote AUSTransaction was to let all the code that executes things 
                  work with one object, rather than managing both a Connection and Transaction 
16:45 <@catlee> ok
16:46 <@catlee> so it's weird that it's not the one opening the connection
16:46 < bhearsum> hmmm
16:46 < bhearsum> yeah, i can see that
16:46 < bhearsum> maybe it should take an engine instead, and open the connection itself?
16:46 <@catlee> yeah, that would make more sense I think
16:50 < bhearsum> alright, i'll do that

Comment 7

[[e-mail] (:bhearsum)]

Comment on attachment 611021 [details] [diff] [review]
pass engine to AUSTransaction

Landed. Jenkins run is here: https://jenkins.mozilla.org/job/Balrog/68/ (oddly, I had to force it).

Comment 8

[[e-mail] (:bhearsum)]

Thanks again everyone for all your help diagnosing this.