Closed Bug 836851 Opened 11 years ago Closed 11 years ago

Intermittent test_play_events.html | Last event should be canplaythrough for http://mochi.test:8888/tests/content/media/test/seek.webm - got playing, expected canplaythrough

Categories

(Core :: Audio/Video, defect)

Product:
Core
Component:
Audio/Video
Platform:
x86
Windows 7
Type:
defect
Priority:
Not set
Severity:
normal

Tracking

()

Status:
RESOLVED FIXED
Milestone:
mozilla27
Tracking Flags:
Tracking Status
firefox25 --- fixed
firefox26 --- fixed
firefox27 --- fixed
firefox-esr24 --- fixed

People

(Reporter: RyanVM, Unassigned)

References

Details

(Keywords: intermittent-failure) 

https://tbpl.mozilla.org/php/getParsedLog.php?id=19317911&tree=Mozilla-Inbound

Rev3 WINNT 6.1 mozilla-inbound opt test mochitest-1 on 2013-01-31 02:48:38 PST for push f54c2ac62480
slave: talos-r3-w7-075

186132 INFO TEST-START | /tests/content/media/test/test_play_events.html
186133 INFO TEST-INFO | /tests/content/media/test/test_play_events.html | Started Thu Jan 31 2013 03:07:33 GMT-0800 (Pacific Standard Time) (1359630453.777s)
186134 INFO TEST-PASS | /tests/content/media/test/test_play_events.html | [started small-shot.ogg-0] Length of array should match number of running tests
186135 INFO TEST-PASS | /tests/content/media/test/test_play_events.html | [started r11025_s16_c1.wav-3] Length of array should match number of running tests
186136 INFO TEST-PASS | /tests/content/media/test/test_play_events.html | Check expected event got play at 0 for http://mochi.test:8888/tests/content/media/test/small-shot.ogg uneval(event.type)="play" typeof(event.type)=string uneval(v._state)=0 typeof(v._state)=number tokens[0]=play tokens[0].indexOf(event.type)=0
186137 INFO TEST-PASS | /tests/content/media/test/test_play_events.html | Check expected event got play at 0 for http://mochi.test:8888/tests/content/media/test/r11025_s16_c1.wav uneval(event.type)="play" typeof(event.type)=string uneval(v._state)=0 typeof(v._state)=number tokens[0]=play tokens[0].indexOf(event.type)=0
186138 INFO TEST-PASS | /tests/content/media/test/test_play_events.html | Check expected event got canplay at play for http://mochi.test:8888/tests/content/media/test/r11025_s16_c1.wav uneval(event.type)="canplay" typeof(event.type)=string uneval(v._state)="play" typeof(v._state)=string tokens[play]=canplay tokens[play].indexOf(event.type)=0
186139 INFO TEST-PASS | /tests/content/media/test/test_play_events.html | Check expected event got playing at canplay for http://mochi.test:8888/tests/content/media/test/r11025_s16_c1.wav uneval(event.type)="playing" typeof(event.type)=string uneval(v._state)="canplay" typeof(v._state)=string tokens[canplay]=playing tokens[canplay].indexOf(event.type)=0
186140 INFO TEST-PASS | /tests/content/media/test/test_play_events.html | Check expected event got canplaythrough at playing for http://mochi.test:8888/tests/content/media/test/r11025_s16_c1.wav uneval(event.type)="canplaythrough" typeof(event.type)=string uneval(v._state)="playing" typeof(v._state)=string tokens[playing]=canplay,canplaythrough tokens[playing].indexOf(event.type)=1
186141 INFO TEST-PASS | /tests/content/media/test/test_play_events.html | Check expected event got canplay at play for http://mochi.test:8888/tests/content/media/test/small-shot.ogg uneval(event.type)="canplay" typeof(event.type)=string uneval(v._state)="play" typeof(v._state)=string tokens[play]=canplay tokens[play].indexOf(event.type)=0
186142 INFO TEST-PASS | /tests/content/media/test/test_play_events.html | Check expected event got playing at canplay for http://mochi.test:8888/tests/content/media/test/small-shot.ogg uneval(event.type)="playing" typeof(event.type)=string uneval(v._state)="canplay" typeof(v._state)=string tokens[canplay]=playing tokens[canplay].indexOf(event.type)=0
186143 INFO TEST-PASS | /tests/content/media/test/test_play_events.html | Check expected event got canplaythrough at playing for http://mochi.test:8888/tests/content/media/test/small-shot.ogg uneval(event.type)="canplaythrough" typeof(event.type)=string uneval(v._state)="playing" typeof(v._state)=string tokens[playing]=canplay,canplaythrough tokens[playing].indexOf(event.type)=1
186144 INFO TEST-PASS | /tests/content/media/test/test_play_events.html | Last event should be canplaythrough for http://mochi.test:8888/tests/content/media/test/small-shot.ogg
186145 INFO TEST-PASS | /tests/content/media/test/test_play_events.html | [finished small-shot.ogg-0] Length of array should match number of running tests
186146 INFO TEST-PASS | /tests/content/media/test/test_play_events.html | [started 320x240.ogv-4] Length of array should match number of running tests
186147 INFO TEST-PASS | /tests/content/media/test/test_play_events.html | Check expected event got play at 0 for http://mochi.test:8888/tests/content/media/test/320x240.ogv uneval(event.type)="play" typeof(event.type)=string uneval(v._state)=0 typeof(v._state)=number tokens[0]=play tokens[0].indexOf(event.type)=0
186148 INFO TEST-PASS | /tests/content/media/test/test_play_events.html | Check expected event got canplay at play for http://mochi.test:8888/tests/content/media/test/320x240.ogv uneval(event.type)="canplay" typeof(event.type)=string uneval(v._state)="play" typeof(v._state)=string tokens[play]=canplay tokens[play].indexOf(event.type)=0
186149 INFO TEST-PASS | /tests/content/media/test/test_play_events.html | Check expected event got playing at canplay for http://mochi.test:8888/tests/content/media/test/320x240.ogv uneval(event.type)="playing" typeof(event.type)=string uneval(v._state)="canplay" typeof(v._state)=string tokens[canplay]=playing tokens[canplay].indexOf(event.type)=0
186150 INFO TEST-PASS | /tests/content/media/test/test_play_events.html | Check expected event got canplaythrough at playing for http://mochi.test:8888/tests/content/media/test/320x240.ogv uneval(event.type)="canplaythrough" typeof(event.type)=string uneval(v._state)="playing" typeof(v._state)=string tokens[playing]=canplay,canplaythrough tokens[playing].indexOf(event.type)=1
186151 INFO TEST-PASS | /tests/content/media/test/test_play_events.html | Last event should be canplaythrough for http://mochi.test:8888/tests/content/media/test/320x240.ogv
186152 INFO TEST-PASS | /tests/content/media/test/test_play_events.html | [finished 320x240.ogv-4] Length of array should match number of running tests
186153 INFO TEST-PASS | /tests/content/media/test/test_play_events.html | [started seek.webm-5] Length of array should match number of running tests
186154 INFO TEST-PASS | /tests/content/media/test/test_play_events.html | Check expected event got play at 0 for http://mochi.test:8888/tests/content/media/test/seek.webm uneval(event.type)="play" typeof(event.type)=string uneval(v._state)=0 typeof(v._state)=number tokens[0]=play tokens[0].indexOf(event.type)=0
186155 INFO TEST-PASS | /tests/content/media/test/test_play_events.html | Check expected event got canplay at play for http://mochi.test:8888/tests/content/media/test/seek.webm uneval(event.type)="canplay" typeof(event.type)=string uneval(v._state)="play" typeof(v._state)=string tokens[play]=canplay tokens[play].indexOf(event.type)=0
186156 INFO TEST-PASS | /tests/content/media/test/test_play_events.html | Check expected event got playing at canplay for http://mochi.test:8888/tests/content/media/test/seek.webm uneval(event.type)="playing" typeof(event.type)=string uneval(v._state)="canplay" typeof(v._state)=string tokens[canplay]=playing tokens[canplay].indexOf(event.type)=0
186157 INFO TEST-PASS | /tests/content/media/test/test_play_events.html | Last event should be canplaythrough for http://mochi.test:8888/tests/content/media/test/r11025_s16_c1.wav
186158 INFO TEST-PASS | /tests/content/media/test/test_play_events.html | [finished r11025_s16_c1.wav-3] Length of array should match number of running tests
186159 INFO TEST-PASS | /tests/content/media/test/test_play_events.html | [started detodos.opus-6] Length of array should match number of running tests
186160 INFO TEST-PASS | /tests/content/media/test/test_play_events.html | Check expected event got play at 0 for http://mochi.test:8888/tests/content/media/test/detodos.opus uneval(event.type)="play" typeof(event.type)=string uneval(v._state)=0 typeof(v._state)=number tokens[0]=play tokens[0].indexOf(event.type)=0
186161 INFO TEST-PASS | /tests/content/media/test/test_play_events.html | Check expected event got canplay at play for http://mochi.test:8888/tests/content/media/test/detodos.opus uneval(event.type)="canplay" typeof(event.type)=string uneval(v._state)="play" typeof(v._state)=string tokens[play]=canplay tokens[play].indexOf(event.type)=0
186162 INFO TEST-PASS | /tests/content/media/test/test_play_events.html | Check expected event got playing at canplay for http://mochi.test:8888/tests/content/media/test/detodos.opus uneval(event.type)="playing" typeof(event.type)=string uneval(v._state)="canplay" typeof(v._state)=string tokens[canplay]=playing tokens[canplay].indexOf(event.type)=0
186163 INFO TEST-PASS | /tests/content/media/test/test_play_events.html | Check expected event got canplaythrough at playing for http://mochi.test:8888/tests/content/media/test/detodos.opus uneval(event.type)="canplaythrough" typeof(event.type)=string uneval(v._state)="playing" typeof(v._state)=string tokens[playing]=canplay,canplaythrough tokens[playing].indexOf(event.type)=1
186164 INFO TEST-PASS | /tests/content/media/test/test_play_events.html | Last event should be canplaythrough for http://mochi.test:8888/tests/content/media/test/detodos.opus
186165 INFO TEST-PASS | /tests/content/media/test/test_play_events.html | [finished detodos.opus-6] Length of array should match number of running tests
186166 ERROR TEST-UNEXPECTED-FAIL | /tests/content/media/test/test_play_events.html | Last event should be canplaythrough for http://mochi.test:8888/tests/content/media/test/seek.webm - got playing, expected canplaythrough
186167 INFO TEST-PASS | /tests/content/media/test/test_play_events.html | [finished seek.webm-5] Length of array should match number of running tests
186168 INFO TEST-INFO | /tests/content/media/test/test_play_events.html | Finished at Thu Jan 31 2013 03:07:38 GMT-0800 (Pacific Standard Time) (1359630458.998s)
186169 INFO TEST-INFO | /tests/content/media/test/test_play_events.html | Running time: 5.221s
186170 INFO TEST-END | /tests/content/media/test/test_play_events.html | finished in 5351ms
Paul or Chris, can you help with this? This needs an owner.
Flags: needinfo?(paul)
Flags: needinfo?(cpearce)
I will try to get to this when my current high priority work is out of the way, in  a week or so.
Flags: needinfo?(paul)
Flags: needinfo?(cpearce)
I'm developing a new HTTP cache backend (happens on Gum project tree).

I can reproduce this (or similar) intermittent failure with the new cache backend quite often:
https://tbpl.mozilla.org/?tree=Gum&rev=4d6933eb8d38 [Ubuntu debug M(1) mainly]

The new HTTP cache code doesn't seem to be the cause (by means of having a bug).  I have a log of nsHttp:5,cache2:5 from a bad run (just a single one, it's very hard to reproduce...) and it's in no way different from a log of a good run.

It more happens for gizmo.mp4 file, but I presume the test do the same stuff just with different files.

This is the last intermittent failure that spiked with the new cache backend on.  When it is fixed the new cache beckend tree is completely green!


I don't understand the test, so I cannot efficiently fix this intermittent failure my self.

Chris, will you get to this?  The time frame for landing the new cache is in one month, disabled on desktop but enabled on mobile and probably b2g too.
Flags: needinfo?(cpearce)
(In reply to Honza Bambas (:mayhemer) from comment #79)
> I'm developing a new HTTP cache backend (happens on Gum project tree).
> 
> I can reproduce this (or similar) intermittent failure with the new cache
> backend quite often:
> https://tbpl.mozilla.org/?tree=Gum&rev=4d6933eb8d38 [Ubuntu debug M(1)
> mainly]

You're probably hitting a bug in the platform AAC decoders that we have installed on the Linux tbpl machines. We've identified the packages that need to be installed to fix this issue, and have asked releng to install them. We're tracking releng installing them in bug 912854.


> I don't understand the test, so I cannot efficiently fix this intermittent
> failure my self.

Once bug 912854 is fixed we expect to see a significant drop in orange rates in media tests on Linux, including the test you're having trouble with.


> Chris, will you get to this?  The time frame for landing the new cache is in
> one month, disabled on desktop but enabled on mobile and probably b2g too.

How common do you see this failing on non-Linux platforms?
Flags: needinfo?(cpearce) → needinfo?(honzab.moz)
(In reply to Chris Pearce (:cpearce) from comment #81)
> (In reply to Honza Bambas (:mayhemer) from comment #79)
> > I'm developing a new HTTP cache backend (happens on Gum project tree).
> > 
> > I can reproduce this (or similar) intermittent failure with the new cache
> > backend quite often:
> > https://tbpl.mozilla.org/?tree=Gum&rev=4d6933eb8d38 [Ubuntu debug M(1)
> > mainly]
> 
> You're probably hitting a bug in the platform AAC decoders that we have
> installed on the Linux tbpl machines.

I realise this may not be totally clear; the media tests are failing because they're hitting a bug in the AAC decoder installed on our Linux boxes.
(In reply to Chris Pearce (:cpearce) from comment #81)
> How common do you see this failing on non-Linux platforms?

I can see it in some 30% of runs.
Flags: needinfo?(honzab.moz)
According this try run [1] it seems like this is fixed, at least with the new cache.  Older run [2] to compare.  Looks like bug 912854 actually has fixed this.

Should we close this bug now?


[1] https://tbpl.mozilla.org/?tree=Try&rev=efec3d01bf20
[2] https://tbpl.mozilla.org/?tree=Gum&rev=4d6933eb8d38
See comment 84.
Flags: needinfo?(cpearce)
This seems to be fixed, on m-c and on gum too.  Thanks!
Status: NEW → RESOLVED
Closed: 11 years ago
Resolution: --- → FIXED
status-firefox25: --- → fixed
status-firefox26: --- → fixed
status-firefox27: --- → fixed
status-firefox-esr24: --- → fixed
Flags: needinfo?(cpearce)
Target Milestone: --- → mozilla27
(this is still not fixed when the new http cache is on, the test is probably wrong or there is something wrong in the new cache).
On which platforms does this failure still occur in the new HTTP cache? Are the failures being reported in another bug?
(In reply to Chris Pearce (:cpearce) from comment #89)
> On which platforms does this failure still occur in the new HTTP cache? Are
> the failures being reported in another bug?

It happens mainly (and I think only) on linux.  I was told the other day it was something missing on the test boxes that needed to be installed/updated.  It had been fixed, but the problem prevails.

I should probably report a new bug dedicated only to the cache2 enabled failure.  First I need to show those are 100% still there (reran m1 on linux, we'll see): https://tbpl.mozilla.org/?tree=Gum&rev=4771b6a88afb

I don't see them on gum right now, but sometimes I find them on try.
You need to log in before you can comment on or make changes to this bug.