Last Comment Bug 744698 - Intermittent test_nodb_pluschanges.js | command timed out: 1200 seconds without output
: Intermittent test_nodb_pluschanges.js | command timed out: 1200 seconds witho...
Status: RESOLVED FIXED
: intermittent-failure
Product: Firefox
Classification: Client Software
Component: Search (show other bugs)
: Trunk
: All All
: -- normal (vote)
: Firefox 15
Assigned To: David Rajchenbach-Teller [:Yoric] (please use "needinfo")
:
Mentors:
Depends on: 500388
Blocks: 438871
  Show dependency treegraph
 
Reported: 2012-04-11 22:50 PDT by Phil Ringnalda (:philor)
Modified: 2012-11-25 19:31 PST (History)
5 users (show)
ryanvm: in‑testsuite-
See Also:
Crash Signature:
(edit)
QA Whiteboard:
Iteration: ---
Points: ---
Has Regression Range: ---
Has STR: ---


Attachments
Forcing timeout, to improve logging (3.64 KB, patch)
2012-04-22 02:41 PDT, David Rajchenbach-Teller [:Yoric] (please use "needinfo")
gavin.sharp: review+
Details | Diff | Review
Forcing timeout, to improve logging (3.64 KB, patch)
2012-04-23 00:08 PDT, David Rajchenbach-Teller [:Yoric] (please use "needinfo")
no flags Details | Diff | Review
Forcing timeout, to improve logging (3.65 KB, patch)
2012-04-23 11:10 PDT, David Rajchenbach-Teller [:Yoric] (please use "needinfo")
no flags Details | Diff | Review
Closing stream once commit is complete (4.74 KB, patch)
2012-04-26 08:53 PDT, David Rajchenbach-Teller [:Yoric] (please use "needinfo")
no flags Details | Diff | Review
Closing stream once commit is complete (2.33 KB, patch)
2012-04-27 00:16 PDT, David Rajchenbach-Teller [:Yoric] (please use "needinfo")
gavin.sharp: review+
Details | Diff | Review

Description Phil Ringnalda (:philor) 2012-04-11 22:50:28 PDT
https://tbpl.mozilla.org/php/getParsedLog.php?id=10830007&tree=Mozilla-Inbound
Rev3 Fedora 12x64 mozilla-inbound debug test xpcshell on 2012-04-11 18:21:30 PDT for push bfa27d58769d

TEST-INFO | /home/cltbld/talos-slave/test/build/xpcshell/tests/toolkit/components/search/tests/xpcshell/test_nodb_pluschanges.js | running test ...

command timed out: 1200 seconds without output, attempting to kill
Comment 2 David Rajchenbach-Teller [:Yoric] (please use "needinfo") 2012-04-19 07:18:04 PDT
Investigating. Is this only on Linux 64bit?
Comment 3 David Rajchenbach-Teller [:Yoric] (please use "needinfo") 2012-04-19 07:21:35 PDT
How comes I can't see any log?
Comment 4 David Rajchenbach-Teller [:Yoric] (please use "needinfo") 2012-04-19 07:48:04 PDT
I can't see any logs on tbpl (this test should produce pages of logs). Also, I cannot reproduce the issue and I cannot find any occurrence of on inbound it since Marco's message. Right now, I have no idea what can have gone wrong or how I can fix it.

If anybody manages to reproduce the issue, I would be very interested in the logs.
Comment 5 Matt Brubeck (:mbrubeck) 2012-04-19 08:23:35 PDT
(In reply to David Rajchenbach Teller [:Yoric] from comment #2)
> Investigating. Is this only on Linux 64bit?

Comment 1 is on Mac OS X 32-bit.

The missing logging is because of bug 500388.  Since this failure seems fairly rare, the best bet might be fix or work around that bug so we can get logs if it happens in the future.
Comment 6 David Rajchenbach-Teller [:Yoric] (please use "needinfo") 2012-04-22 01:13:56 PDT
(In reply to Matt Brubeck (:mbrubeck) from comment #5)
> The missing logging is because of bug 500388.  Since this failure seems
> fairly rare, the best bet might be fix or work around that bug so we can get
> logs if it happens in the future.

Ok. If I set a timeout internally and call |do_throw| from that timeout, this should work around bug 500388, shouldn't it?
Comment 7 David Rajchenbach-Teller [:Yoric] (please use "needinfo") 2012-04-22 02:41:57 PDT
Created attachment 617299 [details] [diff] [review]
Forcing timeout, to improve logging

Is this what you have in mind?
Comment 8 Matt Brubeck (:mbrubeck) 2012-04-22 07:58:30 PDT
Comment on attachment 617299 [details] [diff] [review]
Forcing timeout, to improve logging

Looks like a good idea, but I've never written an xpcshell test and am not the best person to review this.  (For example, it's not clear to me whether unfired do_timeout timers are automatically cleared when the test finishes.)
Comment 9 David Rajchenbach-Teller [:Yoric] (please use "needinfo") 2012-04-22 09:07:02 PDT
Comment on attachment 617299 [details] [diff] [review]
Forcing timeout, to improve logging

Ok, placing the burden back on Gavin.
Comment 10 :Gavin Sharp [email: gavin@gavinsharp.com] 2012-04-22 18:18:31 PDT
Comment on attachment 617299 [details] [diff] [review]
Forcing timeout, to improve logging

>diff --git a/toolkit/components/search/tests/xpcshell/test_nodb_pluschanges.js b/toolkit/components/search/tests/xpcshell/test_nodb_pluschanges.js

>+  do_timeout(2000, function() {

2 seconds isn't that long, which might cause this test to fail where it would otherwise pass. Given that the harness timeout seems to occur after 20 minutes, you could stand to make this timeout be ~10 minutes to be sure to only catch the cases where we're truly failing.
Comment 11 David Rajchenbach-Teller [:Yoric] (please use "needinfo") 2012-04-23 00:08:28 PDT
Created attachment 617403 [details] [diff] [review]
Forcing timeout, to improve logging

Done.
Comment 12 David Rajchenbach-Teller [:Yoric] (please use "needinfo") 2012-04-23 01:48:32 PDT
Comment on attachment 617403 [details] [diff] [review]
Forcing timeout, to improve logging

[Approval Request Comment]
Please see https://wiki.mozilla.org/Tree_Rules for information on mozilla-central landings that do not require approval.

Possible risk to Fennec Native 14 (if any): None, it should only impact logging of one test.
Comment 13 Matt Brubeck (:mbrubeck) 2012-04-23 08:04:38 PDT
Comment on attachment 617403 [details] [diff] [review]
Forcing timeout, to improve logging

You don't need explicit approval; you can just land this with a=test-only:
https://wiki.mozilla.org/Tree_Rules
Comment 14 David Rajchenbach-Teller [:Yoric] (please use "needinfo") 2012-04-23 11:10:01 PDT
Created attachment 617550 [details] [diff] [review]
Forcing timeout, to improve logging

Here we go. Thanks, Matt.
Comment 15 Ryan VanderMeulen [:RyanVM] 2012-04-23 15:06:37 PDT
https://hg.mozilla.org/integration/mozilla-inbound/rev/efba113561c6
Comment 16 Ed Morley [:emorley] 2012-04-24 04:16:14 PDT
> Created attachment 617550 [details] [diff] [review]
> Forcing timeout, to improve logging

https://hg.mozilla.org/mozilla-central/rev/efba113561c6
Comment 17 Treeherder Robot 2012-04-25 20:19:27 PDT
khuey
https://tbpl.mozilla.org/php/getParsedLog.php?id=11213591&tree=Firefox
Rev3 Fedora 12 mozilla-central pgo test xpcshell on 2012-04-25 18:57:14
slave: talos-r3-fed-037

TEST-UNEXPECTED-FAIL | /home/cltbld/talos-slave/test/build/xpcshell/tests/toolkit/components/search/tests/xpcshell/test_nodb_pluschanges.js | test failed (with xpcshell return code: 0), see following log:
TEST-UNEXPECTED-FAIL | /home/cltbld/talos-slave/test/build/xpcshell/tests/toolkit/components/search/tests/xpcshell/test_nodb_pluschanges.js | Timeout - See following stack:
TEST-UNEXPECTED-FAIL | /home/cltbld/talos-slave/test/build/xpcshell/head.js | exception thrown from do_timeout callback: 2147500036 - See following stack:
Comment 18 David Rajchenbach-Teller [:Yoric] (please use "needinfo") 2012-04-26 08:53:35 PDT
Created attachment 618672 [details] [diff] [review]
Closing stream once commit is complete

Ok, logs make it a little better. Adding more logs and what might possibly be a fix.
Comment 19 :Gavin Sharp [email: gavin@gavinsharp.com] 2012-04-26 10:16:32 PDT
This patch doesn't seem to apply on top of the other one, did you attach the wrong one?

I wonder whether asyncCopy should handle explicitly closing the output stream before invoking its callback. It seems like this problem could affect many other consumers of it (who don't currently rely on immediately reading back in the written data, I guess).
Comment 20 David Rajchenbach-Teller [:Yoric] (please use "needinfo") 2012-04-27 00:16:18 PDT
Created attachment 618944 [details] [diff] [review]
Closing stream once commit is complete

Sorry about that, I had posted a merged patch. This one should do the trick.
Comment 21 David Rajchenbach-Teller [:Yoric] (please use "needinfo") 2012-04-27 00:18:47 PDT
(In reply to :Gavin Sharp (use gavin@gavinsharp.com for email) from comment #19)
> This patch doesn't seem to apply on top of the other one, did you attach the
> wrong one?
> 
> I wonder whether asyncCopy should handle explicitly closing the output
> stream before invoking its callback. It seems like this problem could affect
> many other consumers of it (who don't currently rely on immediately reading
> back in the written data, I guess).

If this patch proves to fix the issue, this definitely deserves investigation.
Comment 22 David Rajchenbach-Teller [:Yoric] (please use "needinfo") 2012-05-04 00:03:55 PDT
Gavin? Still waiting for your word.
Comment 23 David Rajchenbach-Teller [:Yoric] (please use "needinfo") 2012-05-08 03:12:15 PDT
Thanks
Comment 24 Ed Morley [:emorley] 2012-05-08 04:52:28 PDT
applying c:\users\ed\appdata\local\temp\thg-import-5fuczc.patch
patching file toolkit/components/search/nsSearchService.js
Hunk #1 FAILED at 3781
1 out of 1 hunks FAILED -- saving rejects to file toolkit/components/search/nsSearchService.js.rej
patching file toolkit/components/search/tests/xpcshell/test_nodb_pluschanges.js
abort: patch failed to apply
Comment 25 Ryan VanderMeulen [:RyanVM] 2012-05-08 15:51:01 PDT
https://hg.mozilla.org/integration/mozilla-inbound/rev/eb164529f0d5

David, should the [leave open] still be on the whiteboard?
Comment 26 David Rajchenbach-Teller [:Yoric] (please use "needinfo") 2012-05-09 01:13:45 PDT
You are right, we should probably close this bug and reopen it if necessary.
Comment 27 Ed Morley [:emorley] 2012-05-09 03:44:03 PDT
https://hg.mozilla.org/mozilla-central/rev/eb164529f0d5

Note You need to log in before you can comment on or make changes to this bug.