1039803 - Please re-deploy tokenserver 1.2.9 to stage

Status: VERIFIED FIXED

(Cloud Services :: Operations: Deployment Requests - DEPRECATED, task)

Description

[Benson Wong [:mostlygeek]]

+++ This bug was initially created as a clone of Bug #1036687 +++

Found a few bugs in the puppet-config / cloudformation 

- updated AMI to latest version (varan) to fix a bug w/ ephemeral0 storage not mounting correctly

- add updatingpuppet-config-common-scripts as part of the initial cloudinit process. Helps us keep all puppet pieces at the same version. This also fixes a bug which caused a dependency on hiera ::ec2_region being undefined due to the puppet code on the AMI being an earlier version

- due to the above puppet version mismatch heka is not able to aggregate logs to kibana. This should be fixed. 

- added shipping nginx error logs to kibana as well (https://github.com/mozilla-services/puppet-config/pull/692). This will be helpful for us to track the 500 errors that sometimes occur on the box.

- fix memory usage issue when there are HTTP 500 requests tokenserver processes gobble upwards of 60% of the ram and never releases it. It doesn't seem to grow past that however. Adding a `--max-requests` flag to gunicorn to recycle them after 20K requests

Comment 1

[Ryan Kelly [:rfkelly]]

> - fix memory usage issue when there are HTTP 500 requests tokenserver processes gobble upwards of 60% 
> of the ram and never releases it. It doesn't seem to grow past that however. Adding a `--max-requests`
> flag to gunicorn to recycle them after 20K requests

Do you know what triggered these 500s?  If we can reproduce this reliably it might be a nice way to get to the bottom of some memory-usage issues.

Comment 2

[Benson Wong [:mostlygeek]]

Several things. Trying to get to the bottom of all of them. Though they might be all related:

- running of our file descriptors for nginx (it was 1024 before, now 65K). 
- log_rotate using up a lot of io/cpu causing python to hang/wait for cpu, which caused nginx to timeout (maybe). Fixed by fixing a bug w/ the AMI cloudinit script.
- not a lot of visibility so no nginx error logs > kibana. they are there now

This next puppet-config release should hopefully clear up all those issues.

Comment 3

[James Bonacci [:jbonacci]]

:mostlygeek where are we this? Do we want to do some Stage testing this week? Or wait for next week?


REFs:
https://github.com/mozilla-services/svcops/pull/199
https://github.com/mozilla-services/svcops/pull/200
https://github.com/mozilla-services/puppet-config/pull/692
https://github.com/mozilla-services/puppet-config/pull/693

Comment 4

[Benson Wong [:mostlygeek]]

All the PRs above have been merged. The stack on stage is updated w/ the latest CFN / puppet code so it is ready for QA. I'd like to get it QA'd this week so we can deploy it early next week.

Comment 5

[James Bonacci [:jbonacci]]

OK. Quick verification shows a new instance for Stage:
one m3.medium
i-979bb0bc
(Token app server (tokenserver-stage))
Public DNS: ec2-54-80-214-178

Starting load tests now...

Comment 6

[James Bonacci [:jbonacci]]

Results:
10min: https://loads.services.mozilla.com/run/a7b70c10-a7c5-4809-aa5f-f1c6e8a3c5fd
https://jbonacci.pastebin.mozilla.org/5568846

30min: https://loads.services.mozilla.com/run/44d045ee-98f9-4d9b-b254-211c79255e30
https://jbonacci.pastebin.mozilla.org/5568865

60min: https://loads.services.mozilla.com/run/2dafd810-5bd9-4414-94f4-62a73dca04d5
https://jbonacci.pastebin.mozilla.org/5568878


Some Hekad errors:
See https://github.com/mozilla-services/puppet-config/issues/699

Related to that:
/media/ephemeral0/logs/tokenserver/token.error.log
Exception KeyError: KeyError(22260464,) in <module 'threading' from '/usr/lib64/python2.6/threading.pyc'> ignored

So, the Key Error shows up in the hekad logs and the token error logs...


Finally, a few nasty looking exceptions that I am pretty sure that have not seen before - in /media/ephemeral0/logs/tokenserver/token.log:
{"error": "StopIteration()", "traceback": "Uncaught exception:\n  File \"/data/tokenserver/local/lib/python2.6/site-packages/gunicorn/workers/async.py\", line 116, in handle_request\n    raise StopIteration()\n<type 'exceptions.StopIteration'>\nStopIteration()\n", "time": "2014-07-17T19:47:49.577996Z", "v": 1, "message": "Error handling request", "hostname": "ip-10-225-173-253", "pid": 30087, "op": "gunicorn.error", "name": "gunicorn.error"}

Comment 7

[Benson Wong [:mostlygeek]]

Seen the StopIteration exception before. It is a gunicorn thing when nginx closes the TCP socket without sending any data. 

see: https://github.com/benoitc/gunicorn/issues/65
Here's the actual gunicorn code: https://github.com/benoitc/gunicorn/blob/master/gunicorn/workers/async.py#L116

Not entirely sure how to silence it but it sounds like it can safely be ignored.

Comment 8

[James Bonacci [:jbonacci]]

OK. Let's have :rfkelly review all this.
It sounds like, with :whd looking at https://github.com/mozilla-services/puppet-config/issues/699 , 
we can probably move forward.
File info/size:
-rw-r--r--  1 root root 8258 Jul 17 21:05 tokenserver.stderr.log

So we are probably safe that this will not get to large before we have a proper fix.

:rfkelly r+ ?
:-)

Comment 9

[Ryan Kelly [:rfkelly]]

Those exceptions look OK, they're both shutdown-related errors.  I guess they're showing up now because of the --max-requests thing that kills the worker procs.  I filed Bug 1040396 and Bug 1040397 to follow up on them, but they needn't block this rollout.

Comment 10

[James Bonacci [:jbonacci]]

OK. Great, I am going to call this one good.

Comment 11

[James Bonacci [:jbonacci]]

Next up is Production: bug 1039749