Closed Bug 951100 Opened 11 years ago Closed 8 years ago

Intermittent TEST-UNEXPECTED-FAIL | /tests/content/media/test/test_new_audio.html | [finished small-shot.m4a-3] Length of array should match number of running tests - got -1, expected 0

Categories

(Core :: Audio/Video: Playback, defect, P5)

Product:
Core
Component:
Audio/Video: Playback
Platform:
x86
Linux
Type:
defect

Tracking

()

Status:
RESOLVED FIXED
Tracking Flags:
Tracking Status
firefox28 --- unaffected
firefox29 --- unaffected
firefox30 --- affected
firefox31 --- affected
firefox-esr24 --- unaffected
b2g-v1.3 --- unaffected
b2g-v1.4 --- affected

People

(Reporter: cbook, Assigned: jwwang)

References

(
URL
)

Details

(Keywords: intermittent-failure)

Attachments

(2 files, 1 obsolete file)

part1-v2.patch
1.22 KB, patch
jwwang
: review+
Details | Diff | Splinter Review
part2_fix-v1.patch
1.40 KB, patch
cpearce
: review+
Details | Diff | Splinter Review 
Ubuntu VM 12.04 b2g-inbound debug test mochitest-1 on 2013-12-16 19:43:36 PST for push b2534d128e42

slave: tst-linux32-spot-338

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

152141 ERROR TEST-UNEXPECTED-FAIL | /tests/content/media/test/test_new_audio.html | [finished small-shot.m4a-3] Length of array should match number of running tests - got -1, expected 0
Just before the unpexpected-fail, I see this message in the log:
12:09:57     INFO -  02-05 19:57:11.011    40   119 W AudioFlinger: Thread AudioOut_1 cannot connect to the power manager service

I'm seeing all kinds of Android error messages in these failing logs, but not in passing logs. But perhaps those are filtered out in passing logs?

I'm also seeing this in the failing log:
12:09:57     INFO -  02-05 19:52:30.295   735  1292 V IMediaResourceManagerDeathNotifier: getMediaResourceManagerService
Perhaps that's causing the media source to fail to load?
JW, any chance you can take a look at this soon? I'm probably going to disable it shortly due to the high rate of failure we're seeing.
Flags: needinfo?(jwwang)
(In reply to Ryan VanderMeulen [:RyanVM UTC-5] from comment #84)
> JW, any chance you can take a look at this soon? I'm probably going to
> disable it shortly due to the high rate of failure we're seeing.

Investigating this bug now. Hope I can get some clues before the sunset.
Flags: needinfo?(jwwang)
Attached patch part1-v1.patch (obsolete) — — Splinter Review 
a.setAttribute("autoplay", false) will result in a.autoplay == true.
Call a.autoplay = false instead.

It looks like a.autoplay == true will result in onended being called more than once in this test case and therefore manager.finished is called more than once for the same token.

try: https://tbpl.mozilla.org/?tree=Try&rev=8a82475cbf0a
This failure doesn't occur for 200 runs.
Attachment #8372172 - Flags: review?(cpearce)
https://tbpl.mozilla.org/php/getParsedLog.php?id=34276843&tree=Try&full=1#error0

03:31:04     INFO -  1605 INFO TEST-START | /tests/content/media/test/test_new_audio.html
03:31:04     INFO -  1606 INFO TEST-INFO | /tests/content/media/test/test_new_audio.html | Started Fri Feb 07 2014 11:30:51 GMT+0000 (UTC) (1391772651.534s)
03:31:04     INFO -  1607 INFO TEST-INFO | /tests/content/media/test/test_new_audio.html | manager.started: r11025_s16_c1.wav-0
03:31:04     INFO -  1608 INFO TEST-INFO | /tests/content/media/test/test_new_audio.html | manager.started: sound.ogg-1
03:31:04     INFO -  1609 INFO TEST-INFO | /tests/content/media/test/test_new_audio.html | canplaythrough: r11025_s16_c1.wav-0
03:31:04     INFO -  1610 INFO TEST-INFO | /tests/content/media/test/test_new_audio.html | canplaythrough: sound.ogg-1
03:31:04     INFO -  1611 INFO TEST-INFO | /tests/content/media/test/test_new_audio.html | ended: r11025_s16_c1.wav-0
03:31:04     INFO -  1612 INFO TEST-INFO | /tests/content/media/test/test_new_audio.html | manager.started: owl.mp3-2
03:31:04     INFO -  1613 INFO TEST-INFO | /tests/content/media/test/test_new_audio.html | canplaythrough: owl.mp3-2
03:31:04     INFO -  1614 INFO TEST-INFO | /tests/content/media/test/test_new_audio.html | ended: sound.ogg-1
03:31:04     INFO -  1615 INFO TEST-INFO | /tests/content/media/test/test_new_audio.html | manager.started: small-shot.m4a-3
03:31:04     INFO -  1616 INFO TEST-INFO | /tests/content/media/test/test_new_audio.html | ended: owl.mp3-2
03:31:04     INFO -  1617 INFO TEST-INFO | /tests/content/media/test/test_new_audio.html | canplaythrough: small-shot.m4a-3
03:31:04     INFO -  1618 INFO TEST-INFO | /tests/content/media/test/test_new_audio.html | ended: small-shot.m4a-3
03:31:04     INFO -  1619 INFO TEST-INFO | /tests/content/media/test/test_new_audio.html | ended: small-shot.m4a-3
03:31:04     INFO -  1620 ERROR TEST-UNEXPECTED-FAIL | /tests/content/media/test/test_new_audio.html | [finished small-shot.m4a-3] Length of array should match number of running tests - got -1, expected 0

From the log, we can see small-shot.m4a received onended event twice. It is because the file is played twice, one by autoplay=true, the other by e.target.play() in oncanplaythrough. It looks like a timing issue for the duration of small-shot.m4a is very short. The patch should fix the problem by setting autoplay to false.
Comment on attachment 8372172 [details] [diff] [review]
part1-v1.patch

Review of attachment 8372172 [details] [diff] [review]:
-----------------------------------------------------------------

r=cpearce provided you remove the line you setting the autoplay attribute.

::: content/media/test/test_new_audio.html
@@ +31,3 @@
>    manager.started(token);
>    var a = new Audio(test.name);
> +  a.autoplay = false;

The autoplay attribute is a boolean attribute. Meaning that any value it is set to means that it's considered present or "true". Which is why calling  a.setAttribute("autoplay", false) makes a.autoplay==true.

Except when you set the attribute using a setter (=), and set it to a boolean or int, as only string values are reflected through to content attributes. That's why calling a.autoplay=false has the effect of removing the autoplay attribute.

I think you should just remove the line setting the autoplay attribute. The behaviour will be the same as with this patch. This test doesn't need the audio element to have its autoplay attribute set to pass; the play() in the canplaythrough handler should have the same effect as having its autoplay attribute set.
Attachment #8372172 - Flags: review?(cpearce) → review+
Attached patch part1-v2.patch — — Splinter Review 
minor fix as suggested by cpearce.
Assignee: nobody → jwwang
Attachment #8372172 - Attachment is obsolete: true
Status: NEW → ASSIGNED
Attachment #8373096 - Flags: review+
(In reply to JW Wang[:jwwang] from comment #169)
> Created attachment 8373096 [details] [diff] [review]
> part1-v2.patch
> 
> minor fix as suggested by cpearce.

try: https://tbpl.mozilla.org/?tree=Try&rev=544b989c35f8
Hi Ryan,
Please check in part1-v2.patch. Thanks.
Keywords: checkin-needed
https://hg.mozilla.org/mozilla-central/rev/77bb6be4adb4
Status: ASSIGNED → RESOLVED
Closed: 10 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla30
It looks like 'canplaythrough' is fired more than once and trigger another 'play' after 'end'. Since 'canplaythrough' is resulted from an estimation of download speed and playback rate, it could be fired multiple times or sometimes zero. Should we just call a.play() right after the Audio() constructor?
Flags: needinfo?(cpearce)
Set the audio element's "autoplay" attribute to true.
Flags: needinfo?(cpearce)
Set 'autoplay' to true to trigger play instead of calling play() in 'canplaythrough' callback for it is resulted from an estimation of download speed and playback rate and could be fired multiple times or sometimes zero.
Attachment #8393365 - Flags: review?(cpearce)
Status: RESOLVED → REOPENED
Resolution: FIXED → ---
Attachment #8393365 - Flags: review?(cpearce) → review+
Hi Ryan,
Please check in part2_fix-v1.patch only, thanks.
Keywords: checkin-needed
Whiteboard: [leave open]
status-b2g-v1.4: fixed → affected
status-firefox30: fixed → affected
status-firefox31: --- → affected
Target Milestone: mozilla30 → ---
Component: Audio/Video → Audio/Video: Playback
Keywords: leave-open
Priority: -- → P5
Whiteboard: [leave open]
Assume it is fixed since no timeout happened for a long time. Should it happen again, file a new bug since code has changed a lot.
Status: REOPENED → RESOLVED
Closed: 10 years ago → 8 years ago
Keywords: leave-open
Resolution: --- → FIXED
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: