Closed Bug 1592781 Opened 3 months ago Closed 2 months ago

Intermittent TVw ::: Test verification FAIL | ERROR - TinderboxPrint: Per-test run of .../cors-check.https.html<br/>: FAILURE

Categories

(Core :: Web Audio, defect, P5)

defect

Tracking

()

RESOLVED FIXED
mozilla72
Tracking Status
firefox72 --- fixed

People

(Reporter: intermittent-bug-filer, Assigned: karlt, NeedInfo)

References

(Regression)

Details

(Keywords: intermittent-failure, Whiteboard: , [wptsync upstream][stockwell unknown])

Attachments

(6 files)

Filed by: apavel [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=273755816&repo=autoland
Full log: https://queue.taskcluster.net/v1/task/QGUJZ9_iQrqdezpyib-RZw/runs/0/artifacts/public/logs/live_backing.log
Reftest URL: https://hg.mozilla.org/mozilla-central/raw-file/tip/layout/tools/reftest/reftest-analyzer.xhtml#logurl=https://queue.taskcluster.net/v1/task/QGUJZ9_iQrqdezpyib-RZw/runs/0/artifacts/public/logs/live_backing.log&only_show_unexpected=1


[task 2019-10-30T20:06:30.379Z] 20:06:30 INFO - TEST-START | /webaudio/the-audio-api/the-mediaelementaudiosourcenode-interface/cors-check.https.html
[task 2019-10-30T20:06:30.380Z] 20:06:30 INFO - Run 9/10
[task 2019-10-30T20:06:30.388Z] 20:06:30 INFO - Closing window 39
[task 2019-10-30T20:06:30.530Z] 20:06:30 INFO - PID 15695 | ++DOCSHELL 0x7f8c3dab7800 == 1 [pid = 16239] [id = {2a2616d7-69b5-4ba9-ad6f-5d8cefee445e}]
[task 2019-10-30T20:06:30.599Z] 20:06:30 INFO - PID 15695 | ++DOMWINDOW == 1 (0x7f8c3dacdf20) [pid = 16239] [serial = 1] [outer = (nil)]
[task 2019-10-30T20:06:30.599Z] 20:06:30 INFO - PID 15695 | ++DOMWINDOW == 2 (0x7f8c3efe8800) [pid = 16239] [serial = 2] [outer = 0x7f8c3dacdf20]
[task 2019-10-30T20:06:30.782Z] 20:06:30 INFO - PID 15695 | ### XPCOM_MEM_BLOAT_LOG defined -- logging bloat/leaks to /tmp/tmpARuo_h.mozrunner/runtests_leaks_15639_tab_pid16283.log
[task 2019-10-30T20:06:30.798Z] 20:06:30 INFO - PID 15695 | [Child 16283, Main Thread] WARNING: No CID found when attempting to map contract ID: file /builds/worker/workspace/build/src/xpcom/components/nsComponentManager.cpp, line 729
[task 2019-10-30T20:06:30.941Z] 20:06:30 INFO - PID 15695 | ++DOMWINDOW == 3 (0x7f8c3dbf4c00) [pid = 16239] [serial = 3] [outer = 0x7f8c3dacdf20]
[task 2019-10-30T20:06:30.957Z] 20:06:30 INFO - PID 15695 | Couldn't convert chrome URL: chrome://branding/locale/brand.properties
[task 2019-10-30T20:06:31.115Z] 20:06:31 INFO - PID 15695 | ++DOMWINDOW == 4 (0x7f8c3efe7c00) [pid = 16239] [serial = 4] [outer = 0x7f8c3dacdf20]
[task 2019-10-30T20:06:31.132Z] 20:06:31 INFO - PID 15695 | [Child 16283, Main Thread] WARNING: could not set real-time limit at process startup: file /builds/worker/workspace/build/src/dom/ipc/ContentChild.cpp, line 1787
[task 2019-10-30T20:06:31.270Z] 20:06:31 INFO - PID 15695 | [Child 16149, Main Thread] WARNING: IPC message discarded: actor cannot send: file /builds/worker/workspace/build/src/ipc/glue/ProtocolUtils.cpp, line 481

[task 2019-10-30T20:06:35.895Z] 20:06:35 INFO - | /webaudio/the-audio-api/the-mediaelementaudiosourcenode-interface/cors-check.https.html | Executing "setting-up-graph" | PASS: 7/10, MISSING: 3/10 | |
[task 2019-10-30T20:06:35.895Z] 20:06:35 INFO -
[task 2019-10-30T20:06:35.896Z] 20:06:35 INFO - ::: Running tests in a loop 10 times : FAIL
[task 2019-10-30T20:06:35.896Z] 20:06:35 INFO - :::
[task 2019-10-30T20:06:35.897Z] 20:06:35 ERROR - ::: Test verification FAIL
[task 2019-10-30T20:06:35.897Z] 20:06:35 INFO - :::
[task 2019-10-30T20:06:36.203Z] 20:06:36 ERROR - Return code: 1
[task 2019-10-30T20:06:36.205Z] 20:06:36 ERROR - # TBPL FAILURE #
[task 2019-10-30T20:06:36.205Z] 20:06:36 WARNING - setting return code to 2
[task 2019-10-30T20:06:36.205Z] 20:06:36 ERROR - TinderboxPrint: Per-test run of .../cors-check.https.html<br/>: FAILURE
[task 2019-10-30T20:06:36.206Z] 20:06:36 INFO - Running command: ['/builds/worker/workspace/build/venv/bin/python', '-u', '/builds/worker/workspace/build/tests/web-platform/runtests.py', '--log-raw=-', '--log-raw=/builds/worker/workspace/build/blobber_upload_dir/wpt_raw.log', '--log-wptreport=/builds/worker/workspace/build/blobber_upload_dir/wptreport.json', '--log-errorsummary=/builds/worker/workspace/build/blobber_upload_dir/wpt_errorsummary.log', '--binary=/builds/worker/workspace/build/application/firefox/firefox', '--symbols-path=/builds/worker/workspace/build/symbols', '--stackwalk-binary=/builds/worker/workspace/build/linux64-minidump_stackwalk', '--stackfix-dir=/builds/worker/workspace/build/tests/bin', '--run-by-dir=3', '--no-pause-after-test', '--install-fonts', '--test-type=testharness', '--setpref=media.peerconnection.mtransport_process=false', '--setpref=network.process.enabled=false', '--stylo-threads=4', '--prefs-root=/builds/worker/workspace/build/tests/web-platform/prefs', '--processes=1', '--config=/builds/worker/workspace/build/tests/web-platform/wptrunner.ini', '--ca-cert-path=/builds/worker/workspace/build/tests/web-platform/tests/tools/certs/cacert.pem', '--host-key-path=/builds/worker/workspace/build/tests/web-platform/tests/tools/certs/web-platform.test.key', '--host-cert-path=/builds/worker/workspace/build/tests/web-platform/tests/tools/certs/web-platform.test.pem', '--certutil-binary=/builds/worker/workspace/build/tests/bin/certutil', '--verify-log-full', '--verify', u'tests/web-platform/tests/webaudio/the-audio-api/the-mediaelementaudiosourcenode-interface/no-cors.https.html'] in /builds/worker/workspace/build
[task 2019-10-30T20:06:36.207Z] 20:06:36 INFO - Copy/paste: /builds/worker/workspace/build/venv/bin/python -u /builds/worker/workspace/build/tests/web-platform/runtests.py --log-raw=- --log-raw=/builds/worker/workspace/build/blobber_upload_dir/wpt_raw.log --log-wptreport=/builds/worker/workspace/build/blobber_upload_dir/wptreport.json --log-errorsummary=/builds/worker/workspace/build/blobber_upload_dir/wpt_errorsummary.log --binary=/builds/worker/workspace/build/application/firefox/firefox --symbols-path=/builds/worker/workspace/build/symbols --stackwalk-binary=/builds/worker/workspace/build/linux64-minidump_stackwalk --stackfix-dir=/builds/worker/workspace/build/tests/bin --run-by-dir=3 --no-pause-after-test --install-fonts --test-type=testharness --setpref=media.peerconnection.mtransport_process=false --setpref=network.process.enabled=false --stylo-threads=4 --prefs-root=/builds/worker/workspace/build/tests/web-platform/prefs --processes=1 --config=/builds/worker/workspace/build/tests/web-platform/wptrunner.ini --ca-cert-path=/builds/worker/workspace/build/tests/web-platform/tests/tools/certs/cacert.pem --host-key-path=/builds/worker/workspace/build/tests/web-platform/tests/tools/certs/web-platform.test.key --host-cert-path=/builds/worker/workspace/build/tests/web-platform/tests/tools/certs/web-platform.test.pem --certutil-binary=/builds/worker/workspace/build/tests/bin/certutil --verify-log-full --verify tests/web-platform/tests/webaudio/the-audio-api/the-mediaelementaudiosourcenode-interface/no-cors.https.html
[task 2019-10-30T20:06:36.207Z] 20:06:36 INFO - Using env: (same as previous command)
[task 2019-10-30T20:06:36.207Z] 20:06:36 INFO - Calling ['/builds/worker/workspace/build/venv/bin/python', '-u', '/builds/worker/workspace/build/tests/web-platform/runtests.py', '--log-raw=-', '--log-raw=/builds/worker/workspace/build/blobber_upload_dir/wpt_raw.log', '--log-wptreport=/builds/worker/workspace/build/blobber_upload_dir/wptreport.json', '--log-errorsummary=/builds/worker/workspace/build/blobber_upload_dir/wpt_errorsummary.log', '--binary=/builds/worker/workspace/build/application/firefox/firefox', '--symbols-path=/builds/worker/workspace/build/symbols', '--stackwalk-binary=/builds/worker/workspace/build/linux64-minidump_stackwalk', '--stackfix-dir=/builds/worker/workspace/build/tests/bin', '--run-by-dir=3', '--no-pause-after-test', '--install-fonts', '--test-type=testharness', '--setpref=media.peerconnection.mtransport_process=false', '--setpref=network.process.enabled=false', '--stylo-threads=4', '--prefs-root=/builds/worker/workspace/build/tests/web-platform/prefs', '--processes=1', '--config=/builds/worker/workspace/build/tests/web-platform/wptrunner.ini', '--ca-cert-path=/builds/worker/workspace/build/tests/web-platform/tests/tools/certs/cacert.pem', '--host-key-path=/builds/worker/workspace/build/tests/web-platform/tests/tools/certs/web-platform.test.key', '--host-cert-path=/builds/worker/workspace/build/tests/web-platform/tests/tools/certs/web-platform.test.pem', '--certutil-binary=/builds/worker/workspace/build/tests/bin/certutil', '--verify-log-full', '--verify', u'tests/web-platform/tests/webaudio/the-audio-api/the-mediaelementaudiosourcenode-interface/no-cors.https.html'] with output_timeout 1000
[task 2019-10-30T20:06:36.631Z] 20:06:36 INFO - :::
[task 2019-10-30T20:06:36.631Z] 20:06:36 INFO - ::: Running test verification step "Running tests in a loop 10 times"...
[task 2019-10-30T20:06:36.631Z] 20:06:36 INFO - :::
[task 2019-10-30T20:06:36.935Z] 20:06:36 INFO - mozversion application_buildid: 20191030191348

Summary: Intermittent TVw ::: Test verification FAIL → Intermittent TVw ::: Test verification FAIL | ERROR - TinderboxPrint: Per-test run of .../cors-check.https.html<br/>: FAILURE

Karl please take a look.

Flags: needinfo?(karlt)
Regressed by: 1592503
Whiteboard: [stockwell needswork:owner]

promise_test() provides that a subtest is generated for each Task and run even
when an exception is thrown while running a previous Task.

This change also provides that Tasks that are not reached due to TIMEOUT in a
previous tests are reported NOTRUN.

The previous logic in Task.run() to generate a subtest for reporting a PASS
after calling _taskFunction() had a flaw that calls to done() during
_taskFunction() would synchronously call _testharnessDone() before the subtest
was generated.

Unhandled rejection are then reported against the appropriate subtest.

Depends on D51563

Attachment #9106109 - Attachment description: Bug 1592781 auto-finish tasks created from async functions r?jgraham → bug 1592781 auto-finish TaskRunner Tasks created from async functions r?jgraham

Raymond, the patches here make a bit of a change in the way audit.js works to provide a framework to start to address https://github.com/web-platform-tests/wpt/issues/10201

Would you like to have a look before we push this?

Phabricator doesn't make it particularly easy to fetch patches. The raw affected files that are relevant to Chrome can be downloaded, if that's helpful:
https://hg.mozilla.org/try/raw-file/be6b53219c36842748ee6bf4a7fd59d83430547c/testing/web-platform/tests/webaudio/resources/audit.js
https://hg.mozilla.org/try/raw-file/be6b53219c36842748ee6bf4a7fd59d83430547c/testing/web-platform/tests/webaudio/the-audio-api/the-audioworklet-interface/audioworklet-suspend.https.html

Or let me know if you'd prefer to discuss on github, and I'll create a PR there.

Flags: needinfo?(toy.raymond)

Search for /status": "[^PO]/ to find changes in unsuccessful results reported.

These tests now report the particular subtest that causes the test to time out:
the-audiocontext-interface/audiocontext-suspend-resume.html
the-channelmergernode-interface/active-processing.https.html
the-convolvernode-interface/active-processing.https.html
the-convolvernode-interface/realtime-conv.html
the-mediaelementaudiosourcenode-interface/cors-check.https.html

the-audioworklet-interface/audioworkletnode-output-channel-count.https.html is similar and also reports a subtest "Givien outputChannelCount must be honored." that is not run.

Attachment #9107088 - Attachment is patch: true

Can't really figure out what you want to change in audit.js. As mentioned in https://github.com/web-platform-tests/wpt/issues/10201, I find it super useful to see the output array. This is particularly useful when comparing runs across platforms.

If the output is not consistent between runs, that points to perhaps a bug in the implementation (we've found some in chrome this way), or a bug in the test where it's making assumptions that aren't true (which we've found by testing on Firefox). I'm going to be out of the office for the next few days so I won't be able to comment much more on this until late next week.

Flags: needinfo?(toy.raymond)

(In reply to toy.raymond from comment #14)

Can't really figure out what you want to change in audit.js.

Thanks for having a quick look.

As mentioned in https://github.com/web-platform-tests/wpt/issues/10201, I find it super useful to see the output array. This is particularly useful when comparing runs across platforms.

I don't want to take away any information that is useful to you. These changes are not doing that.

Conceptually an audit.js Task corresponds to a testharness.js "subtest". These changes are providing, for each Task, a subtest which reports (some and can be made to report other) uncaught exceptions thrown and which reports if the Task fails to complete and even if the Task fails to start.

The Task subtest for reporting where exceptions are thrown was introduced in https://phabricator.services.mozilla.com/D46106#change-CifrYHlClsXl but this caused new problems, which https://phabricator.services.mozilla.com/D47025#change-CifrYHlClsXl failed to properly address. It didn't provide the other features, but the number of new results in the "meta" files provides a hint as to the quantity of Tasks that were failing to run at all because of an exception in a previous Task.

If the output is not consistent between runs, that points to perhaps a bug in the implementation (we've found some in chrome this way), or a bug in the test where it's making assumptions that aren't true (which we've found by testing on Firefox).

For the most part, these changes are about better reporting of when there is a bug. They identify the Task associated with in an uncaught exception and identify which Tasks timeout and which Tasks don't start at all.

I am, however, interested in whether you find it useful to see the output array even when the task passes?
One place where this is causing problems for wpt-chrome-dev-stability is the use of notBeConstantValueOf(), which is intended to allow the test to pass with varying output data, which leads to different subtest names.

Ah, I see it now. Yes, this makes sense.

Since notBeConstantValueOf() doesn't care about the values, it's probably best not to print any values. I do have a vague memory that I found some silly mistakes in some tests when looking at the outputs. Probably more indicative of the test not being as good as it should have been.

No objections from me on the audit.js changes you want to make.

Pushed by ktomlinson@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/195a6104b5fd
use promise_test() to schedule TaskRunner Tasks r=jgraham
https://hg.mozilla.org/integration/autoland/rev/98ce0aadba7a
catch unhandled rejections in async TaskRunner Tasks r=jgraham
https://hg.mozilla.org/integration/autoland/rev/2d26bfe54d3f
use existing promise test instead of separate subtest for step_timeout() r=jgraham
https://hg.mozilla.org/integration/autoland/rev/4f9bb3fd9920
assert that task.done() is called once only r=jgraham
https://hg.mozilla.org/integration/autoland/rev/8ac99aff562c
auto-finish TaskRunner Tasks created from async functions r=jgraham
Failed to create upstream wpt PR due to merge conflicts. This requires fixup from a wpt sync admin.
Flags: needinfo?(wptsync)
Whiteboard: [stockwell needswork:owner] → [stockwell needswork:owner], [wptsync upstream error]

The merge conflict is due to https://bugzilla.mozilla.org/show_bug.cgi?id=1583496#c13.
Those changes are mostly undone by the changes here.

Depends on: 1583496
See Also: → 1597658
See Also: 1597658
Created web-platform-tests PR https://github.com/web-platform-tests/wpt/pull/20610 for changes under testing/web-platform/tests
Whiteboard: , [wptsync upstream error][stockwell unknown] → , [wptsync upstream][stockwell unknown]
Can't merge web-platform-tests PR due to failing upstream checks:
Github PR https://github.com/web-platform-tests/wpt/pull/20610
* Community-TC (pull_request) (https://community-tc.services.mozilla.com/tasks/groups/MK_xCWaTQzOVxUI6gCtdyg)
Can't merge web-platform-tests PR due to failing upstream checks:
Github PR https://github.com/web-platform-tests/wpt/pull/20610
* Community-TC (pull_request) (https://community-tc.services.mozilla.com/tasks/groups/VOXenOqmQsGjvrhitZqyrQ)
Can't merge web-platform-tests PR due to failing upstream checks:
Github PR https://github.com/web-platform-tests/wpt/pull/20610
* Community-TC (pull_request) (https://community-tc.services.mozilla.com/tasks/groups/KZmSIyO6Rl-m6vl260h2-Q)
Upstream PR merged by jgraham
You need to log in before you can comment on or make changes to this bug.