478652 - [Windows] Intermittent Mochitest "test_access_control.html | Test timed out"

Status: RESOLVED FIXED

(Core :: Audio/Video, defect)

Description

[Serge Gautherie (:sgautherie)]

For example:
{
http://tinderbox.mozilla.org/showlog.cgi?log=SeaMonkey/1234700671.1234706254.29323.gz
Win2k3 comm-central dep unit test on 2009/02/15 04:24:31

[...]
result loaded*** 26918 INFO TEST-PASS | /tests/content/media/video/test/test_access_control.html | Can load from different port on same domain with allow-origin
NEXT ERROR *** 26919 ERROR TEST-UNEXPECTED-FAIL | /tests/content/media/video/test/test_access_control.html | Test timed out.
}
and
{
http://tinderbox.mozilla.org/showlog.cgi?log=SeaMonkey/1234714851.1234720340.2182.gz
Win2k3 comm-central dep unit test on 2009/02/15 08:20:51
}

(And this failure then triggers bug 451949.)

This test was added by bug 451958:
could someone "Blocks" on it, and possibly cc me to it ?

Comment 1

[Serge Gautherie (:sgautherie)]

(In reply to comment #0)
> This test was added by bug 451958:
> could someone "Blocks" on it, and possibly cc me to it ?

Done :-)

Comment 2

[Chris Pearce [:cpearce (Not reading bugmail)]]

The patch for bug 476731 made some changes to the access controls test, to remove some intermittent failures that where showing up when working on that bug, so now that it's landed, does the test failure still show up?

Comment 3

[Serge Gautherie (:sgautherie)]

(In reply to comment #2)
> [...] bug 476731 [...] landed, does the test failure still show up?

Landed on trunk, but not on 1.9.1 yet ... so I can't tell wrt SeaMonkey tinderbox(es).

If you have examples of other tinderboxes failing (before/after), please add a comment.

Comment 4

[Serge Gautherie (:sgautherie)]

(In reply to comment #3)
> Landed on trunk, but not on 1.9.1 yet

I was going to file a bug about the
{
result [...]*** 26905 INFO TEST-PASS | /tests/content/media/video/test/test_access_control.html | [...]
}
(wrong) output but I see this is already fixed on trunk :-)

Comment 5

[Serge Gautherie (:sgautherie)]

Firefox has a similar(/same !?) issue:
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox3.1/1234885710.1234890838.16319.gz
WINNT 5.2 mozilla-1.9.1 unit test on 2009/02/17 07:48:30
{
result loaded*** 27260 INFO TEST-PASS | /tests/content/media/video/test/test_access_control.html | Can load from different port on same domain with allow-origin

command timed out: 300 seconds without output
program finished with exit code 1
}

Comment 6

[Markus Stange [:mstange]]

Today it timed out on Firefox trunk:
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1236773232.1236777577.22588.gz#err0
OS X 10.5.2 mozilla-central unit test on 2009/03/11 05:07:12

Comment 7

[Chris Pearce [:cpearce (Not reading bugmail)]]

Attachment: Mochitest changes to show bug in opt builds

Ok, with these changes to test_access_control.html I can reproduce the bug hang.

This changes the testcase so that it loops infinitely trying an access-control-allowed and then disallowed load. After a while it will hang. It reproduces a lot more reliably in opt builds, and adding more logging tends to reduce the chance of the bug happening, so it's probably a timing issue.

Comment 8

[Chris Pearce [:cpearce (Not reading bugmail)]]

Ok, so the problem here is that the test is listening for loadeddata events, and sometimes we don't deliver them.

In a normal load, we usually receive these events:
loadstart progress durationchange loadedmetadata loadeddata progress canplay canplaythrough load

But sometimes we receive them in this order:
loadstart progress durationchange loadedmetadata canplay canplaythrough progress canplay canplaythrough load

The test is waiting on loadeddata which will never come, hence the failure.

Comment 9

[Chris Pearce [:cpearce (Not reading bugmail)]]

Attachment: Patch v1

* Rearrange nsHTMLMediaElement::ChangeReadyState() so that it always sends loaded data the first time readyState transitions to HAVE_CURRENT_DATA or greater.

Comment 10

[Chris Pearce [:cpearce (Not reading bugmail)]]

(In reply to comment #9)
> Created an attachment (id=367713) [details]
> Patch v1
* Mochitests pass on Linux and Windows with this patch BTW.

Comment 11

[Robert O'Callahan (:roc) (email my personal email if necessary)]

+static const char* ReadyStateToString(nsMediaReadyState aState)
+{
+  switch (aState) {
+  case nsIDOMHTMLMediaElement::HAVE_NOTHING: return "HAVE_NOTHING";
+  case nsIDOMHTMLMediaElement::HAVE_METADATA: return "HAVE_METADATA";
+  case nsIDOMHTMLMediaElement::HAVE_CURRENT_DATA: return "HAVE_CURRENT_DATA";
+  case nsIDOMHTMLMediaElement::HAVE_FUTURE_DATA: return "HAVE_FUTURE_DATA";
+  case nsIDOMHTMLMediaElement::HAVE_ENOUGH_DATA: return "HAVE_ENOUGH_DATA";
+  default: return "ERROR_UNKNOWN_STATE";
+  }
+}

Just use a static const array and make it #ifdef DEBUG

+  if (mReadyState >= nsIDOMHTMLMediaElement::HAVE_CURRENT_DATA && 
+      oldState <= nsIDOMHTMLMediaElement::HAVE_METADATA &&
+      !mLoadedFirstFrame)

I think this would be more readable if we put the old state check first and wrot the same constant in both places:
  if (oldState < nsIDOMHTMLMediaElement::HAVE_CURRENT_DATA &&
      mReadyState >= nsIDOMHTMLMediaElement::HAVE_CURRENT_DATA &&
      !mLoadedFirstFrame)
Similar for the other oldState/mReadyState checks.

Hmm, can't we get rid of these nsIDOMHTMLMediaElement:: prefixes? Those constants should be inherited in here anyway.

I think we should break up the mReadyState == nsIDOMHTMLMediaElement::HAVE_ENOUGH_DATA actions into separate if statements. Then by changing the conditions we can share the code that triggers "canplay", and we can share the code that triggers "playing".

Comment 12

[Chris Pearce [:cpearce (Not reading bugmail)]]

Attachment: Patch v2

> Hmm, can't we get rid of these nsIDOMHTMLMediaElement:: prefixes? Those
> constants should be inherited in here anyway.

Unfortunately not. nsHTMLMediaElement does not inherit from nsIDOMHTMLMediaElement, only nsHTMLVideoElement and nsHTMLAudioElement do.

I made the other changes you suggested. They allow a bit of code reuse, but I think the if-statement changes make it harder to see whether we follow the spec.

Tests still pass on Windows.

Comment 13

[Robert O'Callahan (:roc) (email my personal email if necessary)]

+  if (oldState < nsIDOMHTMLMediaElement::HAVE_FUTURE_DATA && 
+      (mReadyState == nsIDOMHTMLMediaElement::HAVE_FUTURE_DATA || 
+       mReadyState == nsIDOMHTMLMediaElement::HAVE_ENOUGH_DATA)) {

mReadyState >= nsIDOMHTMLMediaElement::HAVE_FUTURE_DATA

+     (mReadyState == nsIDOMHTMLMediaElement::HAVE_ENOUGH_DATA ||
+      mReadyState == nsIDOMHTMLMediaElement::HAVE_FUTURE_DATA) &&

Ditto

+      mReadyState == nsIDOMHTMLMediaElement::HAVE_ENOUGH_DATA) {

For symmetry, >= here

I like this code arrangement personally.

Comment 14

[Chris Pearce [:cpearce (Not reading bugmail)]]

Attachment: Patch v3 [Checkin: Comment 15 & 17]

Comment 15

[Serge Gautherie (:sgautherie)]

Comment on attachment 367940 [details] [diff] [review]
Patch v3
[Checkin: Comment 15 & 17]


http://hg.mozilla.org/mozilla-central/rev/aeada77bb251

Comment 16

[Serge Gautherie (:sgautherie)]

http://tinderbox.mozilla.org/showlog.cgi?log=SeaMonkey/1237621406.1237628858.2843.gz
MacOSX 10.4 comm-central dep unit test on 2009/03/21 00:43:26
and triggered bug 481949:
looking forward to 1.9.1 landing.

Comment 17

[Robert O'Callahan (:roc) (email my personal email if necessary)]

http://hg.mozilla.org/releases/mozilla-1.9.1/rev/2b44c51033c0