1286252 - deal with non-fatal error messages better

Status: RESOLVED WONTFIX

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

Description

[[e-mail] (:bhearsum)]

Something I've noticed on numerous occasions is that non-fatal error messages - particularly errors that get rtried for - end up getting bugs filed or commented on by Orange Factor, other tools, and sometimes humans.

The most recent case of this is https://bugzilla.mozilla.org/show_bug.cgi?id=1223872#c18. The "error" it's noticing is a something that is automatically retried, and does not affect the job in any way other than making it slightly longer.

It would be really nice to have a way to whitelist or otherwise teach the tools about acceptable or ignorable "errors".

Comment 1

[Ed Morley [:emorley]]

For bug 1223872 in particular, that bug does not have the 'intermittent-failure' keyword set, so humans are manually entering that bug number. If the logs are confusing enough for humans, then I'm not sure how Treeherder is going to be able to handle them, unless we hardcode specific strings (and even then, the error string below is too generic - we'd risk whitelisting other failures).

The error in that log is:
 2016-07-11 13:42:12,581 - DEBUG - retry: Caught exception: 
 Traceback (most recent call last):
   File "/home/worker/tools/lib/python/vendor/redo-1.4.1/redo/__init__.py", line 152, in retry
     return action(*args, **kwargs)
   File "/home/worker/tools/lib/python/balrog/submitter/cli.py", line 304, in update_dated
     schemaVersion=schemaVersion, data_version=data_version)
   File "/home/worker/tools/lib/python/balrog/submitter/api.py", line 217, in update_build
     return self.request(method='PUT', data=data)
   File "/home/worker/tools/lib/python/balrog/submitter/api.py", line 103, in request
     return self.do_request(url, data, method)
   File "/home/worker/tools/lib/python/balrog/submitter/api.py", line 121, in do_request
     req.raise_for_status()
   File "/usr/lib/python2.7/dist-packages/requests/models.py", line 825, in raise_for_status
     raise HTTPError(http_error_msg, response=self)
HTTPError: 400 Client Error: BAD REQUEST 

IMO this really isn't the type of output that should be given for an expected error. The retry handler should be catching HTTPError (and ConnectionError for that matter), and outputting a more user-friendly error message. And then only outputting an error/traceback if the maximum retries have been hit.

We've hit this case again and again - it seems like an unfortunate design pattern that's being reused in various places (specifically: IMO it's not safe to assume a traceback can be dumped to a log if it's not an error).

That said, having a way to ignore certain output would be useful. And in fact, we already have this - in the form of the mozharness DEBUG/INFO prefixes, but we still have a lot of log output that isn't using them.

The following would help:
1) Fix this and any other retry patterns to stop dumping tracebacks if the error isn't fatal (particularly for case where the traceback isn't useful like HTTPErrors)
2) Slowly convert more log output to using mozharness (or similar) prefixes, such that we can exempt certain lines
3) Prune the Treeherder regexes, to the point where we eventually only listen to the ERROR mozharness prefix and above.

However #3 relies on #2 - if we were to do that now, we'd end up with many more false negatives (ie "error summary empty" type job failures, which cost a lot of sheriff time), than we do false positives.

As such, as filed (as a Treeherder bug) I'm struggling to see this as anything other than WORKSFORME (since treeherder exempts mozharness DEBUG/INFO lines) or WONTFIX (since the log output in this case is questionable).

Open to any other ideas I may not have thought of, however :-)

Comment 2

[Ed Morley [:emorley]]

Oops read this as a Treeherder bug, since OrangeFactor only posts what has been entered by Treeherder.
Moving there now.

Comment 3

[[e-mail] (:bhearsum)]

(In reply to Ed Morley [:emorley] from comment #1)
> For bug 1223872 in particular, that bug does not have the
> 'intermittent-failure' keyword set, so humans are manually entering that bug
> number. If the logs are confusing enough for humans, then I'm not sure how
> Treeherder is going to be able to handle them, unless we hardcode specific
> strings (and even then, the error string below is too generic - we'd risk
> whitelisting other failures).

Good to know that intermittent-failure can be used to hush some things, but it's not exactly accurate for cases like this (as I'm sure you know!)

> The error in that log is:
>  2016-07-11 13:42:12,581 - DEBUG - retry: Caught exception: 
>  Traceback (most recent call last):
>    File "/home/worker/tools/lib/python/vendor/redo-1.4.1/redo/__init__.py",
> line 152, in retry
>      return action(*args, **kwargs)
>    File "/home/worker/tools/lib/python/balrog/submitter/cli.py", line 304,
> in update_dated
>      schemaVersion=schemaVersion, data_version=data_version)
>    File "/home/worker/tools/lib/python/balrog/submitter/api.py", line 217,
> in update_build
>      return self.request(method='PUT', data=data)
>    File "/home/worker/tools/lib/python/balrog/submitter/api.py", line 103,
> in request
>      return self.do_request(url, data, method)
>    File "/home/worker/tools/lib/python/balrog/submitter/api.py", line 121,
> in do_request
>      req.raise_for_status()
>    File "/usr/lib/python2.7/dist-packages/requests/models.py", line 825, in
> raise_for_status
>      raise HTTPError(http_error_msg, response=self)
> HTTPError: 400 Client Error: BAD REQUEST 
> 
> IMO this really isn't the type of output that should be given for an
> expected error. The retry handler should be catching HTTPError (and
> ConnectionError for that matter), and outputting a more user-friendly error
> message. And then only outputting an error/traceback if the maximum retries
> have been hit.

Hrm. I don't necessarily disagree that a more user friendly message could be used, but I'm not sure I understand how it would help in this case. Even if there was no traceback, the message would still indicate that there was some sort of error? Or does simply having a traceback cause this to get picked up?

> We've hit this case again and again - it seems like an unfortunate design
> pattern that's being reused in various places (specifically: IMO it's not
> safe to assume a traceback can be dumped to a log if it's not an error).

Having extra information when we're retrying things can be useful as well, I think there's a case for not assuming every Traceback is a failure or problem. Perhaps all of that information could be conveyed in a non-traceback log message instead...

> 
> That said, having a way to ignore certain output would be useful. And in
> fact, we already have this - in the form of the mozharness DEBUG/INFO
> prefixes, but we still have a lot of log output that isn't using them.
> 
> The following would help:
> 1) Fix this and any other retry patterns to stop dumping tracebacks if the
> error isn't fatal (particularly for case where the traceback isn't useful
> like HTTPErrors)

Didn't know this existed, nice. Seems like that may be the best route here.

> Open to any other ideas I may not have thought of, however :-)

Yeah, I don't have any bright ideas unfortunately :(. It seems like one of the main issues here is that it requires parsing a bunch of lines to determine whether or not an error such us the one I linked to is ignorable.

Comment 4

[Ed Morley [:emorley]]

(In reply to Ben Hearsum (:bhearsum) from comment #3)
> Good to know that intermittent-failure can be used to hush some things, but
> it's not exactly accurate for cases like this (as I'm sure you know!)

The keyword doesn't hush things - it's more that the keyword is required on a bug for Treeherder to automatically suggest it. So in this case I can tell that the bug wasn't suggested automatically, and instead a human must have gone out of their way to enter the bug number manually.

> Hrm. I don't necessarily disagree that a more user friendly message could be
> used, but I'm not sure I understand how it would help in this case. Even if
> there was no traceback, the message would still indicate that there was some
> sort of error? Or does simply having a traceback cause this to get picked up?

So in this case, the `HTTPError` at the start of the line is matching:
r"|^[A-Za-z.]+Error: "

...from here:
https://github.com/mozilla/treeherder/blob/b60b90097e414adc98d285d396d05234bf6f959e/treeherder/log_parser/parsers.py#L377

> Having extra information when we're retrying things can be useful as well, I
> think there's a case for not assuming every Traceback is a failure or
> problem. Perhaps all of that information could be conveyed in a
> non-traceback log message instead...

True, but if the error were permanent, then the final attempt (that wasn't going to retry) would dump the full exception and fail the job, so you'd still have the traceback.

Or in the intermittent failure case (where the retry succeeds), the error could be output as:

Failure during foo bar: HTTPError(...)

Which wouldn't match the regex, and would likely still yield enough information for debugging.

Ideally HTTPErrors should be handled specifically, and additional logging info shown (eg perhaps show server response etc).

> Didn't know this existed, nice. Seems like that may be the best route here.

Ah great - I didn't know that you didn't know :-)

> Yeah, I don't have any bright ideas unfortunately :(. It seems like one of
> the main issues here is that it requires parsing a bunch of lines to
> determine whether or not an error such us the one I linked to is ignorable.

Structured logs are the true solution here really :-)

Comment 5

[Ed Morley [:emorley]]

Until we have everything using structured logs (where the log level is separate from the log message), or more complete usage of say mozharness log prefix strings (the "<timestamp> - ERROR - <log line>" style logs) we have no choice but to have regex for all sorts of error terms. 

As such, these terms should be avoided from cases where it's not a real error (eg retry). The best practice would instead be to output a "Failed due to HTTP 403, retrying 1 of 3", followed by an actual error message if all of the retries failed.