524812 - slow minis need more time for mochitest-plain (/tests/security/ssl/mixedcontent/test_secureAll.html and other mixedcontent tests sporadically time out)

Status: RESOLVED FIXED

(Release Engineering :: General, defect)

Description

[Paul O'Shannessy [:zpao] (not bugmail, email directly)]

First Seen:
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox3.5-Unittest/1256672470.1256676163.6838.gz
OS X 10.5.2 mozilla-1.9.1 test mochitests on 2009/10/27 12:41:10

...
74447 INFO TEST-PASS | /tests/security/ssl/mixedcontent/test_innerHtmlUnsecurePicture.html | innerHTML back to previous, expected  got
74448 INFO TEST-PASS | /tests/security/ssl/mixedcontent/test_innerHtmlUnsecurePicture.html | , expected secure got secure
74449 INFO TEST-PASS | /tests/security/ssl/mixedcontent/test_innerHtmlUnsecurePicture.html | for 'secure' expected flags [0,0,0],
74451 INFO Running /tests/security/ssl/mixedcontent/test_secureAll.html...

command timed out: 3600 seconds elapsed, killing pid 564
process killed by signal 9
program finished with exit code -1

Comment 1

[Daniel Holbert [:dholbert]]

This has actually been happening with a ton of the "security/ssl/mixedcontent" tests on Mac OS 1.9.1 over the past few weeks.

e.g. test_cssContent2.html...
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox3.5-Unittest/1256763908.1256767646.10515.gz
OS X 10.5.2 mozilla-1.9.1 test mochitests on 2009/10/28 14:05:08


test_unsecureIframe.html...
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox3.5-Unittest/1257048942.1257052637.23700.gz
OS X 10.5.2 mozilla-1.9.1 test mochitests on 2009/10/31 21:15:42

test_securePicture.html...
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox3.5-Unittest/1257396217.1257400235.30468.gz
OS X 10.5.2 mozilla-1.9.1 test mochitests on 2009/11/04 20:43:37

test_innerHtmlDelayedUnsecurePicture.html...
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox3.5-Unittest/1257438987.1257442711.29749.gz
OS X 10.5.2 mozilla-1.9.1 test mochitests on 2009/11/05 08:36:27

test_documentWrite1.html...
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox3.5-Unittest/1257411503.1257415223.32498.gz
OS X 10.5.2 mozilla-1.9.1 test mochitests on 2009/11/05 00:58:23

Comment 2

[Daniel Holbert [:dholbert]]

Some more timeouts like this (all from the "mixedcontent" folder):

test_dynUnsecurePicture.html...
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox3.5-Unittest/1257108104.1257111765.17350.gz
OS X 10.5.2 mozilla-1.9.1 test mochitests on 2009/11/01 12:41:44
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox3.5-Unittest/1257132292.1257135958.20567.gz
OS X 10.5.2 mozilla-1.9.1 test mochitests on 2009/11/01 19:24:52

test_cssBefore1.html...
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox3.5-Unittest/1257007951.1257011658.30519.gz
OS X 10.5.2 mozilla-1.9.1 test mochitests on 2009/10/31 09:52:31

test_unsecureIframe2.html...
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox3.5-Unittest/1257192147.1257195830.22709.gz
OS X 10.5.2 mozilla-1.9.1 test mochitests on 2009/11/02 12:02:27

test_bug455367.html...
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox3.5-Unittest/1257159722.1257163448.28776.gz
Linux mozilla-1.9.1 test mochitests on 2009/11/02 03:02:02
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox3.5-Unittest/1257159722.1257163474.29095.gz
OS X 10.5.2 mozilla-1.9.1 test mochitests on 2009/11/02 03:02:02

test_secureAll.html...
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox3.5-Unittest/1257189926.1257193660.29982.gz
OS X 10.5.2 mozilla-1.9.1 test mochitests on 2009/11/02 11:25:26

test_unsecurePictureInIframe.html...
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox3.5-Unittest/1257187678.1257191359.3963.gz
OS X 10.5.2 mozilla-1.9.1 test mochitests on 2009/11/02 10:47:58

Note that one of the logs above above was from Linux -- so while this is a mac-heavy class of timeouts, it apparently isn't mac-only.

Comment 3

[Daniel Holbert [:dholbert]]

Here's a similar-looking timeout from today in "test_html5_tree_construction.html":
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox3.5-Unittest/1257491225.1257494896.23149.gz
OS X 10.5.2 mozilla-1.9.1 test mochitests on 2009/11/05 23:07:05

This test isn't in the /mixedcontent/ folder, but it's just barely before that folder's tests.  (After test_html5_tree_construction.html comes 3 small tests in /security/ssl/bugs/, and then /security/ssl/mixedcontent/)

This could be related, if this bug ends up being due to something like "Firefox sporadically times out N seconds after doing X".  (or perhaps "Mac OS eats up our CPU N seconds after rebooting")

Comment 4

[Daniel Holbert [:dholbert]]

(In reply to comment #3)
> Here's a similar-looking timeout from today
(oops -- s/today/yesterday/ )

Along the same lines as comment 3: here's a sporadic test in a test from fairly soon *after* the /security/ssl/mixedcontent/ folder --  test_Microformats_hCard.html:
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox3.5-Unittest/1257543561.1257547278.5005.gz
OS X 10.5.2 mozilla-1.9.1 test mochitests on 2009/11/06 13:39:21

Comment 5

[Daniel Holbert [:dholbert]]

http://tinderbox.mozilla.org/showlog.cgi?log=Firefox3.5-Unittest/1257549027.1257552805.2106.gz
OS X 10.5.2 mozilla-1.9.1 test mochitests on 2009/11/06 15:10:27
tests/security/ssl/mixedcontent/test_dynUnsecureIframeRedirect.html

Comment 6

[Timothy Nikkel (:tnikkel)]

The first occurrence of this failure seems to be with http://hg.mozilla.org/releases/mozilla-1.9.1/rev/1a90838e2043

A week before (only 10 pushes) bug 521461 landed on 1.9.1, and it changes some mochitests in the mixedcontent directory so it could be related.

Comment 7

[Timothy Nikkel (:tnikkel)]

http://tinderbox.mozilla.org/showlog.cgi?log=Firefox3.5-Unittest/1257746101.1257749773.483.gz

Comment 8

[Nick Thomas [:nthomas] (UTC+12)]

I dug into this big time, data is at 
http://spreadsheets.google.com/pub?key=tH22zs1cOgXVZHQy9lBjb2A&output=html

Notes:
* There are 55 builds starting from 19/10/09 10:02:04
* 17 have been green
* 38 have been orange (test fail)
  * 23 of those are "command timed out: 3600 seconds elapsed"
  * 12 leaks of 472 bytes, sometimes with other intermittent failures
  *  3 are other failures that occur just once

The 23 timeouts have occurred because the mochitest run-time has reached 1 hour, which is the limit we have set in buildbot. This relatively new, and different from "no output for N seconds" which indicates a hang. 

Every timeout occurs on a 1.6GHz mini (moz2-darwin9-slave19 thru 26), added on 2009-10-20 in bug 521052. There are some runs on slower minis which leak instead, but that also happens on xserves and 1.8GHz minis. I'll attach a patch shortly which bumps the timeout. I expect we'd see similar behavior for electrolysis and tracemonkey tests if we looked, because they share the slow minis; m-c, m-1.9.2 and places don't and should be unaffected.

The signature for the leaks is  (trimmed output)
leaked 472 bytes during test execution
leaked 2 instances of nsCLiveconnect with size 4 bytes each (8 bytes total)
leaked 1 instance of nsComponentManagerImpl with size 276 bytes
leaked 1 instance of nsJVMManager with size 4 bytes
leaked 3 instances of nsLocalFile with size 24 bytes each (72 bytes total)
leaked 1 instance of nsPluginHostImpl with size 84 bytes
leaked 2 instances of nsTArray_base with size 4 bytes each (8 bytes total)
leaked 2 instances of nsVoidArray with size 4 bytes each (8 bytes total)
leaked 1 instance of nsWeakReference with size 12 bytes
I couldn't find a bug for this, but didn't try very hard. If a developer could follow up here it would be much appreciated.

Comment 9

[Timothy Nikkel (:tnikkel)]

I believe the leak was caused by the reintroduction of liveconnect and has been fixed (don't have the bug numbers off hand).

Comment 10

[Nick Thomas [:nthomas] (UTC+12)]

Attachment: 60 --> 90 mins

This sets a 90 minutes maxTime for all mochitest-* suites, so it's not a very targeted change. Perhaps a better approach is to split mochitest-plain in 5 as we do on m-c, depending of course on our readiness to do that.

If this is acceptable, could you land and reconfig the master ? All the mac test orange is getting in the way of freezing 3.5.6 on Nov 10.

Comment 11

[Nick Thomas [:nthomas] (UTC+12)]

(In reply to comment #9)
> I believe the leak was caused by the reintroduction of liveconnect and has been
> fixed (don't have the bug numbers off hand).

Ah hah, that'll be bug 526277 and
 http://hg.mozilla.org/releases/mozilla-1.9.1/rev/1f087bddafcf
then. Thanks!

Comment 12

[Nick Thomas [:nthomas] (UTC+12)]

Comment on attachment 411156 [details] [diff] [review]
60 --> 90 mins

http://hg.mozilla.org/build/buildbotcustom/rev/dd53f015b0aa

Comment 13

[Nick Thomas [:nthomas] (UTC+12)]

Master reconfig'd. Lets reopen if we continue to see timeouts after 5400 seconds.

Comment 14

[Nick Thomas [:nthomas] (UTC+12)]

Removing old dependency.