Closed
Bug 974033
Opened 10 years ago
Closed 10 years ago
Intermittent test_seek_out_of_range.html | Assertion count 1 is greater than expected range (Should know audio start time if we have audio.: '!HasAudio() || mAudioStartTime != -1')
Categories
(Core :: Audio/Video, defect)
Tracking
()
RESOLVED
FIXED
mozilla30
Tracking | Status | |
---|---|---|
firefox28 | --- | unaffected |
firefox29 | --- | unaffected |
firefox30 | --- | fixed |
firefox-esr24 | --- | unaffected |
People
(Reporter: RyanVM, Assigned: alessandro.d)
Details
(Keywords: assertion, intermittent-failure)
The gstreamer error looks relevant. https://tbpl.mozilla.org/php/getParsedLog.php?id=34857562&tree=Mozilla-Inbound Ubuntu VM 12.04 mozilla-inbound debug test mochitest-1 on 2014-02-18 10:18:53 PST for push 35240da28ab0 slave: tst-linux32-ec2-057 11:08:34 INFO - 9074 INFO TEST-START | /tests/content/media/test/test_seek_out_of_range.html 11:08:34 INFO - System JS : ERROR (null):0 - uncaught exception: 2147746065 11:08:34 INFO - ++DOMWINDOW == 25 (0xc8ae900) [pid = 2407] [serial = 4787] [outer = 0xc3d3ea8] 11:08:34 INFO - 9075 INFO TEST-INFO | /tests/content/media/test/test_seek_out_of_range.html | Started Tue Feb 18 2014 11:08:34 GMT-0800 (PST) (1392750514.535s) 11:08:34 INFO - System JS : ERROR (null):0 - uncaught exception: 2147746065 11:08:35 INFO - System JS : ERROR (null):0 - uncaught exception: 2147746065 11:08:35 INFO - --DOMWINDOW == 24 (0xd160100) [pid = 2407] [serial = 4782] [outer = (nil)] [url = http://mochi.test:8888/tests/SimpleTest/iframe-between-tests.html] 11:08:35 INFO - --DOMWINDOW == 23 (0xc54d900) [pid = 2407] [serial = 4780] [outer = (nil)] [url = http://mochi.test:8888/tests/SimpleTest/iframe-between-tests.html] 11:08:35 INFO - --DOMWINDOW == 22 (0xffb2c00) [pid = 2407] [serial = 4779] [outer = (nil)] [url = http://mochi.test:8888/tests/content/media/test/test_replay_metadata.html] 11:08:35 INFO - --DOMWINDOW == 21 (0xb3d9010) [pid = 2407] [serial = 4783] [outer = (nil)] [url = http://mochi.test:8888/tests/content/media/test/test_seek2.html] 11:08:35 INFO - --DOMWINDOW == 20 (0xb0dabd0) [pid = 2407] [serial = 4784] [outer = (nil)] [url = http://mochi.test:8888/tests/SimpleTest/iframe-between-tests.html] 11:08:35 INFO - --DOMWINDOW == 19 (0xfd98200) [pid = 2407] [serial = 4786] [outer = (nil)] [url = http://mochi.test:8888/tests/SimpleTest/iframe-between-tests.html] 11:08:35 INFO - System JS : ERROR (null):0 - uncaught exception: 2147746065 11:08:35 INFO - --DOMWINDOW == 18 (0xf9509b0) [pid = 2407] [serial = 4781] [outer = (nil)] [url = http://mochi.test:8888/tests/content/media/test/test_reset_src.html] 11:08:36 INFO - (firefox:2407): GStreamer-CRITICAL **: gst_segment_set_seek: assertion `start <= stop' failed 11:08:36 INFO - [Parent 2407] ###!!! ASSERTION: Should know audio start time if we have audio.: '!HasAudio() || mAudioStartTime != -1', file /builds/slave/m-in-lx-d-00000000000000000000/build/content/media/MediaDecoderStateMachine.cpp, line 2240 11:08:36 INFO - UNKNOWN [/builds/slave/test/build/application/firefox/libxul.so +0x01385b7f] 11:08:36 INFO - UNKNOWN [/builds/slave/test/build/application/firefox/libxul.so +0x0138914c] 11:08:36 INFO - mozilla::MediaDecoderStateMachine::CallRunStateMachine() [content/media/MediaDecoderStateMachine.cpp:2535] 11:08:36 INFO - UNKNOWN [/builds/slave/test/build/application/firefox/libxul.so +0x013893fd] 11:08:36 INFO - UNKNOWN [/builds/slave/test/build/application/firefox/libxul.so +0x003df677] 11:08:36 INFO - UNKNOWN [/builds/slave/test/build/application/firefox/libxul.so +0x003dccb5] 11:08:36 INFO - UNKNOWN [/builds/slave/test/build/application/firefox/libxul.so +0x0036fc4f] 11:08:36 INFO - UNKNOWN [/builds/slave/test/build/application/firefox/libxul.so +0x00622b26] 11:08:36 INFO - UNKNOWN [/builds/slave/test/build/application/firefox/libxul.so +0x0060dd86] 11:08:36 INFO - UNKNOWN [/builds/slave/test/build/application/firefox/libxul.so +0x0060ddac] 11:08:36 INFO - UNKNOWN [/builds/slave/test/build/application/firefox/libxul.so +0x003dc38b] 11:08:36 INFO - UNKNOWN [/builds/slave/test/build/application/firefox/libnspr4.so +0x0002f3d5] 11:08:36 INFO - UNKNOWN [/lib/i386-linux-gnu/libpthread.so.0 +0x00006d4c] 11:08:36 INFO - System JS : ERROR (null):0 - uncaught exception: 2147746065 11:08:36 INFO - System JS : ERROR (null):0 - uncaught exception: 2147746065 11:08:36 INFO - --DOMWINDOW == 17 (0xfb62100) [pid = 2407] [serial = 4785] [outer = (nil)] [url = http://mochi.test:8888/tests/content/media/test/test_seekLies.html] 11:08:37 INFO - System JS : ERROR (null):0 - uncaught exception: 2147746065 11:08:37 INFO - System JS : ERROR (null):0 - uncaught exception: 2147746065 11:08:38 INFO - System JS : ERROR (null):0 - uncaught exception: 2147746065 11:08:38 INFO - System JS : ERROR (null):0 - uncaught exception: 2147746065 11:08:39 INFO - System JS : ERROR (null):0 - uncaught exception: 2147746065 11:08:39 INFO - System JS : ERROR (null):0 - uncaught exception: 2147746065 11:08:40 INFO - System JS : ERROR (null):0 - uncaught exception: 2147746065 11:08:40 INFO - System JS : ERROR (null):0 - uncaught exception: 2147746065 11:08:41 INFO - System JS : ERROR (null):0 - uncaught exception: 2147746065 11:08:41 INFO - System JS : ERROR (null):0 - uncaught exception: 2147746065 11:08:42 INFO - System JS : ERROR (null):0 - uncaught exception: 2147746065 11:08:42 INFO - System JS : ERROR (null):0 - uncaught exception: 2147746065 11:08:43 INFO - System JS : ERROR (null):0 - uncaught exception: 2147746065 11:08:43 INFO - System JS : ERROR (null):0 - uncaught exception: 2147746065 11:08:44 INFO - System JS : ERROR (null):0 - uncaught exception: 2147746065 11:08:44 INFO - System JS : ERROR (null):0 - uncaught exception: 2147746065 11:08:45 INFO - System JS : ERROR (null):0 - uncaught exception: 2147746065 11:08:45 INFO - System JS : ERROR (null):0 - uncaught exception: 2147746065 11:08:46 INFO - System JS : ERROR (null):0 - uncaught exception: 2147746065 11:08:46 INFO - System JS : ERROR (null):0 - uncaught exception: 2147746065 11:08:47 INFO - System JS : ERROR (null):0 - uncaught exception: 2147746065 11:08:47 INFO - System JS : ERROR (null):0 - uncaught exception: 2147746065 11:08:48 INFO - System JS : ERROR (null):0 - uncaught exception: 2147746065 11:08:48 INFO - System JS : ERROR (null):0 - uncaught exception: 2147746065 11:08:49 INFO - System JS : ERROR (null):0 - uncaught exception: 2147746065 11:08:49 INFO - System JS : ERROR (null):0 - uncaught exception: 2147746065 11:08:50 INFO - System JS : ERROR (null):0 - uncaught exception: 2147746065 11:08:51 INFO - System JS : ERROR (null):0 - uncaught exception: 2147746065 11:08:51 INFO - System JS : ERROR (null):0 - uncaught exception: 2147746065 11:08:52 INFO - System JS : ERROR (null):0 - uncaught exception: 2147746065 11:08:52 INFO - System JS : ERROR (null):0 - uncaught exception: 2147746065 11:08:53 INFO - System JS : ERROR (null):0 - uncaught exception: 2147746065 11:08:53 INFO - System JS : ERROR (null):0 - uncaught exception: 2147746065 11:08:54 INFO - System JS : ERROR (null):0 - uncaught exception: 2147746065 11:08:54 INFO - System JS : ERROR (null):0 - uncaught exception: 2147746065 11:08:55 INFO - System JS : ERROR (null):0 - uncaught exception: 2147746065 11:08:55 INFO - System JS : ERROR (null):0 - uncaught exception: 2147746065 11:08:56 INFO - System JS : ERROR (null):0 - uncaught exception: 2147746065 11:08:56 INFO - System JS : ERROR (null):0 - uncaught exception: 2147746065 11:08:57 INFO - System JS : ERROR (null):0 - uncaught exception: 2147746065 11:08:57 INFO - System JS : ERROR (null):0 - uncaught exception: 2147746065 11:08:58 INFO - 9076 INFO TEST-INFO | /tests/content/media/test/test_seek_out_of_range.html | Finished at Tue Feb 18 2014 11:08:58 GMT-0800 (PST) (1392750538.016s) 11:08:58 INFO - 9077 INFO TEST-INFO | /tests/content/media/test/test_seek_out_of_range.html | Running time: 23.481s 11:08:58 INFO - 9078 INFO TEST-INFO | MEMORY STAT vsize after test: 854863872 11:08:58 INFO - 9079 INFO TEST-INFO | MEMORY STAT residentFast after test: 270082048 11:08:58 INFO - System JS : ERROR (null):0 - uncaught exception: 2147746065 11:08:58 INFO - 9080 INFO TEST-END | /tests/content/media/test/test_seek_out_of_range.html | finished in 23984ms 11:08:58 INFO - ++DOMWINDOW == 18 (0xe395aa0) [pid = 2407] [serial = 4788] [outer = 0xc3d3ea8] 11:08:58 INFO - 9081 ERROR TEST-UNEXPECTED-FAIL | /tests/content/media/test/test_seek_out_of_range.html | Assertion count 1 is greater than expected range 0-0 assertions.
Comment hidden (Legacy TBPL/Treeherder Robot) |
Reporter | ||
Comment 2•10 years ago
|
||
Going out on a limb that this is a regression from bug 874806.
Flags: needinfo?(alessandro.d)
Comment hidden (Legacy TBPL/Treeherder Robot) |
Comment hidden (Legacy TBPL/Treeherder Robot) |
Assignee | ||
Comment 5•10 years ago
|
||
For some reason I think that getting rid of that ->Read() is making a race condition easier to hit. I can repro the bug pretty easily.
Flags: needinfo?(alessandro.d)
Comment hidden (Legacy TBPL/Treeherder Robot) |
Comment hidden (Legacy TBPL/Treeherder Robot) |
Comment hidden (Legacy TBPL/Treeherder Robot) |
Comment hidden (Legacy TBPL/Treeherder Robot) |
Comment hidden (Legacy TBPL/Treeherder Robot) |
Comment hidden (Legacy TBPL/Treeherder Robot) |
Comment hidden (Legacy TBPL/Treeherder Robot) |
Comment hidden (Legacy TBPL/Treeherder Robot) |
Comment hidden (Legacy TBPL/Treeherder Robot) |
Assignee | ||
Comment 15•10 years ago
|
||
This is what I see in the logs: 0:00:00.449602000 81583 0x1133dd000 DEBUG qtdemux qtdemux.c:3130:gst_qtdemux_activate_segment:<qtdemux0> newsegment 0 from 0:00:00.299000000 to 0:00:00.299000000, time 0:00:00.299000000 ... 0:00:00.449692000 81583 0x1133de280 DEBUG baseparse gstbaseparse.c:983:gst_base_parse_sink_eventfunc:<aacparse0> newseg rate 1, applied rate 1, format 3, start = 0:00:00.299000000, stop = 0:00:00.299000000, pos = 0:00:00.299000000 ... 0:00:00.450116000 81583 0x1133dd000 LOG qtdemux qtdemux.c:3736:gst_qtdemux_decorate_and_push_buffer:<qtdemux0> Pushing buffer with time 0:00:00.277333333, duration 0:00:00.021333333 on pad audio_00 ... 0:00:00.450222000 81583 0x1133de280 LOG baseparse gstbaseparse.c:1812:gst_base_parse_push_frame:<aacparse0> processing buffer of size 135 with ts 0:00:00.277333333, duration 0:00:00.021333333 ... 0:00:00.450457000 81583 0x1133de280 LOG baseparse gstbaseparse.c:1960:gst_base_parse_push_frame:<aacparse0> frame (135 bytes) dropped So: - the test seeks at 0.299 - the last audio sample ends at 0.298 so gstreamer skips it since it's outside the configured seek segment - the audio stream reaches EOS as far as gst is concerned (and we set mReachedAudioEos accordingly) - at this point the state machine is in the DECODER_STATE_COMPLETED state and does // Play the remaining media. We want to run AdvanceFrame() at least // once to ensure the current playback position is advanced to the // end of the media, and so that we update the readyState. if (mState == DECODER_STATE_COMPLETED && (mReader->VideoQueue().GetSize() > 0 || (HasAudio() && !mAudioCompleted) || (mDecoder->GetDecodedStream() && !mDecoder->GetDecodedStream()->IsFinished()))) { AdvanceFrame(); - in AdvanceFrame we hit the following assertion NS_ASSERTION(!HasAudio() || mAudioStartTime != -1, "Should know audio start time if we have audio."); I'm not sure what i'm supposed to do here. I can make HasAudio() return false if mReachedAudioEos, but no other reader subclass does that. Ideas?
Comment hidden (Legacy TBPL/Treeherder Robot) |
Comment hidden (Legacy TBPL/Treeherder Robot) |
Comment hidden (Legacy TBPL/Treeherder Robot) |
Comment hidden (Legacy TBPL/Treeherder Robot) |
Comment hidden (Legacy TBPL/Treeherder Robot) |
Comment hidden (Legacy TBPL/Treeherder Robot) |
Comment hidden (Legacy TBPL/Treeherder Robot) |
Comment hidden (Legacy TBPL/Treeherder Robot) |
Comment hidden (Legacy TBPL/Treeherder Robot) |
Comment hidden (Legacy TBPL/Treeherder Robot) |
Reporter | ||
Comment 26•10 years ago
|
||
Sorry, this is happening too frequently :(. Bug 874806 backed out. https://hg.mozilla.org/integration/mozilla-inbound/rev/26487075b6ec
Assignee: nobody → alessandro.d
Status: NEW → RESOLVED
Closed: 10 years ago
status-firefox28:
--- → unaffected
status-firefox29:
--- → unaffected
status-firefox30:
--- → fixed
status-firefox-esr24:
--- → unaffected
Resolution: --- → FIXED
Target Milestone: --- → mozilla30
Comment hidden (Legacy TBPL/Treeherder Robot) |
Comment hidden (Legacy TBPL/Treeherder Robot) |
Comment hidden (Legacy TBPL/Treeherder Robot) |
Comment hidden (Legacy TBPL/Treeherder Robot) |
Comment hidden (Legacy TBPL/Treeherder Robot) |
Comment hidden (Legacy TBPL/Treeherder Robot) |
Assignee | ||
Comment 33•10 years ago
|
||
does this mean that the failure is happening after the backout (and so that that commit maybe was not related)?
Reporter | ||
Comment 34•10 years ago
|
||
No, it just means that runs that were already in progress can still fail and that backouts on one branch can take time to propagate to all other affected branches. If we're still seeing them tomorrow, then you've got a legitimate beef :-)
Assignee | ||
Comment 35•10 years ago
|
||
I see. I would have asked on IRC but you're afk :P
Assignee | ||
Comment 36•10 years ago
|
||
In fact locally I _never_ get audio when seeking to 0.299000000. I am not sure why sometimes the assertion doesn't get hit on try.
Assignee | ||
Comment 37•10 years ago
|
||
And then i'll end the witch hunt... even after reverting https://bugzilla.mozilla.org/show_bug.cgi?id=874806 I still get the same behaviour: i _always_ hit the assertion locally, I never have audio after the test seeks to the very end. And this with nonsense, I'll move to the beach.
Comment hidden (Legacy TBPL/Treeherder Robot) |
Reporter | ||
Comment 39•10 years ago
|
||
(In reply to TBPL Robot from comment #38) This was definitely post-backout :(
Reporter | ||
Comment 40•10 years ago
|
||
Hrm, but no instances since. So maybe comment 38 was a fluke of some sort. You can see from the TBPLbot comments that this was happening frequently pre-backout and hasn't really happened since.
Comment hidden (Legacy TBPL/Treeherder Robot) |
You need to log in
before you can comment on or make changes to this bug.
Description
•