Closed Bug 974033 Opened 6 years ago Closed 6 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)

x86
Linux
defect
Not set

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.
Going out on a limb that this is a regression from bug 874806.
Flags: needinfo?(alessandro.d)
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)
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?
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: 6 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla30
does this mean that the failure is happening after the backout (and so that that commit maybe was not related)?
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 :-)
I see. I would have asked on IRC but you're afk :P
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.
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.
(In reply to TBPL Robot from comment #38)

This was definitely post-backout :(
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.
You need to log in before you can comment on or make changes to this bug.