Closed Bug 542736 Opened 10 years ago Closed 10 years ago

random orange in xpcshell/tests/test_places/expiration/test_pref_interval.js | test failed (with xpcshell return code: 0), with "false == true

Categories

(Toolkit :: Places, defect)

Product:
Toolkit
Component:
Places
Platform:
x86
macOS
Type:
defect
Priority:
Not set

Tracking

()

Status:
RESOLVED FIXED
Milestone:
mozilla1.9.3a5

People

(Reporter: dholbert, Assigned: mak)

References

(
URL
)

Details

(Keywords: intermittent-failure)

Attachments

(2 files)

increase interval leeway [Checkin: Comment 17]
1.63 KB, patch
mak
: review+
Details | Diff | Splinter Review
patch v1.0
5.12 KB, patch
sdwilsh
: review+
Details | Diff | Splinter Review 
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1264669941.1264671983.3961.gz
OS X 10.5.2 mozilla-central debug test xpcshell on 2010/01/28 01:12:21
s: moz2-darwin9-slave11
TEST-UNEXPECTED-FAIL | /builds/slave/mozilla-central-macosx-debug-unittest-xpcshell/build/xpcshell/tests/test_places/expiration/test_pref_interval.js | test failed (with xpcshell return code: 0), see following log:
TEST-UNEXPECTED-FAIL | /builds/slave/mozilla-central-macosx-debug-unittest-xpcshell/build/xpcshell/tests/test_places/expiration/test_pref_interval.js | false == true - See following stack:

Relevant chunk of shortlog is:
TEST-UNEXPECTED-FAIL | /builds/slave/mozilla-central-macosx-debug-unittest-xpcshell/build/xpcshell/tests/test_places/expiration/test_pref_interval.js | test failed (with xpcshell return code: 0), see following log:
  >>>>>>>
  ### XPCOM_MEM_LEAK_LOG defined -- logging leaks to /var/folders/TL/TLg3RrMbFAur2hBCXvCeqk+++TM/-Tmp-/tmprD7E_V/runxpcshelltests_leaks.log
*** Registering components in: xpconnect
*** Registering components in: nsUConvModule
*** Registering components in: nsI18nModule

 Skipping 79 Lines...

nsNativeModuleLoader::LoadModule("/builds/slave/mozilla-central-macosx-debug-unittest-xpcshell/build/MinefieldDebug.app/Contents/MacOS/components/libtestdynamic.dylib") - load FAILED, rv: 80004005, error:
	Unknown error: -2804
nsNativeModuleLoader::LoadModule("/builds/slave/mozilla-central-macosx-debug-unittest-xpcshell/build/MinefieldDebug.app/Contents/MacOS/components/libMyService.dylib") - load FAILED, rv: 80004005, error:
	Unknown error: -2804
nsNativeModuleLoader::LoadModule("/builds/slave/mozilla-central-macosx-debug-unittest-xpcshell/build/MinefieldDebug.app/Contents/MacOS/components/libxpcomsample.dylib") - load FAILED, rv: 80004005, error:
	Unknown error: -2804
*** Registering components in: nsAlertsServiceModule
nsNativeModuleLoader::LoadModule("/builds/slave/mozilla-central-macosx-debug-unittest-xpcshell/build/MinefieldDebug.app/Contents/MacOS/components/libtestcrasher.dylib") - load FAILED, rv: 80004005, error:
	Unknown error: -2804
*** registering FeedWriter.js: [ Feed Writer ]
*** registering WebContentConverter.js: [ Web Content Handler Registrar ]
*** registering nsMicrosummaryService.js: [ Microsummary Service ]
*** registering nsPlacesTransactionsService.js: [ Places Transaction Manager ]
*** registering PlacesProtocolHandler.js: [ Places Protocol Handler ]
*** registering nsPrivateBrowsingService.js: [ PrivateBrowsing Service ]
*** registering nsSessionStore.js: [ Browser Session Store Service ]
*** registering nsSessionStartup.js: [ Browser Session Startup Service ]
*** registering nsSetDefaultBrowser.js: [ Default Browser Cmdline Handler ]
*** Registering components in: nsBrowserCompsModule
************************************************************
* Call to xpconnect wrapped JSObject produced this error:  *
[Exception... "Component returned failure code: 0x80570016 (NS_ERROR_XPC_GS_RETURNED_FAILURE) [nsIJSCID.getService]"  nsresult: "0x80570016 (NS_ERROR_XPC_GS_RETURNED_FAILURE)"  location: "JS frame :: file:///builds/slave/mozilla-central-macosx-debug-unittest-xpcshell/build/MinefieldDebug.app/Contents/MacOS/components/nsBrowserContentHandler.js :: mod_regself :: line 799"  data: no]
************************************************************
*** registering nsBrowserGlue.js: [ Firefox Browser Glue Service, Geolocation Prompting Component ]
*** registering fuelApplication.js: [ Application ]
TEST-INFO | (xpcshell/head.js) | test 1 pending
Set interval to 1s.
TEST-INFO | (xpcshell/head.js) | test 2 pending
TEST-INFO | (xpcshell/head.js) | test 2 finished
TEST-INFO | (xpcshell/head.js) | running event loop
TEST-UNEXPECTED-FAIL | /builds/slave/mozilla-central-macosx-debug-unittest-xpcshell/build/xpcshell/tests/test_places/expiration/test_pref_interval.js | false == true - See following stack:
JS frame :: /builds/slave/mozilla-central-macosx-debug-unittest-xpcshell/build/xpcshell/head.js :: do_throw :: line 202
JS frame :: /builds/slave/mozilla-central-macosx-debug-unittest-xpcshell/build/xpcshell/head.js :: do_check_eq :: line 232
JS frame :: /builds/slave/mozilla-central-macosx-debug-unittest-xpcshell/build/xpcshell/tests/test_places/expiration/test_pref_interval.js :: check_result :: line 123
JS frame :: /builds/slave/mozilla-central-macosx-debug-unittest-xpcshell/build/xpcshell/head.js :: anonymous :: line 96
TEST-INFO | (xpcshell/head.js) | exiting test
WARNING: nsExceptionService ignoring thread destruction after shutdown: file /builds/slave/mozilla-central-macosx-debug/build/xpcom/base/nsExceptionService.cpp, line 194
nsXPConnect::CommenceShutdown()
nsStringStats
 => mAllocCount:           2432
 => mReallocCount:           11
 => mFreeCount:            2432
 => mShareCount:            193
 => mAdoptCount:            816
 => mAdoptFreeCount:        816

  <<<<<<<
Blocks: 438871
Whiteboard: [orange]
OS: Linux → Mac OS X
Just failed on tryserver, too:
http://tinderbox.mozilla.org/showlog.cgi?log=MozillaTry/1264674307.1264684897.25308.gz
OS X 10.5.2 try hg unit test on 2010/01/28 02:25:07

Recent regression?
doubt it, it's probably just that the 1s addition in the test is not enough if the tinderbox is under heavy load...
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1265203842.1265206139.31296.gz
OS X 10.5.2 mozilla-central debug test xpcshell on 2010/02/03 05:30:42
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1265500580.1265502621.27698.gz
OS X 10.5.2 mozilla-central debug test xpcshell on 2010/02/06 15:56:20
s: moz2-darwin9-slave18
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1265768381.1265771158.16286.gz
OS X 10.5.2 mozilla-central debug test xpcshell on 2010/02/09 18:19:41
s: moz2-darwin9-slave23
http://tinderbox.mozilla.org/showlog.cgi?log=SeaMonkey/1266802005.1266803746.19182.gz
OS X 10.5 comm-central-trunk debug test xpcshell on 2010/02/21 17:26:45
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1266887890.1266890016.12209.gz
OS X 10.5.2 mozilla-central debug test xpcshell on 2010/02/22 17:18:10
s: moz2-darwin9-slave15
http://tinderbox.mozilla.org/showlog.cgi?log=TraceMonkey/1268466972.1268468417.20045.gz
OS X 10.5.2 tracemonkey debug test xpcshell on 2010/03/12 23:56:12
s: bm-xserve22
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1268828602.1268830725.30292.gz
OS X 10.5.2 mozilla-central debug test xpcshell on 2010/03/17 05:23:22
s: moz2-darwin9-slave15
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1268849901.1268853301.1353.gz
WINNT 5.2 mozilla-central debug test xpcshell on 2010/03/17 11:18:21
s: win32-slave25
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1268925969.1268927595.28363.gz
Linux mozilla-central opt test xpcshell

(In reply to comment #2)
> doubt it, it's probably just that the 1s addition in the test is not enough if
> the tinderbox is under heavy load...

Would we be comfortable increasing it?
(In reply to comment #12)
> Would we be comfortable increasing it?

absolutely, i just forgot or did not have time. rs=me
let waitSeconds = Math.min(MAX_WAIT_SECONDS, gCurrentTest.interval + 1);
i'd say to increase both MAX_WAIT_SECONDS and the +1 by one.
(I saw your rs=me but wanted to be sure)
Comment on attachment 433370 [details] [diff] [review]
increase interval leeway
[Checkin: Comment 17]

i have absolutely no idea what leeway means, but sounds like a nice term. yep.
Attachment #433370 - Flags: review?(mak77) → review+
It looks like it's still happening:

http://tinderbox.mozilla.org/showlog.cgi?log=SeaMonkey/1269021409.1269023820.16742.gz
OS X 10.5 comm-central-trunk debug test xpcshell on 2010/03/19 10:56:49

http://tinderbox.mozilla.org/showlog.cgi?log=SeaMonkey/1269029402.1269031239.7618.gz
OS X 10.5 comm-central-trunk debug test xpcshell on 2010/03/19 13:10:02
Please rewrite the test to not use setTimeout at all, or back out bug 520165.  Tests that depend on timing are not acceptable even for features that involve timing.
(In reply to comment #19)
> Please rewrite the test to not use setTimeout at all, or back out bug 520165. 
> Tests that depend on timing are not acceptable even for features that involve
> timing.

no, to both question. And i think tests depending on timing are more than acceptable, more than people not writing tests. We just have to make them suck less. And i can think of hundreds paths that you can't test any other way, especially in the effort of moving things to async.

1. there is no way to detect if something HAS NOT run, if you know one just let me know, i'll be happy to implement it. The test has to ensure that something has run, how can i test it has not run if not checking if it has run after the expected time? if it does not run i can't clearly have a notification.

2. i'm not even sure why i should backout a change like that for a random failure of a test. i could probably backout 300 bugs based on number of random oranges. Is this the expected way to handle the problem?

It is even possible this failure is instead showing a real bug, investigating it
can require time as for everything other.
(In reply to comment #20)
> 1. there is no way to detect if something HAS NOT run, if you know one just let
> me know, i'll be happy to implement it. The test has to ensure that something
> has run, how can i test it has not run if not checking if it has run after the
> expected time? if it does not run i can't clearly have a notification.

How about doing the timeout (or switching to do_execute_soon) repeatedly and checking to see if it has happened. If the event never happens (a failure case) then the event will timeout. If the event happens, no matter how long it takes, then the test passes. Timers can be used so long as how long something takes to happen (within a reasonable margin) doesn't affect the outcome of the test.
the point is that "how long it takes" is somehow important, since the test is checking that the interval pref is used correctly. it is "check the event happens in the interval required".
I think i could just wait for the event to happen, and then check how much time has elapsed and see if it makes sense (having a large enough interval that does still ensure we are not using the default timeout, that iirc is 3 mins).
If we never receive the event the failure will be a timeout, this should never happen unless we regress so it should be fine. If we receive it too late, xpcshell tests will take a bit longer time (3 minutes as i said before) but we will see the failure due to "it took too long", and will know something has regressed.
i'll reimplement the test based on comment 22.
Assignee: nobody → mak77
It would be better if you removed wall time from the equation entirely, e.g. by using mock timers.  You'd be able to test the Places code more thoroughly without taking 3 seconds per test.
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1269977374.1269979658.15628.gz
OS X 10.5.2 mozilla-central debug test xpcshell on 2010/03/30 12:29:34
s: moz2-darwin9-slave02

TEST-UNEXPECTED-FAIL | /builds/slave/mozilla-central-macosx-debug-unittest-xpcshell/build/xpcshell/tests/test_places/expiration/test_pref_interval.js | test failed (with xpcshell return code: 0), see following log:
TEST-UNEXPECTED-FAIL | /builds/slave/mozilla-central-macosx-debug-unittest-xpcshell/build/xpcshell/tests/test_places/expiration/test_pref_interval.js | true == false - See following stack:
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1270008806.1270010170.4843.gz
OS X 10.5.2 mozilla-central debug test xpcshell on 2010/03/30 21:13:26
s: bm-xserve19

TEST-UNEXPECTED-FAIL | /builds/moz2_slave/mozilla-central-macosx-debug-unittest-xpcshell/build/xpcshell/tests/test_places/expiration/test_pref_interval.js | test failed (with xpcshell return code: 0), see following log:
TEST-UNEXPECTED-FAIL | /builds/moz2_slave/mozilla-central-macosx-debug-unittest-xpcshell/build/xpcshell/tests/test_places/expiration/test_pref_interval.js | true == false - See following stack:
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1270046875.1270048163.27961.gz
WINNT 5.2 mozilla-central opt test xpcshell on 2010/03/31 07:47:55
s: mw32-ix-slave16
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1270046785.1270047980.27100.gz
WINNT 5.2 mozilla-central opt test xpcshell on 2010/03/31 07:46:25
s: win32-slave02
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1270043784.1270046578.22444.gz
WINNT 5.2 mozilla-central debug test xpcshell on 2010/03/31 06:56:24
s: win32-slave02
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1270043767.1270046076.21149.gz
OS X 10.5.2 mozilla-central debug test xpcshell on 2010/03/31 06:56:07
s: moz2-darwin9-slave21
hm, looks like i could have misread this failure, we get a notification, but we should not get one, i thought it was the opposite, the failure is on last test.
I think the first test, that is setting time to 1s, could cause 2 expirations to start, and a next test could collect the second notification.
Attached patch patch v1.0 — — Splinter Review
Attachment #440070 - Flags: review?(sdwilsh)
Comment on attachment 440070 [details] [diff] [review]
patch v1.0

We may want to pull that code out and make a more generic mock object in our head files later on (we can effectively get rid of lazy add in tests this way I think).

r=sdwilsh for this for now though.
Attachment #440070 - Flags: review?(sdwilsh) → review+
Attachment #433370 - Attachment description: increase interval leeway → increase interval leeway [Checkin: Comment 17]
http://hg.mozilla.org/mozilla-central/rev/c384c6d82168
Target Milestone: --- → mozilla1.9.3a5
Status: NEW → RESOLVED
Closed: 10 years ago
Resolution: --- → FIXED
Flags: in-testsuite+
Whiteboard: [orange]
You need to log in before you can comment on or make changes to this bug.