Mochitest failure scenarios that aren't test files need to be compatible with structured logging

ASSIGNED
Assigned to

Status

ASSIGNED
4 years ago
4 years ago

People

(Reporter: chmanchester, Assigned: chmanchester)

Tracking

Firefox Tracking Flags

(Not tracked)

Details

Attachments

(1 attachment)

Mochitest and other harnesses log failure situations that aren't assertion functions in test files. Among them are leak logging and assertion count logging, both of which have had problematic interactions with structured logging (bug 1045255 and bug 1048288). We need to log a mozharness/tbpl/treeherder friendly failure in cases test_start/test_end might not make sense without hanging on to "TEST-UNEXPECTED-FAIL".

I see a few viable approaches:

1. Model leak-checking/assertions as tests and make sure we always log test_start/test_end.
2. Log these at the error level an ensure our tools are aware of this. This entails never buffering these messages, and altering the formatter, or mozharness/tbpl/treeherder, or both so these are treated appropriately.
3. Create a new log action that means the run is broken that our tools understand.
1) This feels kind of hacky. Leaks and assertions aren't tests, they exist outside of the regular stream of test_start/test_end messages.

2) This might be simplest, though an ASSERTION or leak on its own is not an ERROR. It's only an error if there are more assertions/leaks than there is in the specified threshold.

3) I like this approach. Why work around the limitations of the protocol when we can change the protocol to suit us?
I personally think the ERROR log level conveys that exact meaning ("an error happened, and here is a string to explain it") but I'm also OK with adding a new log action!
(In reply to Andrew Halberstadt [:ahal] from comment #1)
> 1) This feels kind of hacky. Leaks and assertions aren't tests, they exist
> outside of the regular stream of test_start/test_end messages.

I'm not sure it's right to lump the assertion checker in with leaks - leak checking happens at the end of the run, whereas assertion checking happens after each test - unless I am misremembering? Also, the tests do declare the number of expected assertions in the test file itself, which kind of does make it a condition of that test file required to pass?

I guess there are other grey areas too - for example the new checks being added in bug 1032878 - they are technically outside of the test_end, but that's the whole point of them :-)
Right, if I understand how the leak checker works correctly, it seems unambiguously like a test. A special test that's implemented in the harness, but a test nonetheless.

The assertion count thing might be different; one could model it as a subtest if we were using those. Or we could have an assert_count log type with a field for the maximum number allowed and a field for the test if it's always linked to a specific test.
(In reply to Ahmed Kachkach [:akachkach] from comment #2)
> I personally think the ERROR log level conveys that exact meaning ("an error
> happened, and here is a string to explain it") but I'm also OK with adding a
> new log action!

Right, I meant that there needs to be enough assertions/leaks to surpass the threshold before we consider it an error. So we need to do some processing before logging it as an error.
So I think using ERROR isn't ideal, although it's a reasonable hack before anything else is available. There are a couple of problems with it:

a) I expect ERRORs to cause tbpl to turn red rather than orange
b) Putting information in ERROR logs makes it hard to distinguish from other ERRORs so we can't process it specially without using regexp.
(Assignee)

Updated

4 years ago
Depends on: 1045525
(Assignee)

Comment 7

4 years ago
Created attachment 8479556 [details] [diff] [review]
Make mochitest log test_end after all status messages for a test.

This takes the step of logging assertion count checks as test status messages and waiting to log test end after the assertion count checks occur, undoing the known problem with the workaround fixing bug 1048288.

Here it is on try with the assertion counts modified as in the test case demonstrating that bug:

https://tbpl.mozilla.org/?tree=Try&rev=94b16bff744b
(Assignee)

Updated

4 years ago
Assignee: nobody → cmanchester
Status: NEW → ASSIGNED
(Assignee)

Comment 8

4 years ago
Comment on attachment 8479556 [details] [diff] [review]
Make mochitest log test_end after all status messages for a test.

This relies on the idea that testUnloaded is always called, and only once, but it looks plausible. Ahmed, if you have a chance could you see if this looks ok to you? Thanks!
Attachment #8479556 - Flags: feedback?(ahmed.kachkach)
(Assignee)

Comment 9

4 years ago
My thoughts on handling this is the least worst way right now:

Log assertion checks with a test file as test status messages.

Log anything in the harness that intends to fail the job at the error level to turn the build red, and consider making logs at the warning level turn the job orange. These still need to be "TEST-UNEXPECTED" until the mozharness refactor is done. 

Sticking to the duck-typeable (unstructured) part of the logging api will be desirable for things like automationutils where we have structured and unstructured callers unless we think re-writing these code paths is a priority, but we should consider a "leakcheck" action in mozlog, because it's used by multiple suites, and I noticed tools like tbpl have a notion of "LEAK" as an overall status of a job that we may want to preserve.
Comment on attachment 8479556 [details] [diff] [review]
Make mochitest log test_end after all status messages for a test.

Review of attachment 8479556 [details] [diff] [review]:
-----------------------------------------------------------------

Looks good to me!

I think this is the best thing to do (for now?); This keeps the same implicit structure that was previously present in these logs: that all harness errors are related to some "entity", usually a filename, and that it's equivalent to a test_status message (formatting wise and on the mozharness level).
Attachment #8479556 - Flags: feedback?(ahmed.kachkach) → feedback+
(Assignee)

Updated

4 years ago
Attachment #8479556 - Flags: review?(ahalberstadt)
Comment on attachment 8479556 [details] [diff] [review]
Make mochitest log test_end after all status messages for a test.

Review of attachment 8479556 [details] [diff] [review]:
-----------------------------------------------------------------

Thanks, this makes sense and I think is the best way to handle this for now.
Attachment #8479556 - Flags: review?(ahalberstadt) → review+
(Assignee)

Comment 12

4 years ago
A more extensive (and intended to be green) try run:

https://treeherder.mozilla.org/ui/#/jobs?repo=try&revision=3681ea3c0ba7
(Assignee)

Comment 13

4 years ago
That had some orange from inbound and other fishy stuff. Again here:

https://treeherder.mozilla.org/ui/#/jobs?repo=try&revision=c3752f11bf6b
You need to log in before you can comment on or make changes to this bug.