Closed Bug 855704 Opened 11 years ago Closed 10 years ago

Intermittent webspeech/recognition/test/test_abort.html | unexpected event: error followed by other errors

Categories

(Core :: General, defect)

Product:
Core
Component:
General
Platform:
x86
Windows 7
Type:
defect
Priority:
Not set
Severity:
normal

Tracking

()

Status:
RESOLVED WORKSFORME
Milestone:
mozilla23

People

(Reporter: RyanVM, Assigned: ggp)

References

Details

(Keywords: intermittent-failure)

Attachments

(2 files, 1 obsolete file)

Log error message along with the error
855 bytes, patch
smaug
: review+
johns
: checkin+
Details | Diff | Splinter Review
Use pushPrefEnv instead of setBoolPref in webspeech tests
12.50 KB, patch
ggp
: review+
Details | Diff | Splinter Review 
(Core:General? This really needs a proper Bugzilla component)

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

Rev3 WINNT 6.1 mozilla-inbound opt test mochitest-1 on 2013-03-28 03:14:07 PDT for push 14064d4b31e7
slave: talos-r3-w7-082

03:34:58     INFO -  207562 INFO TEST-START | /tests/content/media/webspeech/recognition/test/test_abort.html
03:34:58     INFO -  207563 INFO TEST-INFO | /tests/content/media/webspeech/recognition/test/test_abort.html | Aborting on start
03:34:58     INFO -  207564 INFO TEST-INFO | /tests/content/media/webspeech/recognition/test/test_abort.html | requesting EVENT_START
03:34:58     INFO -  207565 INFO TEST-INFO | /tests/content/media/webspeech/recognition/test/test_abort.html | requesting EVENT_AUDIO_DATA
03:35:08     INFO -  207566 INFO TEST-PASS | /tests/content/media/webspeech/recognition/test/test_abort.html | received event end
03:35:08     INFO -  207567 ERROR TEST-UNEXPECTED-FAIL | /tests/content/media/webspeech/recognition/test/test_abort.html | unexpected event: error
03:35:08     INFO -  207568 INFO TEST-INFO | /tests/content/media/webspeech/recognition/test/test_abort.html | Aborting on audiostart
03:35:08     INFO -  207569 INFO TEST-INFO | /tests/content/media/webspeech/recognition/test/test_abort.html | requesting EVENT_START
03:35:08     INFO -  207570 INFO TEST-INFO | /tests/content/media/webspeech/recognition/test/test_abort.html | requesting EVENT_AUDIO_DATA
03:35:18     INFO -  207571 INFO TEST-PASS | /tests/content/media/webspeech/recognition/test/test_abort.html | received event end
03:35:18     INFO -  207572 ERROR TEST-UNEXPECTED-FAIL | /tests/content/media/webspeech/recognition/test/test_abort.html | unexpected event: error
03:35:18     INFO -  207573 INFO TEST-INFO | /tests/content/media/webspeech/recognition/test/test_abort.html | Aborting on speechstart
03:35:18     INFO -  207574 INFO TEST-INFO | /tests/content/media/webspeech/recognition/test/test_abort.html | requesting EVENT_START
03:35:18     INFO -  207575 INFO TEST-INFO | /tests/content/media/webspeech/recognition/test/test_abort.html | requesting EVENT_AUDIO_DATA
03:35:28     INFO -  207576 INFO TEST-PASS | /tests/content/media/webspeech/recognition/test/test_abort.html | received event end
03:35:28     INFO -  207577 ERROR TEST-UNEXPECTED-FAIL | /tests/content/media/webspeech/recognition/test/test_abort.html | unexpected event: error
03:35:28     INFO -  207578 INFO TEST-INFO | /tests/content/media/webspeech/recognition/test/test_abort.html | Aborting on speechend
03:35:28     INFO -  207579 INFO TEST-INFO | /tests/content/media/webspeech/recognition/test/test_abort.html | requesting EVENT_START
03:35:28     INFO -  207580 INFO TEST-INFO | /tests/content/media/webspeech/recognition/test/test_abort.html | requesting EVENT_AUDIO_DATA
03:35:38     INFO -  207581 INFO TEST-PASS | /tests/content/media/webspeech/recognition/test/test_abort.html | received event end
03:35:38     INFO -  207582 ERROR TEST-UNEXPECTED-FAIL | /tests/content/media/webspeech/recognition/test/test_abort.html | unexpected event: error
03:35:38     INFO -  207583 INFO TEST-INFO | /tests/content/media/webspeech/recognition/test/test_abort.html | Aborting on audioend
03:35:38     INFO -  207584 INFO TEST-INFO | /tests/content/media/webspeech/recognition/test/test_abort.html | requesting EVENT_START
03:35:38     INFO -  207585 INFO TEST-INFO | /tests/content/media/webspeech/recognition/test/test_abort.html | requesting EVENT_AUDIO_DATA
03:35:48     INFO -  207586 INFO TEST-PASS | /tests/content/media/webspeech/recognition/test/test_abort.html | received event end
03:35:48     INFO -  207587 ERROR TEST-UNEXPECTED-FAIL | /tests/content/media/webspeech/recognition/test/test_abort.html | unexpected event: error
03:35:48     INFO -  207588 INFO TEST-END | /tests/content/media/webspeech/recognition/test/test_abort.html | finished in 50100ms
03:35:48     INFO -  207589 INFO TEST-START | /tests/content/media/webspeech/recognition/test/test_audio_capture_error.html
03:35:48     INFO -  207590 INFO TEST-INFO | /tests/content/media/webspeech/recognition/test/test_audio_capture_error.html | requesting EVENT_START
03:35:48     INFO -  207591 INFO TEST-INFO | /tests/content/media/webspeech/recognition/test/test_audio_capture_error.html | requesting EVENT_AUDIO_ERROR
03:35:48     INFO -  207592 INFO TEST-PASS | /tests/content/media/webspeech/recognition/test/test_audio_capture_error.html | received event end
03:35:48     INFO -  207593 INFO TEST-PASS | /tests/content/media/webspeech/recognition/test/test_audio_capture_error.html | received event error
03:35:48     INFO -  207594 INFO TEST-PASS | /tests/content/media/webspeech/recognition/test/test_audio_capture_error.html | expect correct error code
03:35:48     INFO -  207595 INFO TEST-END | /tests/content/media/webspeech/recognition/test/test_audio_capture_error.html | finished in 140ms
03:35:48     INFO -  207596 INFO TEST-START | /tests/content/media/webspeech/recognition/test/test_call_start_from_end_handler.html
03:35:48     INFO -  207597 INFO TEST-INFO | /tests/content/media/webspeech/recognition/test/test_call_start_from_end_handler.html | requesting EVENT_START
03:35:48     INFO -  207598 INFO TEST-INFO | /tests/content/media/webspeech/recognition/test/test_call_start_from_end_handler.html | requesting EVENT_AUDIO_DATA
03:35:48     INFO -  207599 INFO TEST-INFO | /tests/content/media/webspeech/recognition/test/test_call_start_from_end_handler.html | Queuing event EVENT_RECOGNITIONSERVICE_FINAL_RESULT until we're done sending audio data
03:35:58     INFO -  207600 INFO TEST-PASS | /tests/content/media/webspeech/recognition/test/test_call_start_from_end_handler.html | received event end
03:35:58     INFO -  207601 INFO TEST-INFO | /tests/content/media/webspeech/recognition/test/test_call_start_from_end_handler.html | Successfully start() from end() callback
03:35:58     INFO -  207602 ERROR TEST-UNEXPECTED-FAIL | /tests/content/media/webspeech/recognition/test/test_call_start_from_end_handler.html | unexpected event: error
03:35:58     INFO -  207603 INFO TEST-END | /tests/content/media/webspeech/recognition/test/test_call_start_from_end_handler.html | finished in 10050ms
03:35:58     INFO -  207604 INFO TEST-START | /tests/content/media/webspeech/recognition/test/test_preference_enable.html
03:35:59     INFO -  207605 INFO TEST-PASS | /tests/content/media/webspeech/recognition/test/test_preference_enable.html | SpeechRecognition should be undefined with pref off
03:35:59     INFO -  207606 INFO TEST-PASS | /tests/content/media/webspeech/recognition/test/test_preference_enable.html | SpeechGrammar should be undefined with pref off
03:35:59     INFO -  207607 INFO TEST-PASS | /tests/content/media/webspeech/recognition/test/test_preference_enable.html | SpeechRecognitionResult should be undefined with pref off
03:35:59     INFO -  207608 INFO TEST-PASS | /tests/content/media/webspeech/recognition/test/test_preference_enable.html | SpeechRecognitionResultList should be undefined with pref off
03:35:59     INFO -  207609 INFO TEST-PASS | /tests/content/media/webspeech/recognition/test/test_preference_enable.html | SpeechRecognitionAlternative should be undefined with pref off
03:35:59     INFO -  207610 INFO TEST-END | /tests/content/media/webspeech/recognition/test/test_preference_enable.html | finished in 127ms
03:35:59     INFO -  207611 INFO TEST-START | /tests/content/media/webspeech/recognition/test/test_recognition_service_error.html
03:35:59     INFO -  207612 INFO TEST-INFO | /tests/content/media/webspeech/recognition/test/test_recognition_service_error.html | requesting EVENT_START
03:35:59     INFO -  207613 INFO TEST-INFO | /tests/content/media/webspeech/recognition/test/test_recognition_service_error.html | requesting EVENT_AUDIO_DATA
03:35:59     INFO -  207614 INFO TEST-INFO | /tests/content/media/webspeech/recognition/test/test_recognition_service_error.html | Queuing event EVENT_RECOGNITIONSERVICE_ERROR until we're done sending audio data
03:36:09     INFO -  207615 INFO TEST-PASS | /tests/content/media/webspeech/recognition/test/test_recognition_service_error.html | received event end
03:36:09     INFO -  207616 INFO TEST-PASS | /tests/content/media/webspeech/recognition/test/test_recognition_service_error.html | received event error
03:36:09     INFO -  207617 ERROR TEST-UNEXPECTED-FAIL | /tests/content/media/webspeech/recognition/test/test_recognition_service_error.html | expect correct error code - got 0, expected 3
03:41:25     INFO -  207618 ERROR TEST-UNEXPECTED-FAIL | /tests/content/media/webspeech/recognition/test/test_recognition_service_error.html | Test timed out.
03:41:25     INFO -  args: ['C:\\talos-slave\\test\\build\\tests\\bin\\screenshot.exe', 'c:\\users\\cltbld\\appdata\\local\\temp\\mozilla-test-fail_pd_1np']
03:41:26     INFO -  SCREENSHOT: <see log>
03:41:26     INFO -  207619 INFO TEST-END | /tests/content/media/webspeech/recognition/test/test_recognition_service_error.html | finished in 327588ms
03:41:26     INFO -  207620 INFO TEST-START | /tests/content/media/webspeech/recognition/test/test_success_without_recognition_service.html
03:41:26     INFO -  207621 INFO TEST-INFO | /tests/content/media/webspeech/recognition/test/test_success_without_recognition_service.html | requesting EVENT_START
03:41:26     INFO -  207622 INFO TEST-INFO | /tests/content/media/webspeech/recognition/test/test_success_without_recognition_service.html | requesting EVENT_AUDIO_DATA
03:41:26     INFO -  207623 INFO TEST-INFO | /tests/content/media/webspeech/recognition/test/test_success_without_recognition_service.html | Queuing event EVENT_RECOGNITIONSERVICE_FINAL_RESULT until we're done sending audio data
03:41:36     INFO -  207624 INFO TEST-PASS | /tests/content/media/webspeech/recognition/test/test_success_without_recognition_service.html | received event end
03:41:36     INFO -  207625 ERROR TEST-UNEXPECTED-FAIL | /tests/content/media/webspeech/recognition/test/test_success_without_recognition_service.html | unexpected event: error
03:41:36     INFO -  207626 INFO TEST-END | /tests/content/media/webspeech/recognition/test/test_success_without_recognition_service.html | finished in 10145ms
03:41:36     INFO -  207627 INFO TEST-START | /tests/content/media/webspeech/recognition/test/test_timeout.html
03:41:37     INFO -  207628 INFO TEST-INFO | /tests/content/media/webspeech/recognition/test/test_timeout.html | requesting EVENT_START
03:41:37     INFO -  207629 INFO TEST-INFO | /tests/content/media/webspeech/recognition/test/test_timeout.html | requesting EVENT_AUDIO_DATA
03:41:47     INFO -  207630 INFO TEST-PASS | /tests/content/media/webspeech/recognition/test/test_timeout.html | received event end
03:41:47     INFO -  207631 INFO TEST-PASS | /tests/content/media/webspeech/recognition/test/test_timeout.html | received event error
03:41:47     INFO -  207632 INFO TEST-PASS | /tests/content/media/webspeech/recognition/test/test_timeout.html | expect correct error code
03:46:55     INFO -  207633 ERROR TEST-UNEXPECTED-FAIL | /tests/content/media/webspeech/recognition/test/test_timeout.html | Test timed out.
03:46:55     INFO -  Not taking screenshot here: see the one that was previously logged
03:46:56     INFO -  207634 INFO TEST-END | /tests/content/media/webspeech/recognition/test/test_timeout.html | finished in 319787ms
Assignee: nobody → ggoncalves
Attachment #733112 - Flags: review?(bugs) → review+
https://hg.mozilla.org/mozilla-central/rev/5302617ee727
Status: NEW → RESOLVED
Closed: 11 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla23
Patch just adds logging; forgot to stick [leave open] in the whiteboard
Status: RESOLVED → REOPENED
Resolution: FIXED → ---
Target Milestone: mozilla23 → ---
Status: REOPENED → NEW
The logs from debug builds suggest that we are failing to instantiate the fake recognition service, which means we return early from SpeechRecognition::Start and never leave the state STATE_IDLE.

The speech detection timer gets set in SpeechRecognition::StartRecording, but since we're in STATE_IDLE no audio data is actually processed. So we timeout after 10s of no speech.

We probably fail to instantiate the service becaue the pref media.webspeech.test.fake_recognition_service is not set, so that hints at a race when setting and reading the test prefs. If that's the case, it looks like using pushPrefEnv will help.
Attachment #734040 - Flags: review?(bugs)
I don't understand what race.
Comment on attachment 734040 [details] [diff] [review]
Use pushPrefEnv instead of setBoolPref in webspeech tests

But this is anyhow good change.
Attachment #734040 - Flags: review?(bugs) → review+
(In reply to Nikhil Marathe from comment #31)
> https://hg.mozilla.org/integration/mozilla-inbound/rev/35178de36bd3

Backed out for frequent mochitest failures like the one below.
https://hg.mozilla.org/integration/mozilla-inbound/rev/5a821a7b43ae

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

15:40:25     INFO -  206826 INFO TEST-START | /tests/content/media/webspeech/recognition/test/test_preference_enable.html
15:40:25     INFO -  206827 ERROR TEST-UNEXPECTED-FAIL | /tests/content/media/webspeech/recognition/test/test_preference_enable.html | [SimpleTest.finish()] No checks actually run. (You need to call ok(), is(), or similar functions at least once.  Make sure you use SimpleTest.waitForExplicitFinish() if you need it.)
15:40:26     INFO -  206828 INFO TEST-PASS | /tests/content/media/webspeech/recognition/test/test_preference_enable.html | SpeechRecognition should be undefined with pref off
15:40:26     INFO -  206829 INFO TEST-PASS | /tests/content/media/webspeech/recognition/test/test_preference_enable.html | SpeechGrammar should be undefined with pref off
15:40:26     INFO -  206830 INFO TEST-PASS | /tests/content/media/webspeech/recognition/test/test_preference_enable.html | SpeechRecognitionResult should be undefined with pref off
15:40:26     INFO -  206831 INFO TEST-PASS | /tests/content/media/webspeech/recognition/test/test_preference_enable.html | SpeechRecognitionResultList should be undefined with pref off
15:40:26     INFO -  206832 INFO TEST-PASS | /tests/content/media/webspeech/recognition/test/test_preference_enable.html | SpeechRecognitionAlternative should be undefined with pref off
15:40:26     INFO -  206833 INFO TEST-END | /tests/content/media/webspeech/recognition/test/test_preference_enable.html | finished in 46ms
Looks like I need to use waitForExplicitFinish() whenever I'm using pushPrefEnv(). Updating the patch to make the test that caused the backout to also use waitForEplicitFinish().

Keeping r+ from smaug.
Attachment #734040 - Attachment is obsolete: true
Attachment #735302 - Flags: review+
uh, right. I'm not too familiar with pushPrefEnv.
https://hg.mozilla.org/mozilla-central/rev/f6ac21e1e966
Status: NEW → RESOLVED
Closed: 11 years ago → 11 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla23
Not fixed yet, as per comment 47.
Status: RESOLVED → REOPENED
Resolution: FIXED → ---
(In reply to Guilherme Gonçalves [:ggp] from comment #49)
> Not fixed yet, as per comment 47.

Guilherme, any ideas for what to do next? As you can see, we're still hitting this pretty frequently.
Flags: needinfo?(ggoncalves)
I managed to reproduce this and other problems yesterday on try. While I'm not completely sure what's causing this specific error (the timeout), it does seem related to the others that came out, and smaug and I discussed some possible solutions.

I'll be working on patches to address these problems in the next few days. Sorry for the inconvenience.
Flags: needinfo?(ggoncalves)
Guilherme Gonçalves wrote:

> I now have a log with a failure that also prints the address of the stream we're trying to
> listen to [1]. You'll notice we're expecting audio data from stream 0x34f699d0, and (at least
> from my quick search through the log) that stream seems to never be mentioned in the media
> logs. For comparison, I also have a log of a successful run, where we read from stream
> 0x1ba3f5e0 [2]. Does this help diagnose the problem?
>
> Please note that the error log is not the cleanest possible -- there is a seemingly unrelated
> failure before the one on test_abort.html, which is the one we want -- but it's the best I
> could get so far. I'll let you know if anything better comes up.
>
> 1- https://tbpl.mozilla.org/php/getParsedLog.php?id=22205111&tree=Try&full=1
> 2- https://tbpl.mozilla.org/php/getParsedLog.php?id=22201633&tree=Try&full=1

Log 1 shows that the MediaStreamGraph hung in an earlier media test. That's why "34f699d0" doesn't show up being added to the MediaStreamGraph. It looks like we deadlocked writing audio. Near the end of the log we get a stack trace for the MSG thread:

13:52:04     INFO -   5  nss3.dll!PR_WaitCondVar [prucv.c:6644c76071e6 : 515 + 0xc]
13:52:04     INFO -      eip = 0x68afca84   esp = 0x21e8bc6c   ebp = 0x21e8bca0
13:52:04     INFO -      Found by: call frame info
13:52:04     INFO -   6  xul.dll!mozilla::CondVar::Wait(unsigned int) [BlockingResourceBase.cpp:6644c76071e6 : 340 + 0x14]
13:52:04     INFO -      eip = 0x6b1695c5   esp = 0x21e8bc88   ebp = 0x21e8bca0
13:52:04     INFO -      Found by: call frame info
13:52:04     INFO -   7  xul.dll!mozilla::BufferedAudioStream::Write(float const *,unsigned int) [AudioStream.cpp:6644c76071e6 : 612 + 0xc]
13:52:04     INFO -      eip = 0x6a195a61   esp = 0x21e8bca8   ebp = 0x21e8bcc4
13:52:04     INFO -      Found by: call frame info
13:52:04     INFO -   8  xul.dll!mozilla::AudioSegment::WriteTo(mozilla::AudioStream *) [AudioSegment.cpp:6644c76071e6 : 168 + 0x12]
13:52:04     INFO -      eip = 0x6a19401e   esp = 0x21e8bccc   ebp = 0x21e8f978
13:52:04     INFO -      Found by: call frame info
13:52:04     INFO -   9  xul.dll!mozilla::MediaStreamGraphImpl::PlayAudio(mozilla::MediaStream *,__int64,__int64) [MediaStreamGraph.cpp:6644c76071e6 : 798 + 0xa]
13:52:04     INFO -      eip = 0x6a1c32b9   esp = 0x21e8f980   ebp = 0x21e8f9fc
13:52:04     INFO -      Found by: call frame info
13:52:04     INFO -  10  xul.dll!mozilla::MediaStreamGraphImpl::RunThread() [MediaStreamGraph.cpp:6644c76071e6 : 1013 + 0x13]
13:52:04     INFO -      eip = 0x6a1c361f   esp = 0x21e8fa04   ebp = 0x21e8fae0
13:52:04     INFO -      Found by: call frame info

It looks like we're waiting for more room to free up in the buffer, but nothing ever wakes us up? Paul, Matthew, any known bugs on that?
Disregard comments 91-94, they were in fact permaorange now backed out (likely bug 867174).
Closing bugs where TBPLbot has previously commented, but have now not been modified for >3 months & do not contain the whiteboard strings for disabled/annotated tests or use the keyword leave-open. Filter on: mass-intermittent-bug-closure-2014-07
Status: REOPENED → RESOLVED
Closed: 11 years ago → 10 years ago
Resolution: --- → WORKSFORME
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: