744698 - Intermittent test_nodb_pluschanges.js | command timed out: 1200 seconds without output

Status: RESOLVED FIXED

(Firefox :: Search, defect)

Description

[Phil Ringnalda (:philor)]

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 1

[Marco Bonardo [:mak]]

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

Comment 2

[David Teller [:Yoric] - still alive but not very active]

Investigating. Is this only on Linux 64bit?

Comment 3

[David Teller [:Yoric] - still alive but not very active]

How comes I can't see any log?

Comment 4

[David Teller [:Yoric] - still alive but not very active]

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)]

(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 Teller [:Yoric] - still alive but not very active]

(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 Teller [:Yoric] - still alive but not very active]

Attachment: Forcing timeout, to improve logging

Is this what you have in mind?

Comment 8

[Matt Brubeck (:mbrubeck)]

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 Teller [:Yoric] - still alive but not very active]

Comment on attachment 617299 [details] [diff] [review]
Forcing timeout, to improve logging

Ok, placing the burden back on Gavin.

Comment 10

[:Gavin Sharp [email: [e-mail]]]

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 Teller [:Yoric] - still alive but not very active]

Attachment: Forcing timeout, to improve logging

Done.

Comment 12

[David Teller [:Yoric] - still alive but not very active]

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)]

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 Teller [:Yoric] - still alive but not very active]

Attachment: Forcing timeout, to improve logging

Here we go. Thanks, Matt.

Comment 15

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/integration/mozilla-inbound/rev/efba113561c6

Comment 16

[Ed Morley [:emorley]]

> Created attachment 617550 [details] [diff] [review]
> Forcing timeout, to improve logging

https://hg.mozilla.org/mozilla-central/rev/efba113561c6

Comment 17

[Legacy TBPL/Treeherder Robot]

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 Teller [:Yoric] - still alive but not very active]

Attachment: 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: [e-mail]]]

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 Teller [:Yoric] - still alive but not very active]

Attachment: Closing stream once commit is complete

Sorry about that, I had posted a merged patch. This one should do the trick.

Comment 21

[David Teller [:Yoric] - still alive but not very active]

(In reply to :Gavin Sharp (use [e-mail] 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 Teller [:Yoric] - still alive but not very active]

Gavin? Still waiting for your word.

Comment 23

[David Teller [:Yoric] - still alive but not very active]

Thanks

Comment 24

[Ed Morley [:emorley]]

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]]

https://hg.mozilla.org/integration/mozilla-inbound/rev/eb164529f0d5

David, should the [leave open] still be on the whiteboard?

Comment 26

[David Teller [:Yoric] - still alive but not very active]

You are right, we should probably close this bug and reopen it if necessary.

Comment 27

[Ed Morley [:emorley]]

https://hg.mozilla.org/mozilla-central/rev/eb164529f0d5