474081 - Sporadic failures in browser_bug321000.js

Status: VERIFIED FIXED

(Firefox :: Search, defect)

Description

[Daniel Holbert [:dholbert]]

The "Linux mozilla-1.9.1 unit test" tinderbox just failed this test:

TEST-UNEXPECTED-FAIL | chrome://mochikit/content/browser/browser/base/content/test/browser_bug321000.js | urlbar strips newlines and surrounding whitespace - Got , expected   hello helloworldworld
TEST-UNEXPECTED-FAIL | chrome://mochikit/content/browser/browser/base/content/test/browser_bug321000.js | searchbar replaces newlines with spaces - Got , expected   hello hello     world world

I tend to think this is sporadic, because the previous cycle used the exact same code revision ( http://hg.mozilla.org/releases/mozilla-1.9.1/rev/d9ff78dd3b4b ) and it passed these tests.

Log for failing cycle:
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox3.1/1232145380.1232150430.2394.gz

Log for previous passing cycle:
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox3.1/1232135621.1232141350.15538.gz

Comment 1

[Marco Bonardo [:mak]]

Attachment: patch v1.0 [Checkin: Comment 5 & 6]

This test was constantly failing on my windows vm, with this patch it is always successful instead.

Comment 2

[Dão Gottwald [:dao]]

Is the reason for the sporadic failure known? Maybe it's exposing a bug that should be fixed instead or at least be filed separately?

Comment 3

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

Pasting is async in this case because the Ctrl+V codepath ends up going through DocumentViewerImpl::FireClipboardEvent[1], which just fires an event. I suppose we could avoid the need for these listeners if we called nsIEditor::paste() directly, since it appears to synchronously insert the text.

[1] http://mxr.mozilla.org/mozilla-central/source/layout/base/nsDocumentViewer.cpp#2455

Comment 4

[Marco Bonardo [:mak]]

on IRC Gavin pointed out that using CTRL + V is testing more than simply using Paste on nsIEditor, so the patch is fine as it is.

Comment 5

[Marco Bonardo [:mak]]

http://hg.mozilla.org/mozilla-central/rev/7d6fa381e380

Comment 6

[Marco Bonardo [:mak]]

http://hg.mozilla.org/releases/mozilla-1.9.1/rev/2a7ac14bcb6e

Comment 7

[(not currently active) Ted Mielczarek]

TEST-UNEXPECTED-FAIL | chrome://mochikit/content/browser/browser/base/content/test/browser_bug321000.js | Timed out

From http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1232711766.1232717461.3319.gz

:-/

Comment 8

[Marco Bonardo [:mak]]

mh, how can that timeout, we don't receive input event?

Comment 9

[Marco Bonardo [:mak]]

btw reopening :(
there must be an issue in setting the focus to the urlbar or pasting or firing the oninput event.

Comment 10

[Marco Bonardo [:mak]]

locally when that happens the clipboard is correctly set, the locationbar has focus (cursor blinking), but the syntesizeKey event does not happen, if i ctrl+V manually the test finishes correctly.

Comment 11

[Marco Bonardo [:mak]]

looks like copyString is async, probably handled async by the OS, so it could happen that when we paste the clipboard has not yet been set. Indeed trying to getData from the clipboard immediately after setting it fails and success randomly.

Comment 12

[Marco Bonardo [:mak]]

Attachment: poll clipboard v1.0

as discussed on irc, this patch adds polling the clipboard, i put a limit of 5s that should be enough always (if that's not enough, we probably have some issue on clipboard implementation!)

Comment 13

[Dão Gottwald [:dao]]

I wonder why test_bug253481.xul doesn't have this problem...

Comment 14

[Marco Bonardo [:mak]]

heh, this is interesting enough, that test fails on my VM! while it works if use a setTimeout before checking results!

Comment 15

[Marco Bonardo [:mak]]

hwv could make sense take the polling patch on trunk and see if failures stop. if that's true we can fix that test too, to avoid possible future randomness.
Would be interesting to know the order in which tests run, would it be possible that the clipboard is never cleared so when we set in the browser test, the same string in clipboard is then used in that test?
Ideally they should clear the clipboard content or use different strings.

Comment 16

[Dão Gottwald [:dao]]

(In reply to comment #15)
> Would be interesting to know the order in which tests run, would it be possible
> that the clipboard is never cleared so when we set in the browser test, the
> same string in clipboard is then used in that test?

That's an interesting theory. The tests are using slightly different strings, but I don't think the new lines at the beginning and at the end make a real difference for test_bug253481.xul. The tests should probably use unique strings, or clear the clipboard afterwards, or do both.

Comment 17

[Daniel Holbert [:dholbert]]

Another timeout today:
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox3.1/1233096716.1233100133.5685.gz
Linux mozilla-1.9.1 unit test on 2009/01/27 14:51:56

Comment 18

[Daniel Holbert [:dholbert]]

And another...
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox3.1/1233129221.1233134130.28322.gz
Linux mozilla-1.9.1 unit test on 2009/01/27 23:53:41

Removing "fixed1.9.1" keyword, as this is apparently still broken on 1.9.1 tinderboxen.

Comment 19

[Marco Bonardo [:mak]]

Attachment: poll clipboard v1.1 [Checkin: Comment 20]

set the clipboard to an empty string before exiting, so we can check if other tests are depending on this.

Comment 20

[Marco Bonardo [:mak]]

http://hg.mozilla.org/mozilla-central/rev/49c138f3b421
let bake this on trunk for some day, to see if the randomness has gone.

Comment 21

[Jesse Ruderman]

This test timed out today:

http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1234333287.1234337680.5516.gz#err13

(also noted in bug 473680 comment 19)

Comment 22

[Marco Bonardo [:mak]]

the timeout now looks like other not explainable timeouts, especially on Linux, it's not timing out where we expect it could... rather on startup, as if setTimeout would be never executed.

Comment 23

[Serge Gautherie (:sgautherie)]

(In reply to comment #22)

Confirmed (still there):

http://tinderbox.mozilla.org/showlog.cgi?log=Firefox3.1/1235198229.1235205701.20963.gz
Linux mozilla-1.9.1 unit test on 2009/02/20 22:37:09
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox3.1/1235206781.1235212335.3260.gz
Linux mozilla-1.9.1 unit test on 2009/02/21 00:59:41
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox3.1/1235221181.1235225547.3968.gz
Linux mozilla-1.9.1 unit test on 2009/02/21 04:59:41
{
chrome://mochikit/content/browser/browser/base/content/test/browser_bug321000.js
TEST-UNEXPECTED-FAIL | chrome://mochikit/content/browser/browser/base/content/test/browser_bug321000.js | Timed out
}

Comment 24

[Serge Gautherie (:sgautherie)]

Still there on trunk too:
{
chrome://mochikit/content/browser/browser/base/content/test/browser_bug321000.js
NEXT ERROR TEST-UNEXPECTED-FAIL | chrome://mochikit/content/browser/browser/base/content/test/browser_bug321000.js | Timed out
}

Comment 25

[Marco Bonardo [:mak]]

Attachment: temporary disable the test

Comment 26

[Marco Bonardo [:mak]]

Attachment: disable as comment only [Checkin: Comment 29 & 38]

Comment 27

[Johnathan Nightingale [:johnath]]

Comment on attachment 365182 [details] [diff] [review]
disable as comment only
[Checkin: Comment 29 & 38]

thanks.  I'm not a module peer, of course, but this looks safe, and removing an intermittent orange is winning.

Comment 28

[Serge Gautherie (:sgautherie)]

Comment on attachment 365182 [details] [diff] [review]
disable as comment only
[Checkin: Comment 29 & 38]

>+_BROWSER_FILES = browser_sanitize-timespans.js \

+_BROWSER_FILES = \
                  browser_sanitize-timespans.js \

Please...

Comment 29

[Marco Bonardo [:mak]]

sorry Serge, was pushed just minutes before your comment :\
http://hg.mozilla.org/mozilla-central/rev/b0738a6a17fa

Comment 30

[Serge Gautherie (:sgautherie)]

(In reply to comment #29)
> sorry Serge

When reactivating the test, then.

Comment 31

[Marco Bonardo [:mak]]

the "Timed out" we were seeing in failures, could have been a real exception instead, and the same for many other tests we were seeing "Timed out".

Try running this browser-chrome test, the throw is never catched nor dumped anywhere, and we only end up seeing a "Timed out" in the error log.
So the timeout is hiding the real failure, that could be an API throwing or anything other throwing.

function test() {
  waitForExplicitFinish();

  function finish_test() {
    throw("test");
    finish(); 
  }

  setTimeout(finish_test,1);
}

Comment 32

[Mike Beltzner [:beltzner, not reading bugmail]]

This happened on the 191 branch as well:

http://tinderbox.mozilla.org/showlog.cgi?log=Firefox3.1/1236138732.1236144606.30522.gz&fulltext=1

should we disable the test on that branch, too?

Comment 33

[Marco Bonardo [:mak]]

sure, we can disable the test on 3.1 too, will do when the tree reopens.

Then i'd like to enable a new version of it for a test on trunk, adding some try catch, to evaluate comment 31.

Comment 34

[(not currently active) Ted Mielczarek]

That's interesting. The exceptions just get swallowed? Do they get reported to the error console? I know Mossop was interested in making the harness fail if there were errors logged to the error console.

Comment 35

[Marco Bonardo [:mak]]

the error console reports: "Error: uncaught exception: test".
maybe there's no need to fail for every error (since i see a lot of other errors in the console from other tests), but failing for uncaught exceptions and reporting them in the log looks like something wanted.

Comment 36

[Marco Bonardo [:mak]]

i've filed bug 481406 to investigate if we can report console errors as real errors.

Comment 37

[Mike Beltzner [:beltzner, not reading bugmail]]

Happened again on mozilla-1.9.1:

http://tinderbox.mozilla.org/showlog.cgi?log=Firefox3.1/1236435465.1236439345.8158.gz

Can we get that disable-this-test thing landed on branch as well?

Comment 38

[Dão Gottwald [:dao]]

http://hg.mozilla.org/releases/mozilla-1.9.1/rev/e212796b220f

Comment 39

[Serge Gautherie (:sgautherie)]

Now that bug 481406 is fixed, shall this test be re-enabled on trunk to see what the current situation/log is?

Comment 40

[Marco Bonardo [:mak]]

sure, i'll provide an updated patch for that.

Comment 41

[Marco Bonardo [:mak]]

Attachment: patch v2.0

re-enable test, i cleaned it up a bit so it should be easier to maintain, and added some logging.
With the new harness behavior could be easier to catch where we fail.

Comment 42

[Dão Gottwald [:dao]]

Comment on attachment 387629 [details] [diff] [review]
patch v2.0

>+  { desc: "Urlbar strips newlines and surrounding whitespace"
>+  , element: document.getElementById('urlbar')

gURLBar? Also, comma at the beginning of the line looks strange.

>+var gListener = {
>+  test: null,
>   handleEvent: function(event) {
>+    if (event.type != "input")
>+      return;
>+

That listener isn't added for other events, right? So if handleEvent gets called for other events, that would be a bug. I'd remove the event.type check and rename gListener to gInputListener.

Comment 43

[Marco Bonardo [:mak]]

(In reply to comment #42)
> comma at the beginning of the line looks strange.

it's just to avoid polluting blame when adding new properties in future

Comment 44

[Marco Bonardo [:mak]]

Attachment: patch v2.1

while renaming listener i noticed there's no more need to have it global, so i've moved it inside test_paste, so the only remaining global var is gTests.

Comment 45

[Dão Gottwald [:dao]]

I'd rather optimize for readability. Blame isn't all that interesting here.

Comment 46

[Marco Bonardo [:mak]]

Attachment: patch v2.2 [Checkin: Comment 47]

not a big deal, moving commas around, ready to push.

Comment 47

[Marco Bonardo [:mak]]

http://hg.mozilla.org/mozilla-central/rev/d26cb9a07f91

i'm resolving bug, the first one seeing a failure on m-c should reopen this.

Comment 48

[Marco Bonardo [:mak]]

Attachment: sync test on 1.9.1 [Checkin: Comment 49]

Comment 49

[Marco Bonardo [:mak]]

http://hg.mozilla.org/releases/mozilla-1.9.1/rev/8c85fa67e527

Comment 50

[(no longer active)]

fixed1.9.1 is for the bug fixes which got in for 1.9.1 release, AFAIK.  status1.9.1.3-fixed should be enough here.

Comment 51

[Henrik Skupin [:whimboo][⌚️UTC+2] (away 10/03 - 10/13)]

No orangeness since 3 weeks on 1.9.1 and 1.9.2. Lets call it verified fixed.

Comment 52

[Legacy TBPL/Treeherder Robot]

joshmoz%gmail.com
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1284620669.1284621999.3002.gz
Rev3 Fedora 12 mozilla-central opt test mochitest-other on 2010/09/16 00:04:29

s: talos-r3-fed-038
TEST-UNEXPECTED-FAIL | chrome://mochikit/content/browser/browser/base/content/test/browser_bug304198.js | Test timed out
TEST-UNEXPECTED-FAIL | chrome://mochikit/content/browser/browser/base/content/test/browser_bug304198.js | Found a tab after previous test timed out: http://example.org/browser/browser/base/content/test/dummy_page.html
TEST-UNEXPECTED-FAIL | chrome://mochikit/content/browser/browser/base/content/test/browser_bug304198.js | Found a tab after previous test timed out: http://example.org/browser/browser/base/content/test/dummy_page.html
TEST-UNEXPECTED-FAIL | chrome://mochikit/content/browser/browser/base/content/test/browser_bug304198.js | Found a tab after previous test timed out: http://example.org/browser/browser/base/content/test/dummy_page.html
TEST-UNEXPECTED-FAIL | chrome://mochikit/content/browser/browser/base/content/test/browser_bug321000.js | Test timed out
TEST-UNEXPECTED-FAIL | chrome://mochikit/content/browser/browser/base/content/test/browser_bug321000.js | Urlbar strips newlines and surrounding whitespace - Got mozilla.org, expected   hello helloworldworld

Comment 53

[Legacy TBPL/Treeherder Robot]

joshmoz%gmail.com
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1284621860.1284623136.8541.gz
Rev3 Fedora 12 mozilla-central opt test mochitest-other on 2010/09/16 00:24:20

s: talos-r3-fed-007
TEST-UNEXPECTED-FAIL | chrome://mochikit/content/browser/browser/base/content/test/browser_bug304198.js | Test timed out
TEST-UNEXPECTED-FAIL | chrome://mochikit/content/browser/browser/base/content/test/browser_bug304198.js | Found a tab after previous test timed out: http://example.org/browser/browser/base/content/test/dummy_page.html
TEST-UNEXPECTED-FAIL | chrome://mochikit/content/browser/browser/base/content/test/browser_bug304198.js | Found a tab after previous test timed out: http://example.org/browser/browser/base/content/test/dummy_page.html
TEST-UNEXPECTED-FAIL | chrome://mochikit/content/browser/browser/base/content/test/browser_bug304198.js | Found a tab after previous test timed out: http://example.org/browser/browser/base/content/test/dummy_page.html
TEST-UNEXPECTED-FAIL | chrome://mochikit/content/browser/browser/base/content/test/browser_bug321000.js | Test timed out
TEST-UNEXPECTED-FAIL | chrome://mochikit/content/browser/browser/base/content/test/browser_bug321000.js | Urlbar strips newlines and surrounding whitespace - Got mozilla.org, expected   hello helloworldworld

Comment 54

[Legacy TBPL/Treeherder Robot]

joshmoz%gmail.com
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1284623001.1284623985.12382.gz
Rev3 Fedora 12x64 mozilla-central opt test mochitest-other on 2010/09/16 00:43:21

s: talos-r3-fed64-003
TEST-UNEXPECTED-FAIL | chrome://mochikit/content/browser/browser/base/content/test/browser_bug304198.js | Test timed out
TEST-UNEXPECTED-FAIL | chrome://mochikit/content/browser/browser/base/content/test/browser_bug304198.js | Found a tab after previous test timed out: http://example.org/browser/browser/base/content/test/dummy_page.html
TEST-UNEXPECTED-FAIL | chrome://mochikit/content/browser/browser/base/content/test/browser_bug304198.js | Found a tab after previous test timed out: http://example.org/browser/browser/base/content/test/dummy_page.html
TEST-UNEXPECTED-FAIL | chrome://mochikit/content/browser/browser/base/content/test/browser_bug304198.js | Found a tab after previous test timed out: http://example.org/browser/browser/base/content/test/dummy_page.html
TEST-UNEXPECTED-FAIL | chrome://mochikit/content/browser/browser/base/content/test/browser_bug321000.js | Test timed out
TEST-UNEXPECTED-FAIL | chrome://mochikit/content/browser/browser/base/content/test/browser_bug321000.js | Urlbar strips newlines and surrounding whitespace - Got mozilla.org, expected   hello helloworldworld

Comment 55

[Legacy TBPL/Treeherder Robot]

autonome%gmail.com
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1284625540.1284626437.24354.gz
Rev3 Fedora 12x64 mozilla-central opt test mochitest-other on 2010/09/16 01:25:40

s: talos-r3-fed64-041
TEST-UNEXPECTED-FAIL | chrome://mochikit/content/browser/browser/base/content/test/browser_bug304198.js | Test timed out
TEST-UNEXPECTED-FAIL | chrome://mochikit/content/browser/browser/base/content/test/browser_bug304198.js | Found a tab after previous test timed out: http://example.org/browser/browser/base/content/test/dummy_page.html
TEST-UNEXPECTED-FAIL | chrome://mochikit/content/browser/browser/base/content/test/browser_bug304198.js | Found a tab after previous test timed out: http://example.org/browser/browser/base/content/test/dummy_page.html
TEST-UNEXPECTED-FAIL | chrome://mochikit/content/browser/browser/base/content/test/browser_bug304198.js | Found a tab after previous test timed out: http://example.org/browser/browser/base/content/test/dummy_page.html
TEST-UNEXPECTED-FAIL | chrome://mochikit/content/browser/browser/base/content/test/browser_bug321000.js | Test timed out
TEST-UNEXPECTED-FAIL | chrome://mochikit/content/browser/browser/base/content/test/browser_bug321000.js | Urlbar strips newlines and surrounding whitespace - Got mozilla.org, expected   hello helloworldworld

Comment 56

[Legacy TBPL/Treeherder Robot]

autonome%gmail.com
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1284622758.1284625658.20677.gz
Rev3 Fedora 12 mozilla-central debug test mochitest-other on 2010/09/16 00:39:18

s: talos-r3-fed-036
TEST-UNEXPECTED-FAIL | chrome://mochikit/content/browser/browser/base/content/test/browser_bug304198.js | Test timed out
TEST-UNEXPECTED-FAIL | chrome://mochikit/content/browser/browser/base/content/test/browser_bug304198.js | Found a tab after previous test timed out: http://example.org/browser/browser/base/content/test/dummy_page.html
TEST-UNEXPECTED-FAIL | chrome://mochikit/content/browser/browser/base/content/test/browser_bug304198.js | Found a tab after previous test timed out: http://example.org/browser/browser/base/content/test/dummy_page.html
TEST-UNEXPECTED-FAIL | chrome://mochikit/content/browser/browser/base/content/test/browser_bug304198.js | Found a tab after previous test timed out: http://example.org/browser/browser/base/content/test/dummy_page.html
TEST-UNEXPECTED-FAIL | chrome://mochikit/content/browser/browser/base/content/test/browser_bug321000.js | Test timed out
TEST-UNEXPECTED-FAIL | chrome://mochikit/content/browser/browser/base/content/test/browser_bug321000.js | Urlbar strips newlines and surrounding whitespace - Got mozilla.org, expected   hello helloworldworld

Comment 57

[Dão Gottwald [:dao]]

Please ignore comment 52 and below.

Comment 58

[Marco Bonardo [:mak]]

on the other side, reporting an orange in a bug verified fixed more than 1 year ago is arguably wrong, they should have opened a new bug.