1372567 - Fix problems with structured logger in TestRunner.js

Status: RESOLVED FIXED

(Testing :: Mochitest, enhancement)

Description

[Andrew Halberstadt [:ahal]]

I was in the midst of writing some tests in bug 1372263 when I started noticing all kinds of weirdness with the structured log. Namely:

1. It's possible for several test_end messages to  be logged
2. Assertions are handled with test_end instead of test_status
3. We always log a test_end with status == "ok" no matter what (even if there were failing test_status messages)

Normally this stuff would have raised flags in mozlog, but it's not due to bug 1372565. We'll need to fix this bug before we can fix that other one.

Comment 1

[Andrew Halberstadt [:ahal]]

While the other bug needs to be fixed first, I still needed to write up the patch for this one to properly test it. So might as well get the review going too.

Comment 2

[Andrew Halberstadt [:ahal]]

Attachment: Bug 1372567 - [mozlog] Ensure state for all actions when using log_raw(),

When using log_raw(), we don't catch a lot of the state checking, such as logging a
'test_end' multiple times.

Review commit: https://reviewboard.mozilla.org/r/148496/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/148496/

Comment 3

[Andrew Halberstadt [:ahal]]

Of course I uploaded the patch to the wrong bug..

Comment 4

[Andrew Halberstadt [:ahal]]

Attachment: Bug 1372567 - Fix problems with mochitest structured logging,

The mochitest harness uses testEnd multiple times to log various failures. This can result
in several testEnd messages, which will soon cause mozlog to spit out an error. Instead,
these should be testStatus.

This also starts using mozlog's assertion_count log action to log test assertions (again,
instead of testEnd).

Review commit: https://reviewboard.mozilla.org/r/151786/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/151786/

Comment 5

[James Graham [:jgraham]]

Comment on attachment 8880403 [details]
Bug 1372567 - Fix problems with mochitest structured logging,

https://reviewboard.mozilla.org/r/151786/#review156810

Comment 6

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/25838d44520a
Fix problems with mochitest structured logging, r=jgraham

Comment 7

[Phil Ringnalda (:philor)]

Backed out in https://hg.mozilla.org/integration/autoland/rev/60ffe4e9d98d for https://treeherder.mozilla.org/logviewer.html#?job_id=109561173&repo=autoland

Comment 8

[Andrew Halberstadt [:ahal]]

I think there's an assertion that happens in-between those tests. My patch pushes the assertion check slightly earlier, probably early enough that there's a 50% chance the assertion happens after the check and therefore gets assigned to the next test. So we can either move the assertion check back to where it was or else mark both those tests with expected counts of 0-1.

The only reason the assertion check was move before testEnd was so that we could end with status==ASSERT, but that's probably not all that important. I'll move it back to where it was, it's possible there are other assertions that straddle two tests like this one, so it's the safer call.

Comment 9

[Andrew Halberstadt [:ahal]]

Comment on attachment 8880403 [details]
Bug 1372567 - Fix problems with mochitest structured logging,

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/151786/diff/1-2/

Comment 10

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/0889c455cf63
Fix problems with mochitest structured logging, r=jgraham

Comment 11

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/mozilla-central/rev/0889c455cf63