(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

Comment on attachment 733112 [details] [diff] [review] Log error message along with the error https://hg.mozilla.org/integration/mozilla-inbound/rev/5302617ee727

Patch just adds logging; forgot to stick [leave open] in the whiteboard

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.

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.

(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.

uh, right. I'm not too familiar with pushPrefEnv.

Not fixed yet, as per comment 47.

(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.

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.

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