1188132 - Log lines containing "TALOSDATA" that are not talos results, cause 10 log parse retries & parser backlogs

Status: RESOLVED FIXED

(Tree Management :: Treeherder: Data Ingestion, defect, P1)

Comment 1

[Ed Morley [:emorley]]

The failures in question were:

[2015-07-27 14:47:35,208: INFO/MainProcess] Task parse-log[c2051f0d-6047-4af5-ac67-bf10f50956f7] retry: Retry in 600s: ValueError('Invalid TALOSDATA: 13:14:19     INFO -                 "comments": "Bug 1187082 - Ensure talos always produces TALOSDATA json structure in logs so perfherder can ingest data. r=jlund", \r\n',)
[2015-07-27 14:47:35,285: INFO/MainProcess] Received task: parse-log[7a59706a-60f2-4fb8-94f9-c16188c94b64] eta:[2015-07-27 14:57:35.283045-07:00]
[2015-07-27 14:47:35,645: INFO/Worker-9] Starting new HTTPS connection (1): treeherder.mozilla.org

so tl;dr we're retrying the log parse if we weren't able to json decode the TALOSDATA line. Now since we do an exponential back-off of log parsing retries (which is a good thing when ftp.m.o is down/slow) this just meant we had lots of log parser jobs backing up, since we do up to 10 retries.

We clearly shouldn't be retrying this case, since the TALOSDATA line content isn't going to change each time, so it's just going to fail 10 times over the course of ~1 hour, slowing everything up.

Will landed a hotfix for this on a branch, but we need to fix on master too. PR is at:
https://github.com/mozilla/treeherder/pull/812

I think we should:
1) Make the TALOSDATA regex more strict
2) Either make the try-except not raise, or else make the task retry exclude this specific case.

Comment 2

[Ed Morley [:emorley]]

6000+ log parse retries:
https://rpm.newrelic.com/accounts/677903/applications/4180461/traced_errors?search%5Bname%5D=parse-log&search%5Bsort_by%5D=count&search%5Btype%5D=all&tw%5Bend%5D=1438035533&tw%5Bstart%5D=1438024933&utf8=%E2%9C%93

Comment 3

[Treeherder GitHub Bugbot]

Commit pushed to master at https://github.com/mozilla/treeherder

https://github.com/mozilla/treeherder/commit/4a6d9ca5a68c00cf1f06e85a16c70bd2d97b03a0
Bug 1188132 - Don't retry log parsing for invalid TALOSDATA log lines

Since if it failed the first time, it's always going to fail.

Comment 4

[William Lachance (:wlach)]

So I think this bug is partly an example of why blanket try/except is bad: we're retrying on errors we'll see every time. The problem isn't (just) that we're throwing an error, but how we're handling them. I would suggest that we should *only* retry on urllib2 errors (i.e. subclasses of URLError: https://docs.python.org/2/library/urllib2.html#urllib2.URLError): other errors (e.g. ValueError) indicate a permanent unresolvable problem.

Also, the original behaviour was dumb. We obviously shouldn't fail just because TALOSDATA appeared somewhere else in the log. :) The fix already applied is good, we just need to do a few more things to make sure errors like this don't recur in the future.

Comment 5

[Ed Morley [:emorley]]

Yeah agreed; though I think we should also make the TALOSDATA regex more specific, so we don't waste time trying to json decode 400 jobs in a push, if the logs include the phrase. eg match against "TALOSDATA: { .+ }" not just "TALOSDATA".

Comment 6

[Ed Morley [:emorley]]

I've just found the previously filed bug 1125104 which basically covers this case too.

Comment 7

[William Lachance (:wlach)]

Attachment: Further fixes/changes

Further fixes to make log parsing simpler and more robust in case of failure. I think most of this is self-explanatory, I guess the one exception being the simplification of TALOSDATA parsing: I found out in testing that the regular expression by itself was basically just as fast as the `"TALOSDATA" in foo` logic, so decided to just leave that in.

I think if we wanted to be extra careful here we'd write unit tests to cover this specific failure case. I'm inclined not to just because it would be rather complex for what's pretty simple (esp. now) and going away in the next few months anyway as we move away from log parsing internally.

There's no rush to review this.

Comment 8

[Cameron Dawson [:camd]]

Comment on attachment 8641867 [details] [review]
Further fixes/changes

This all looks reasonable to me.

Comment 10

[Treeherder GitHub Bugbot]

Commit pushed to master at https://github.com/mozilla/treeherder

https://github.com/mozilla/treeherder/commit/3227bafee9c9685d6c6dac6ad05ae7af18bbd167
Bug 1188132 - Further fixes to make (talos) log parsing more robust

* Simplify logic in talos parser (there was an optimization which didn't
  save anything and just caused confusion before)
* Make it so if log parsing fails for a non-http reason, we don't try
  again

Comment 11

[Treeherder GitHub Bugbot]

Commit pushed to master at https://github.com/mozilla/treeherder

https://github.com/mozilla/treeherder/commit/36342cd79c3ad6d7dd2256be554e063ed5336d2e
Bug 1188132 - Don't raise exception if 403/404 when donwloading log

This is somewhat expected (in the case of taskcluster), so we don't
want to hear about it in new relic

Comment 12

[Treeherder GitHub Bugbot]

Commit pushed to master at https://github.com/mozilla/treeherder

https://github.com/mozilla/treeherder/commit/0c632105979ba0d577a2a5747aeeea8167185573
Bug 1188132 - Add a comment linking to 403/404 taskcluster bug

Comment 13

[William Lachance (:wlach)]

I think we're done here. :)