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

Status: RESOLVED FIXED

(Core :: Web Audio, defect, P5)

Description

[Treeherder Bug Filer]

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

Comment 1

[Intermittent Failures Robot]

19 failures in 703 pushes (0.027 failures/push) were associated with this bug yesterday.

Repository breakdown:

• mozilla-central: 11
• mozilla-inbound: 8

Platform breakdown:

• linux64: 3
• macosx1014-64: 2
• windows10-64: 3
• windows7-32: 3
• macosx1014-64-shippable: 2
• linux64-shippable: 2
• windows7-32-shippable: 2
• windows10-64-shippable: 2

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1592781&startday=2019-10-31&endday=2019-10-31&tree=all

Comment 2

[Andreea Pavel [:apavel]]

Karl please take a look.

Comment 3

[Karl Tomlinson (:karlt)]

https://treeherder.mozilla.org/#/jobs?repo=autoland&revision=44d87ccdfa10&searchStr=tvw&selectedJob=273265390 said "Per-test suites: []" but https://treeherder.mozilla.org/#/jobs?repo=try&revision=77508b08a6c25fd28624bfc2c448f1286feb1989&selectedJob=274328246 confirms this existed as of https://hg.mozilla.org/integration/autoland/rev/44d87ccdfa106e6f998b64cea35c45dcc7966f69

Comment 4

[Karl Tomlinson (:karlt)]

https://treeherder.mozilla.org/#/jobs?repo=try&revision=61b622ce2e22e7a8c744c4357b99c016c347a123&selectedJob=274329559

Comment 5

[Intermittent Failures Robot]

26 failures in 4314 pushes (0.006 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 7
• mozilla-central: 11
• mozilla-inbound: 8

Platform breakdown:

• linux64: 4
• windows10-64: 4
• windows7-32: 4
• macosx1014-64-shippable: 3
• windows10-64-shippable: 3
• windows7-32-shippable: 3
• linux64-shippable: 3
• macosx1014-64: 2

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1592781&startday=2019-10-28&endday=2019-11-03&tree=all

Comment 6

[Karl Tomlinson (:karlt)]

Attachment: Bug 1592781 use promise_test() to schedule TaskRunner Tasks r?jgraham

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.

Comment 7

[Karl Tomlinson (:karlt)]

Attachment: Bug 1592781 catch unhandled rejections in async TaskRunner Tasks r?jgraham

Unhandled rejection are then reported against the appropriate subtest.

Depends on D51563

Comment 8

[Karl Tomlinson (:karlt)]

Attachment: Bug 1592781 use existing promise test instead of separate subtest for step_timeout() r?jgraham

Depends on D51564

Comment 9

[Karl Tomlinson (:karlt)]

Attachment: Bug 1592781 assert that task.done() is called once only r?jgraham

Depends on D51565

Comment 10

[Karl Tomlinson (:karlt)]

Attachment: bug 1592781 auto-finish TaskRunner Tasks created from async functions r?jgraham

Depends on D51566

Comment 11

[Karl Tomlinson (:karlt)]

https://treeherder.mozilla.org/#/jobs?repo=try&revision=90bf4d91e3277b5d6fe1fbbdf129cc85bb85a381

Comment 12

[Karl Tomlinson (:karlt)]

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.

Comment 13

[Karl Tomlinson (:karlt)]

Attachment: before/after diff of results reported in Chrome 79.0.3945.8

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.

Comment 14

[toy.raymond]

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.

Comment 15

[Karl Tomlinson (:karlt)]

(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.

Comment 16

[toy.raymond]

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.

Comment 17

[Pulsebot]

Pushed by [e-mail]:
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

Comment 18

[Web Platform Test Sync Bot (Matrix: #interop:mozilla.org)]

Failed to create upstream wpt PR due to merge conflicts. This requires fixup from a wpt sync admin.

Comment 19

[Karl Tomlinson (:karlt)]

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.

Comment 20

[Daniel Varga [:dvarga]]

https://hg.mozilla.org/mozilla-central/rev/195a6104b5fd
https://hg.mozilla.org/mozilla-central/rev/98ce0aadba7a
https://hg.mozilla.org/mozilla-central/rev/2d26bfe54d3f
https://hg.mozilla.org/mozilla-central/rev/4f9bb3fd9920
https://hg.mozilla.org/mozilla-central/rev/8ac99aff562c

Comment 21

[Intermittent Failures Robot]

3 failures in 5444 pushes (0.001 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 3

Platform breakdown:

• android-em-7-0-x86_64: 1
• macosx1014-64-shippable: 1
• linux64-shippable: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1592781&startday=2019-11-18&endday=2019-11-24&tree=all

Comment 22

[Web Platform Test Sync Bot (Matrix: #interop:mozilla.org)]

Created web-platform-tests PR https://github.com/web-platform-tests/wpt/pull/20610 for changes under testing/web-platform/tests

Comment 23

[Web Platform Test Sync Bot (Matrix: #interop:mozilla.org)]

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)

Comment 24

[Web Platform Test Sync Bot (Matrix: #interop:mozilla.org)]

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)

Comment 25

[Web Platform Test Sync Bot (Matrix: #interop:mozilla.org)]

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)

Comment 26

[Web Platform Test Sync Bot (Matrix: #interop:mozilla.org)]

Upstream PR merged by jgraham