Closed Bug 1148224 Opened 5 years ago Closed 4 years ago

Intermittent mediasource-duration.html | Test appendBuffer completes previous seek to truncated duration - assert_equals: Event types match. expected "seeking" but got "timeupdate"

Categories

(Core :: Audio/Video, defect)

39 Branch
x86_64
macOS
defect
Not set

Tracking

()

RESOLVED FIXED
mozilla40
Tracking Status
firefox38 --- fixed
firefox38.0.5 --- fixed
firefox39 --- fixed
firefox40 --- fixed
firefox-esr31 --- unaffected
firefox-esr38 --- fixed
b2g-v2.2 --- unaffected
b2g-master --- fixed

People

(Reporter: KWierso, Assigned: jya)

References

Details

(Keywords: intermittent-failure)

Attachments

(1 file)

14:37:32 INFO - TEST-START | /media-source/mediasource-duration.html
14:37:32 INFO - PROCESS | 1600 | WARNING: content window passed to PrivateBrowsingUtils.isWindowPrivate. Use isContentWindowPrivate instead (but only for frame scripts).
14:37:32 INFO - PROCESS | 1600 | pbu_isWindowPrivate@resource://gre/modules/PrivateBrowsingUtils.jsm:25:14
14:37:32 INFO - PROCESS | 1600 | nsBrowserAccess.prototype.openURI@chrome://browser/content/browser.js:15373:21
14:37:32 INFO - PROCESS | 1600 | __marionetteFunc@dummy file:19:30
14:37:32 INFO - PROCESS | 1600 | @dummy file:28:3
14:37:32 INFO - PROCESS | 1600 | executeWithCallback@chrome://marionette/content/marionette-listener.js:719:5
14:37:32 INFO - PROCESS | 1600 | executeAsyncScript@chrome://marionette/content/marionette-listener.js:612:3
14:37:32 INFO - PROCESS | 1600 | E/MPEG4Extractor( 1600): No width or height, assuming worst case 1080p
14:37:32 INFO - PROCESS | 1600 | E/MPEG4Extractor( 1600): No width or height, assuming worst case 1080p
14:37:32 INFO - PROCESS | 1600 | E/MPEG4Extractor( 1600): No width or height, assuming worst case 1080p
14:37:32 INFO - PROCESS | 1600 | E/MPEG4Extractor( 1600): No width or height, assuming worst case 1080p
14:37:34 INFO - TEST-PASS | /media-source/mediasource-duration.html | Test seek starts on duration truncation below currentTime
14:37:34 INFO - TEST-UNEXPECTED-FAIL | /media-source/mediasource-duration.html | Test appendBuffer completes previous seek to truncated duration - assert_equals: Event types match. expected "seeking" but got "timeupdate"
14:37:34 INFO - EventExpectationsManager.prototype.expectEvent/eventHandler<@http://web-platform.test:8000/media-source/mediasource-util.js:86:13
14:37:34 INFO - Test.prototype.step@http://web-platform.test:8000/resources/testharness.js:1227:20
14:37:34 INFO - Test.prototype.step_func/<@http://web-platform.test:8000/resources/testharness.js:1251:1
14:37:34 INFO - TEST-UNEXPECTED-FAIL | /media-source/mediasource-duration.html | Test endOfStream completes previous seek to truncated duration - assert_equals: Event types match. expected "seeking" but got "timeupdate"
14:37:34 INFO - EventExpectationsManager.prototype.expectEvent/eventHandler<@http://web-platform.test:8000/media-source/mediasource-util.js:86:13
14:37:34 INFO - Test.prototype.step@http://web-platform.test:8000/resources/testharness.js:1227:20
14:37:34 INFO - Test.prototype.step_func/<@http://web-platform.test:8000/resources/testharness.js:1251:1
14:37:34 INFO - TEST-FAIL | /media-source/mediasource-duration.html | Test setting same duration multiple times does not fire duplicate durationchange - assert_equals: durationchanges expected 1 but got 15
14:37:34 INFO - @http://web-platform.test:8000/media-source/mediasource-duration.html:210:23
14:37:34 INFO - EventExpectationsManager.prototype.handleWaitCallback_@http://web-platform.test:8000/media-source/mediasource-util.js:117:9
14:37:34 INFO - Test.prototype.step@http://web-platform.test:8000/resources/testharness.js:1227:20
14:37:34 INFO - Test.prototype.step_func/<@http://web-platform.test:8000/resources/testharness.js:1251:1
14:37:34 INFO - TEST-OK | /media-source/mediasource-duration.html | took 1575ms
14:37:34 WARNING - u'runner_teardown' ()
14:37:34 INFO - Setting up ssl
14:37:34 INFO - PROCESS | certutil |
14:37:34 INFO - PROCESS | certutil |
14:37:34 INFO - PROCESS | certutil |
14:37:34 INFO - Certificate Nickname Trust Attributes
14:37:34 INFO - SSL,S/MIME,JAR/XPI
14:37:34 INFO -
14:37:34 INFO - web-platform-tests CT,,
14:37:34 INFO -
14:37:34 INFO - Starting runner
14:37:35 INFO - PROCESS | 1610 | -*- Webapps.jsm : Saving /var/folders/4n/n74n0twn4pqdpm97cjfm8rmc00000w/T/tmp9tcIEP.mozrunner/webapps/webapps.json
14:37:35 INFO - PROCESS | 1610 | -*- Webapps.jsm : Saving /var/folders/4n/n74n0twn4pqdpm97cjfm8rmc00000w/T/tmp9tcIEP.mozrunner/webapps/webapps.json
14:37:35 INFO - PROCESS | 1610 | -*- Webapps.jsm : Success saving /var/folders/4n/n74n0twn4pqdpm97cjfm8rmc00000w/T/tmp9tcIEP.mozrunner/webapps/webapps.json
14:37:35 INFO - PROCESS | 1610 | -*- Webapps.jsm : Success saving /var/folders/4n/n74n0twn4pqdpm97cjfm8rmc00000w/T/tmp9tcIEP.mozrunner/webapps/webapps.json
14:37:36 INFO - PROCESS | 1610 | Shumway is registered
14:37:36 INFO - TEST-START | /media-source/mediasource-endofstream-invaliderror.html
I think this is the one that showed up on an uplift that we were discussing at one point. Can you please take a look when you get a chance? Especially since 38 is going to be around for a long time.
Flags: needinfo?(jyavenard)
Skip the timeout-prone subtests on Windows for Gecko 38.
https://hg.mozilla.org/releases/mozilla-release/rev/82de02ddde1b
Flags: needinfo?(jyavenard)
Assignee: ryanvm → nobody
Depends on: 1159613
Depends on: 1159678
The tests are implicitly wrong.

They assume that the first event being fired after changing the currentTime attribute is going to be "seeking".

However, just prior it called play().

play() will be firing a "timeupdate" event; after while playback will start. The spec states that another "timeupdate" may be fired every 15 to 250ms whenever the playback position changes monotonically.

Now, the test then waits for "updateend" and "playing" to be fired, and immediately seeks to duration / 2.

Seeking is asynchronous, and will fire the "seeking" event asynchronously (step 8 of the Seeking algorithm:
http://dev.w3.org/html5/spec-preview/media-elements.html#seeking)

If more than 15 to 250ms has passed between the time the last timeupdate() got fired and the time seeking actually start, a timeupdate event could be fired.

This will cause the test to fail as it is expecting the "seeking" event right after changing the currentTime attribute.

Now, I crafted the following test:
started playback, did an appendbuffer, started a seek and immediately entered a blocking wait for 1s.
Now this should have forced timeupdate to be fired at the end of the loop (as playback is still going), and before "seeking" event got fired. And indeed this is what IE and Safari do (and so are we).

However, Chrome will always fire the "seeking" event right after seeking.

As such, the tests are they are test Chrome behaviour, and not what that behaviour should be as per the spec.

karlt your opinion on the matter would be appreciated.

With bug 1159678, there was a case where we would have genuinely misfired a "timeupdate" event so I've fixed that. But timeupdate event being undeterministic in nature, assuming that it won't get fired while playback is going is wrong.
Disable tests that will intermitently fail (and rightly so)
Attachment #8599264 - Flags: review?(karlt)
Assignee: nobody → jyavenard
Status: NEW → ASSIGNED
Comment on attachment 8599264 [details] [diff] [review]
disable invalid tests

Yes, I agree that the results of these subtests cannot be deterministic because the first timeupdate after running the first function passed to waitForExpectedEvents() from the function passed to mediasource_testafterdataloaded() from mediasource_truncated_duration_seek_test() may arrive either before or after the seeking event, because it could be either from the time marches on steps or from the seek.  Thanks very much for the analysis.

If the test would like to continue to use expectEvent(), then I think it needs to choose whether to expect seeking or timeupdate.  It can't have it both ways.
Attachment #8599264 - Flags: review?(karlt) → review+
https://hg.mozilla.org/mozilla-central/rev/f227ff5d16a3
Status: ASSIGNED → RESOLVED
Closed: 4 years ago
Flags: in-testsuite-
Resolution: --- → FIXED
Target Milestone: --- → mozilla40
See Also: → 1154881
You need to log in before you can comment on or make changes to this bug.