Closed Bug 1185264 Opened 11 years ago Closed 11 years ago

Tiles monitoring server is failing due to buggy splice index check

Categories

(Content Services Graveyard :: Tiles: Ops, defect)

Product:
Content Services Graveyard
Component:
Tiles: Ops
Type:
defect
Priority:
Not set
Severity:
normal

Tracking

(Not tracked)

Status:
VERIFIED FIXED

People

(Reporter: mostlygeek, Assigned: mostlygeek)

Details

The tiles monitoring server is triggering various tiles alarms due to a buggy splice index check script. Eventually it becomes impossible to ssh into the server to see what the issue is and we have to terminate and wait for the ASG to create a new server. The problem is /usr/local/bin/splice_tiles_index_crawl.sh, which is run by cron every minute. This script opens dozens of HTTPS/TCP connections to the CDN to check if an asset is there. There seems to be a bug in it that causes it to crash and never finish. As a result there are a lot of left over TCP connections in a CLOSE_WAIT state: [root@ip-172-31-12-61 bwong]# lsof | grep ^python | grep TCP | awk '{print $NF}' | sort | uniq -c 9394 (CLOSE_WAIT) 44 (ESTABLISHED) 1 (LISTEN) [root@ip-172-31-12-61 bwong]# ps axfu | grep tile_index_crawl | grep -v grep root 12869 0.6 11.2 1296992 434888 ? Sl 16:48 0:07 /opt/splice/bin/python /opt/splice/bin/tile_index_crawl.py -v root 13027 0.7 11.2 1296740 434772 ? Sl 16:49 0:07 /opt/splice/bin/python /opt/splice/bin/tile_index_crawl.py -v root 13514 1.0 11.3 1297576 435608 ? Sl 16:52 0:09 /opt/splice/bin/python /opt/splice/bin/tile_index_crawl.py -v These failed processes never exit and continue to hold onto file handles, stacking up until the server gets stuck, and we can't even SSH in.
NOTE: I stopped crond.service so no more additional splice tile crawls are run Cleaning up stuck processes: > ps axfu | grep tile_index_crawl | grep -v grep | awk '{print $2}' | xargs kill > lsof | grep ^python | grep TCP | awk '{print $NF}' | sort | uniq -c 1 (LISTEN) We see that things have returned to a normal state.
Jul 18 16:44:35 localhost splice_tiles_index_crawl: Traceback (most recent call last): Jul 18 16:44:35 localhost splice_tiles_index_crawl: File "/opt/splice/lib/python2.7/site-packages/gevent/greenlet.py", line 327, in run Jul 18 16:44:35 localhost splice_tiles_index_crawl: result = self._run(*self.args, **self.kwargs) Jul 18 16:44:35 localhost splice_tiles_index_crawl: File "/opt/splice/lib/python2.7/site-packages/grequests.py", line 71, in send Jul 18 16:44:35 localhost splice_tiles_index_crawl: self.url, **merged_kwargs) Jul 18 16:44:35 localhost splice_tiles_index_crawl: File "/opt/splice/lib/python2.7/site-packages/requests/sessions.py", line 465, in request Jul 18 16:44:35 localhost splice_tiles_index_crawl: resp = self.send(prep, **send_kwargs) Jul 18 16:44:35 localhost splice_tiles_index_crawl: File "/opt/splice/lib/python2.7/site-packages/requests/sessions.py", line 573, in send Jul 18 16:44:35 localhost splice_tiles_index_crawl: r = adapter.send(request, **kwargs) Jul 18 16:44:35 localhost splice_tiles_index_crawl: File "/opt/splice/lib/python2.7/site-packages/requests/adapters.py", line 431, in send Jul 18 16:44:35 localhost splice_tiles_index_crawl: raise SSLError(e, request=request) Jul 18 16:44:35 localhost splice_tiles_index_crawl: SSLError: [Errno 8] _ssl.c:504: EOF occurred in violation of protocol Jul 18 16:44:35 localhost splice_tiles_index_crawl: <Greenlet at 0x2ea6a50: <bound method AsyncRequest.send of <grequests.AsyncRequest object at 0x2fa1ad0>>(stream=False)> failed with SSLError Jul 18 16:44:35 localhost splice_tiles_index_crawl: Jul 18 16:44:59 localhost splice_tiles_index_crawl: successes: 479 Jul 18 16:44:59 localhost splice_tiles_index_crawl: errors: 1 Jul 18 16:51:28 localhost splice_tiles_index_crawl: Traceback (most recent call last): Jul 18 16:51:28 localhost splice_tiles_index_crawl: File "/opt/splice/lib/python2.7/site-packages/gevent/greenlet.py", line 327, in run Jul 18 16:51:28 localhost splice_tiles_index_crawl: result = self._run(*self.args, **self.kwargs) Jul 18 16:51:28 localhost splice_tiles_index_crawl: File "/opt/splice/lib/python2.7/site-packages/grequests.py", line 71, in send Jul 18 16:51:28 localhost splice_tiles_index_crawl: self.url, **merged_kwargs) Jul 18 16:51:28 localhost splice_tiles_index_crawl: File "/opt/splice/lib/python2.7/site-packages/requests/sessions.py", line 465, in request Jul 18 16:51:28 localhost splice_tiles_index_crawl: resp = self.send(prep, **send_kwargs) Jul 18 16:51:28 localhost splice_tiles_index_crawl: File "/opt/splice/lib/python2.7/site-packages/requests/sessions.py", line 573, in send Jul 18 16:51:28 localhost splice_tiles_index_crawl: r = adapter.send(request, **kwargs) Jul 18 16:51:28 localhost splice_tiles_index_crawl: File "/opt/splice/lib/python2.7/site-packages/requests/adapters.py", line 431, in send Jul 18 16:51:28 localhost splice_tiles_index_crawl: raise SSLError(e, request=request) Jul 18 16:51:28 localhost splice_tiles_index_crawl: SSLError: [Errno 8] _ssl.c:504: EOF occurred in violation of protocol Jul 18 16:51:28 localhost splice_tiles_index_crawl: <Greenlet at 0x436dd70: <bound method AsyncRequest.send of <grequests.AsyncRequest object at 0x3fde9d0>>(stream=False)> failed with SSLError Jul 18 16:51:28 localhost splice_tiles_index_crawl: Jul 18 16:52:37 localhost splice_tiles_index_crawl: Traceback (most recent call last): Jul 18 16:52:37 localhost splice_tiles_index_crawl: File "/opt/splice/lib/python2.7/site-packages/gevent/greenlet.py", line 327, in run Jul 18 16:52:37 localhost splice_tiles_index_crawl: result = self._run(*self.args, **self.kwargs) Jul 18 16:52:37 localhost splice_tiles_index_crawl: File "/opt/splice/lib/python2.7/site-packages/grequests.py", line 71, in send Jul 18 16:52:37 localhost splice_tiles_index_crawl: self.url, **merged_kwargs) Jul 18 16:52:37 localhost splice_tiles_index_crawl: File "/opt/splice/lib/python2.7/site-packages/requests/sessions.py", line 465, in request Jul 18 16:52:37 localhost splice_tiles_index_crawl: resp = self.send(prep, **send_kwargs) Jul 18 16:52:37 localhost splice_tiles_index_crawl: File "/opt/splice/lib/python2.7/site-packages/requests/sessions.py", line 573, in send Jul 18 16:52:37 localhost splice_tiles_index_crawl: r = adapter.send(request, **kwargs) Jul 18 16:52:37 localhost splice_tiles_index_crawl: File "/opt/splice/lib/python2.7/site-packages/requests/adapters.py", line 415, in send Jul 18 16:52:37 localhost splice_tiles_index_crawl: raise ConnectionError(err, request=request) Jul 18 16:52:37 localhost splice_tiles_index_crawl: ConnectionError: ('Connection aborted.', BadStatusLine("''",)) Jul 18 16:52:37 localhost splice_tiles_index_crawl: <Greenlet at 0x38db410: <bound method AsyncRequest.send of <grequests.AsyncRequest object at 0x3390050>>(stream=False)> failed with ConnectionError Jul 18 16:52:37 localhost splice_tiles_index_crawl: Jul 18 16:52:42 localhost splice_tiles_index_crawl: Traceback (most recent call last): Jul 18 16:52:42 localhost splice_tiles_index_crawl: File "/opt/splice/lib/python2.7/site-packages/gevent/greenlet.py", line 327, in run Jul 18 16:52:42 localhost splice_tiles_index_crawl: result = self._run(*self.args, **self.kwargs) Jul 18 16:52:42 localhost splice_tiles_index_crawl: File "/opt/splice/lib/python2.7/site-packages/grequests.py", line 71, in send Jul 18 16:52:42 localhost splice_tiles_index_crawl: self.url, **merged_kwargs) Jul 18 16:52:42 localhost splice_tiles_index_crawl: File "/opt/splice/lib/python2.7/site-packages/requests/sessions.py", line 465, in request Jul 18 16:52:42 localhost splice_tiles_index_crawl: resp = self.send(prep, **send_kwargs) Jul 18 16:52:42 localhost splice_tiles_index_crawl: File "/opt/splice/lib/python2.7/site-packages/requests/sessions.py", line 573, in send Jul 18 16:52:42 localhost splice_tiles_index_crawl: r = adapter.send(request, **kwargs) Jul 18 16:52:42 localhost splice_tiles_index_crawl: File "/opt/splice/lib/python2.7/site-packages/requests/adapters.py", line 431, in send Jul 18 16:52:42 localhost splice_tiles_index_crawl: raise SSLError(e, request=request) Jul 18 16:52:42 localhost splice_tiles_index_crawl: SSLError: [Errno 8] _ssl.c:504: EOF occurred in violation of protocol Jul 18 16:52:42 localhost splice_tiles_index_crawl: <Greenlet at 0x39e2c30: <bound method AsyncRequest.send of <grequests.AsyncRequest object at 0x36dae90>>(stream=False)> failed with SSLError Jul 18 16:52:42 localhost splice_tiles_index_crawl: Jul 18 16:53:35 localhost splice_tiles_index_crawl: test Jul 18 16:54:27 localhost splice_tiles_index_crawl: successes: 41 Jul 18 16:54:27 localhost splice_tiles_index_crawl: errors: 0 Jul 18 17:22:24 localhost splice_tiles_index_crawl: successes: 480 Jul 18 17:22:24 localhost splice_tiles_index_crawl: errors: 0 Jul 18 17:24:01 localhost splice_tiles_index_crawl: LOCK FILE exists, ending early Jul 18 17:25:01 localhost splice_tiles_index_crawl: LOCK FILE exists, ending early Jul 18 17:26:01 localhost splice_tiles_index_crawl: LOCK FILE exists, ending early Jul 18 17:27:02 localhost splice_tiles_index_crawl: LOCK FILE exists, ending early Jul 18 17:28:01 localhost splice_tiles_index_crawl: LOCK FILE exists, ending early Jul 18 17:28:19 localhost splice_tiles_index_crawl: successes: 343 Jul 18 17:28:19 localhost splice_tiles_index_crawl: errors: 0 Jul 18 17:30:01 localhost splice_tiles_index_crawl: LOCK FILE exists, ending early Jul 18 17:30:39 localhost splice_tiles_index_crawl: Traceback (most recent call last): Jul 18 17:30:39 localhost splice_tiles_index_crawl: File "/opt/splice/lib/python2.7/site-packages/gevent/greenlet.py", line 327, in run Jul 18 17:30:39 localhost splice_tiles_index_crawl: result = self._run(*self.args, **self.kwargs) Jul 18 17:30:39 localhost splice_tiles_index_crawl: File "/opt/splice/lib/python2.7/site-packages/grequests.py", line 71, in send Jul 18 17:30:39 localhost splice_tiles_index_crawl: self.url, **merged_kwargs) Jul 18 17:30:39 localhost splice_tiles_index_crawl: File "/opt/splice/lib/python2.7/site-packages/requests/sessions.py", line 465, in request Jul 18 17:30:39 localhost splice_tiles_index_crawl: resp = self.send(prep, **send_kwargs) Jul 18 17:30:39 localhost splice_tiles_index_crawl: File "/opt/splice/lib/python2.7/site-packages/requests/sessions.py", line 573, in send Jul 18 17:30:39 localhost splice_tiles_index_crawl: r = adapter.send(request, **kwargs) Jul 18 17:30:39 localhost splice_tiles_index_crawl: File "/opt/splice/lib/python2.7/site-packages/requests/adapters.py", line 415, in send Jul 18 17:30:39 localhost splice_tiles_index_crawl: raise ConnectionError(err, request=request) Jul 18 17:30:39 localhost splice_tiles_index_crawl: ConnectionError: ('Connection aborted.', BadStatusLine("''",)) Jul 18 17:30:39 localhost splice_tiles_index_crawl: <Greenlet at 0x3dc9b90: <bound method AsyncRequest.send of <grequests.AsyncRequest object at 0x38dde50>>(stream=False)> failed with ConnectionError Jul 18 17:30:39 localhost splice_tiles_index_crawl: Jul 18 17:40:19 localhost splice_tiles_index_crawl: successes: 342 Jul 18 17:40:19 localhost splice_tiles_index_crawl: errors: 1
Oops, here's a easier to read log dump (damn you bugzilla), https://mostlygeek.pastebin.mozilla.org/8839908
Since it's the weekend, I patched the server (directly) with some work arounds: 1. patched splice_tiles_index_crawl.sh to have a lock file so only one can run at a time 2. added a watchdog in case splice_tiles_index_crawl.sh gets stuck 3. Updated crontab New code here: https://gist.github.com/mostlygeek/de4b558b9f275661b381 Changes: - /opt/splice/bin/tile_index_crawl.py: - needs to handle errors better - perhaps reuse the HTTPS connection, TLS handshakes are expensive! - an HTTPS connection pool? max, 10 connections? - have a timeout? so it exists correctly! - running cronjobs with * * * * * MUST consider issues with parallelism (onyx_to_redshift) - onyx_geoip_api_test.sh should take the above into consideration too (connection pool, parallelism, error handling, etc) Assigning this bug to :relud to look at and consider how to make monitoring more stable
Assignee: nobody → dthornton
Also: - consider running checks once every 5 minutes. - running once / minute generates a lot of traffic and uses up a lot of server resources Logs after the changes were implemented: - lock code saves us often! - check times can vary greatly Jul 18 18:17:19 localhost splice_tiles_index_crawl: successes: 479, errors: 1 Jul 18 18:18:22 localhost splice_tiles_index_crawl: successes: 480, errors: 0, took: 21 seconds Jul 18 18:19:40 localhost splice_tiles_index_crawl: successes: 480, errors: 0, took: 39 seconds Jul 18 18:20:23 localhost splice_tiles_index_crawl: successes: 480, errors: 0, took: 22 seconds Jul 18 18:22:01 localhost splice_tiles_index_crawl: LOCK FILE exists, ending early Jul 18 18:22:07 localhost splice_tiles_index_crawl: successes: 480, errors: 0, took: 66 seconds Jul 18 18:23:54 localhost splice_tiles_index_crawl: successes: 480, errors: 0, took: 53 seconds Jul 18 18:25:01 localhost splice_tiles_index_crawl: LOCK FILE exists, ending early Jul 18 18:25:07 localhost splice_tiles_index_crawl: successes: 480, errors: 0, took: 66 seconds Jul 18 18:26:41 localhost splice_tiles_index_crawl: successes: 480, errors: 0, took: 40 seconds Jul 18 18:28:01 localhost splice_tiles_index_crawl: LOCK FILE exists, ending early Jul 18 18:28:37 localhost splice_tiles_index_crawl: successes: 480, errors: 0, took: 96 seconds Jul 18 18:29:52 localhost splice_tiles_index_crawl: successes: 480, errors: 0, took: 51 seconds Jul 18 18:30:33 localhost splice_tiles_index_crawl: successes: 480, errors: 0, took: 32 seconds Jul 18 18:31:21 localhost splice_tiles_index_crawl: successes: 480, errors: 0, took: 20 seconds Jul 18 18:32:23 localhost splice_tiles_index_crawl: successes: 480, errors: 0, took: 22 seconds Jul 18 18:33:28 localhost splice_tiles_index_crawl: successes: 480, errors: 0, took: 27 seconds Jul 18 18:34:29 localhost splice_tiles_index_crawl: successes: 480, errors: 0, took: 28 seconds
Also: A log line like this: splice_tiles_index_crawl: (WATCHDOG) PID 12345, running for 240 seconds. Killing it. Will appear in /var/log/messages if the Watchdog actually kills a stuck process
thanks for the great work digging into this problem, and all of the logs and info. i'll work on this on monday.
After the tiles meeting today this is what we're going to be doing: Change to: tile_index_crawl.py - use connection pooling to reuse the https connections - use "imap" instead of "map" in the python code (faster/out of order) Changes to cron jobs: - Remove lock/watch dog (to see if fixed scripts are more stable). Actually will just revert to what's in puppet-config If script is still resource intensive: - look at adding a lock/watch dog so only 1 can run at a time - only run the check if any of the index files has changed - run the cronjob less frequently, once / 2 min, 3 min or 5min - etc.
Assigning to nanj for the splice script updates, then I will deploy them.
Assignee: dthornton → najiang
QA Contact: kthiessen
:nanj updated the tile_index_crawl.py, it is available under splice 1.1.27. Testing it: - Works. Uses about 20x to 30x fewer open files. Using `lsof`, the previous crawl had 3000+ open files. The new one uses about 120 to 130. It should also use less CPU as we reuse the TLS connection. - had to deploy an empty hello_tile_index_v3.json to the S3 bucket (it would error otherwise) - it also checks desktop-prerelease and hello indexes (the old one didn't) Looks good Deploying it to prod.
Assignee: najiang → bwong
Deployed to prod. Checked and it looks good. Producing metrics and not using as much resources.
Status: NEW → RESOLVED
Closed: 11 years ago
Resolution: --- → FIXED
Status: RESOLVED → VERIFIED
You need to log in before you can comment on or make changes to this bug.