Closed Bug 843479 Opened 9 years ago Closed 8 years ago

Frequent Ubuntu xpcshell failure: test_init_async_multiple_then_sync.js | test failed (with xpcshell return code: 0), see following log


(Release Engineering :: General, defect)

Not set


(Not tracked)



(Reporter: philor, Unassigned)



(Keywords: intermittent-failure, Whiteboard: [leave open])


(1 file)

So many moving parts, between switching to Ubuntu and switching to Ubuntu VMs and switching to mozharness, I'm not at all sure where to think this came from.
Ubuntu 12.04 x64 mozilla-inbound opt test xpcshell on 2013-02-20 18:15:43 PST for push 82747d694e7a
slave: tst-linux64-ec2-038

18:44:41     INFO -  TEST-INFO | /builds/slave/test/build/tests/xpcshell/tests/toolkit/components/search/tests/xpcshell/test_init_async_multiple_then_sync.js | running test ...
18:44:42  WARNING -  TEST-UNEXPECTED-FAIL | /builds/slave/test/build/tests/xpcshell/tests/toolkit/components/search/tests/xpcshell/test_init_async_multiple_then_sync.js | test failed (with xpcshell return code: 0), see following log:
18:44:42  WARNING -  This is a harness error.
18:44:42     INFO -  >>>>>>>
18:44:42     INFO -  TEST-INFO | (xpcshell/head.js) | test 1 pending
18:44:42     INFO -  TEST-INFO | /builds/slave/test/build/tests/xpcshell/tests/toolkit/components/search/tests/xpcshell/test_init_async_multiple_then_sync.js | Setting up test
18:44:42     INFO -  TEST-INFO | (xpcshell/head.js) | test 2 pending
18:44:42     INFO -  TEST-INFO | /builds/slave/test/build/tests/xpcshell/tests/toolkit/components/search/tests/xpcshell/test_init_async_multiple_then_sync.js | Test starting
18:44:42     INFO -  *** Search: metadata init: starting
18:44:42     INFO -  *** Search: Search service falling back to synchronous initialization at SRCH_SVC__ensureInitialized@resource://gre/components/nsSearchService.js:2543
18:44:42     INFO -  SRCH_SVC_getEngines@resource://gre/components/nsSearchService.js:3293
18:44:42     INFO -  run_test@/builds/slave/test/build/tests/xpcshell/tests/toolkit/components/search/tests/xpcshell/test_init_async_multiple_then_sync.js:58
18:44:42     INFO -  _execute_test@/builds/slave/test/build/tests/xpcshell/head.js:325
18:44:42     INFO -  @-e:1
18:44:42     INFO -  This is generally the consequence of an add-on using a deprecated search service API.
18:44:42     INFO -  *** Search: metadata syncInit: starting

(many long lines elided, all of them expressing joy and happiness with how well things are going)

18:44:42     INFO -  TEST-PASS | /builds/slave/test/build/tests/xpcshell/tests/toolkit/components/search/tests/xpcshell/test_init_async_multiple_then_sync.js | [run_test : 59] [xpconnect wrapped nsISearchEngine],[xpconnect wrapped nsISearchEngine],[xpconnect wrapped nsISearchEngine],[xpconnect wrapped nsISearchEngine],[xpconnect wrapped nsISearchEngine],[xpconnect wrapped nsISearchEngine],[xpconnect wrapped nsISearchEngine] != null
18:44:42     INFO -  TEST-INFO | (xpcshell/head.js) | test 2 finished
18:44:42     INFO -  TEST-INFO | (xpcshell/head.js) | running event loop
18:44:42     INFO -  TEST-INFO | (xpcshell/head.js) | test 1 finished
18:44:42     INFO -  TEST-INFO | (xpcshell/head.js) | exiting test
18:44:42     INFO -  TEST-PASS | (xpcshell/head.js) | 18 (+ 0) check(s) passed
18:44:42     INFO -  TEST-INFO | (xpcshell/head.js) | 0 check(s) todo
18:44:42     INFO -  *** Search: _batchCacheInvalidation: Invalidating engine cache
18:44:42     INFO -  *** Search: _buildCache: Writing to cache file.
18:44:42     INFO -  <<<<<<<

Note that "see following log" is an unhelpful suggestion, because there's absolutely no visible sign of failure anywhere in the log. The only slightly odd looking thing is that "INFO -  @-e:1".

Is mozharness eating a failure? Is mozharness calling success failure? Is something broken with the Ubuntu slaves that's causing this (intermittent, but hellishly frequent) failure?
Also notable: landed on February 20, the date of this bug.  (Found using hg annotate on the "see following log" line.)
That'd be an awesome fit if it happened between that landing on the 20th and when I backed it out again on the 20th, then started again when that relanded on the 21st, then moved to m-c when that was merged there at 3am today.
(In reply to Aki Sasaki [:aki] from comment #25)
> Also notable:
> landed on February
> 20, the date of this bug.  (Found using hg annotate on the "see following
> log" line.)

Inbound timeline is as follows:

Initial checkin: 2013-02-20 12:47 PST 
Backout:         2013-02-20 17:22 PST 
Final checkin:   2013-02-21 10:31 PST

Comments #4-7 show inbound failures when this was backed out. Comment #2 even shows a failure on Aurora! Bug 771578 is not the problem here.
I was going to say "oh, mozharness unittests aren't turned on in aurora", but looks like the funky ubuntu for-loop might be enabling mozharness unittests on all branches for ubuntu.

What do we want to do here, switch back to Fedora for xpcshell?
The "INFO -  @-e:1" (and surrounding lines) is normal and expected by this test. We are forcing the use of a fallback that causes this warning.
Attached patch Additional logsSplinter Review
The attached patch adds more logging to the test, which might help us find out where things fail. Self-reviewing, given that it's only logging.
Attachment #717598 - Flags: review+
Keywords: checkin-needed
Whiteboard: [leave open]
I do not see anything of the logs that I have added in the patch landed by Ryan.

As the links all seem to come from Mozilla-Aurora, does this mean that we should uplift this patch to get any additional logs?
Removing the talos dependency, as xpcshell is not talos.
No longer blocks: 713055
Product: → Release Engineering
Closed: 8 years ago
Resolution: --- → WORKSFORME
Component: General Automation → General
You need to log in before you can comment on or make changes to this bug.