Closed Bug 1413729 Opened 2 years ago Closed 2 years ago

Structured logging violations in web-platform --verify

Categories

(Testing :: General, enhancement)

enhancement
Not set

Tracking

(firefox59 fixed)

RESOLVED FIXED
mozilla59
Tracking Status
firefox59 --- fixed

People

(Reporter: gbrown, Assigned: gbrown)

References

Details

Attachments

(2 files, 1 obsolete file)

Bug 1405141 added --verify support to the wpt harness. In bug 1411660, I'm trying to use that in automation, but hit some structured logging problems:

1. Structured logging is bypassed, so we see lots of:

  Test harness output was not a valid structured log message

2. The normal suite_start/suite_end records are suppressed, causing:

  No suite end message was emitted by this harness.

3. The normal test_start/test_end records are suppressed, causing:

  No checks run.
:jgraham -- Here's your patch updated with the addition of dummy suite_start/end and test_start/end. It works! What do you think?

https://treeherder.mozilla.org/logviewer.html#?job_id=141484055&repo=try

[task 2017-11-01T22:58:42.945Z] 22:58:42     INFO - SUITE-START | Running 1 tests
[task 2017-11-01T22:58:42.946Z] 22:58:42     INFO - ::: Running tests in a loop 10 times : PASS
[task 2017-11-01T22:58:42.946Z] 22:58:42     INFO - ::: Running tests in a loop with restarts 5 times : PASS
[task 2017-11-01T22:58:42.947Z] 22:58:42     INFO - ::: Running tests in a loop 10 times with flags chaos_mode_flags=3 : PASS
[task 2017-11-01T22:58:42.947Z] 22:58:42     INFO - ::: Running tests in a loop with restarts 5 times with flags chaos_mode_flags=3 : PASS
[task 2017-11-01T22:58:42.948Z] 22:58:42     INFO - :::
[task 2017-11-01T22:58:42.948Z] 22:58:42     INFO - ::: Test verification PASS
[task 2017-11-01T22:58:42.948Z] 22:58:42     INFO - :::
[task 2017-11-01T22:58:42.949Z] 22:58:42     INFO - TEST-START | Test verification
[task 2017-11-01T22:58:42.949Z] 22:58:42     INFO - TEST-OK | Test verification | took 1ms
[task 2017-11-01T22:58:42.950Z] 22:58:42     INFO - SUITE-END | took 0s
[task 2017-11-01T22:58:43.360Z] 22:58:43     INFO - Return code: 0


I'm okay with this solution. There may be a better way to position the dummy start/end records...but that is tricky because logging is aware of the regular suite_start/end and test_start/end records that are being suppressed: For instance, I tried adding suite_start at the start of the verification run, but structured logging complained of nested suite_start when the first test was run.

An alternative might be to simply not suppress the normal logging. Test verification of mochitests/reftests/xpcshell does no special logging. There is a lot of output, and I limit the number of tests (max 10) per task to avoid excessive task logs, but this approach has the advantage that logging "just works" and all the normal test output is readily available for debugging.
Flags: needinfo?(james)
https://treeherder.mozilla.org/logviewer.html#?job_id=141648663&repo=try&lineNumber=1680 adds an option not to suppress the normal logging, and it seems to work better,  although there is still some logging related error.

FWIW I was hoping to use this for wpt updates and it that case it would be preferable to not limit the test number (in an ideal world we could split large numbers of tests into chunks at runtime). Is there any prospect of adding a way to make that happen?
Flags: needinfo?(james)
(In reply to James Graham [:jgraham] from comment #2)
> https://treeherder.mozilla.org/logviewer.
> html#?job_id=141648663&repo=try&lineNumber=1680 adds an option not to
> suppress the normal logging, and it seems to work better,  

Nice. 

> although there is
> still some logging related error.

The "{'error_list'..." error is debug logging from one of my patches -- nothing to worry about.

> FWIW I was hoping to use this for wpt updates and it that case it would be
> preferable to not limit the test number (in an ideal world we could split
> large numbers of tests into chunks at runtime). Is there any prospect of
> adding a way to make that happen?

In the test-verify task, I'm trying to manage two similar problems: 

 - I don't want the task to run too long: I want to give the sheriffs, etc results asap and I don't want to risk exceeding the task timeout.

 - I don't want to produce too much output, exceeding the 52 MB log limit, as in bug 1412526.

Initially I limited the test-verify run time to 1 hour, abandoning any remaining tests and leaving the task green. That usually worked, but still failed for the log limit in rare cases, so I added the 10 test limit.

I think the same concerns normally apply to test-verify-wpt.


How many tests are typically updated by a wpt update? I wonder how long it would take to verify all of them. That almost seems like a different task, and probably best to run in multiple chunks, as you suggest. I think it could be done, with some work, something like this:
 - add a test-verify-wpt-update task which only runs on a wpt update (maybe we use a particular file as a trigger)
 - make a gross estimate of how much time is required and use that to determine a fixed number of chunks for test-verify-wpt-update
 - perhaps use relaxed max run times for test-verify-wpt-update (a few hours?)
 - make the test-verify mozharness code aware of chunks, so that tests can be distributed across chunks
 - turn off or extend the limits on run time and number of tests in test-verify-wpt-update

I think I'll keep all that in mind, but not try to implement that just yet.
Attachment #8924344 - Attachment is obsolete: true
(In reply to James Graham [:jgraham] from comment #2)
> FWIW I was hoping to use this for wpt updates and it that case it would be
> preferable to not limit the test number (in an ideal world we could split
> large numbers of tests into chunks at runtime). Is there any prospect of
> adding a way to make that happen?

Now we have bug 1418375 for this.
See Also: → 1418375
Attachment #8929527 - Flags: review?(james)
Attachment #8929527 - Flags: review?(james) → review+
Attachment #8929528 - Flags: review?(james) → review+
Pushed by gbrown@mozilla.com:
https://hg.mozilla.org/integration/mozilla-inbound/rev/94fa68445ec3
Web-platform logging changes for proper structured logging in test verification; r=jgraham
https://hg.mozilla.org/integration/mozilla-inbound/rev/622c44a6c3d1
Add a --verify-log-full option to wpt; r=jgraham
https://hg.mozilla.org/mozilla-central/rev/94fa68445ec3
https://hg.mozilla.org/mozilla-central/rev/622c44a6c3d1
Status: NEW → RESOLVED
Closed: 2 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla59
You need to log in before you can comment on or make changes to this bug.