990303 - SimpleTest buffered logging is broken since we don't clear the buffered messages in time

Status: NEW

(Testing :: Mochitest, defect)

Description

[(no longer active)]

We have this code <http://mxr.mozilla.org/mozilla-central/source/testing/mochitest/tests/SimpleTest/SimpleTest.js#1088> which pretends that it's emptying out the buffer when the SimpleTest object is reset.  However, that reset() function doesn't do what its name suggests, and it only does what the comment on top of it suggest ;-) <http://mxr.mozilla.org/mozilla-central/source/testing/mochitest/browser-test.js#497>

IOW, reset() is only used in browser-chrome and nowhere else.

Now the problem here is I landed this broken patch: <https://hg.mozilla.org/integration/mozilla-inbound/rev/352a2109c6e6#l5.97> (note that I am not actually removing that observer because the event I'm observing should never fire) and I got this in the log <https://tbpl.mozilla.org/php/getParsedLog.php?id=37027922&tree=Mozilla-Inbound&full=1#error0>:

15:21:15     INFO -  1928 INFO TEST-START | chrome://mochitests/content/chrome/extensions/cookie/test/test_app_uninstall_cookies.html
15:21:15     INFO -  ++DOMWINDOW == 60 (0x13ceae170) [pid = 963] [serial = 2401] [outer = 0x12decdee0]
15:21:15     INFO -  -*- Webapps.jsm : confirmInstall
15:21:15     INFO -  -*- Webapps.jsm : _writeManifestFile
15:21:15     INFO -  -*- Webapps.jsm : Saving /var/folders/gA/gAn+Yau+GbO+DizThjqg-U+++-k/-Tmp-/tmp1BadsF/webapps/{a2ddbcd9-099e-544b-bc14-ef6e07427a71}/manifest.webapp
15:21:15     INFO -  -*- Webapps.jsm : app.origin: http://www.example.com
15:21:15     INFO -  -*- Webapps.jsm : Saving /var/folders/gA/gAn+Yau+GbO+DizThjqg-U+++-k/-Tmp-/tmp1BadsF/webapps/webapps.json
15:21:15     INFO -  -*- Webapps.jsm : updateAppHandlers: old=null new=[object Object]
15:21:15     INFO -  -*- Webapps.jsm : Saving /var/folders/gA/gAn+Yau+GbO+DizThjqg-U+++-k/-Tmp-/tmp1BadsF/webapps/webapps.json
15:21:15     INFO -  1929 INFO TEST-INFO | dumping last 2 message(s)
15:21:15     INFO -  1930 INFO TEST-INFO | if you need more context, please use SimpleTest.requestCompleteLog() in your test
15:21:15     INFO -  1931 INFO TEST-PASS | chrome://mochitests/content/chrome/dom/tests/mochitest/beacon/test_beaconCookies.html | cookie set by beacon request in normal window
15:21:15     INFO -  1932 INFO TEST-PASS | chrome://mochitests/content/chrome/dom/tests/mochitest/beacon/test_beaconCookies.html | private cookie set by beacon request in private window
15:21:15     INFO -  1933 INFO TEST-UNEXPECTED-FAIL | chrome://mochitests/content/chrome/extensions/cookie/test/test_app_uninstall_cookies.html | cookie set by beacon request in private window
15:21:15     INFO -  1934 INFO TEST-UNEXPECTED-FAIL | chrome://mochitests/content/chrome/extensions/cookie/test/test_app_uninstall_cookies.html | [SimpleTest.finish()] this test already called finish!


Note the first two lines of buffered messages there?  Here's what's going on, copied from irc:

ehsan
jdm: ok I see what's going on now
ehsan
jdm: so we're keeping the window of the beacon test alive
ehsan
jdm: alongside everything in it
ehsan
including the SimpleTest object!
ehsan
then we get a call on the outstanding observer
jdm
and it does getcurrenttesturl?
ehsan
which calls SimpleTest.ok(false,...)
ehsan
which gets us here: http://mxr.mozilla.org/mozilla-central/source/testing/mochitest/tests/SimpleTest/SimpleTest.js#389
ehsan
where we look and see we have a couple of buffered messsages in *that* SimpleTest object
ehsan
with the correct url
ehsan
so we output them
ehsan
and then we'll try to output the error message we just generated
19:54 ehsan
which has the wrong url

We should clear the buffered messages when the test is finished too.

Comment 1

[Nathan Froyd [:froydnj]]

Huh.  I thought I took care of this someplace else.