Closed Bug 1145199 Opened 9 years ago Closed 9 years ago

Intermittent browser_referrer_open_link_in_private.js,browser_referrer_open_link_in_window.js | Test timed out

Categories

(Firefox :: General, defect)

x86_64
Windows 8
defect
Not set
normal

Tracking

()

RESOLVED FIXED
Firefox 41
Tracking Status
firefox39 --- wontfix
firefox40 --- fixed
firefox41 --- fixed
firefox-esr31 --- unaffected
firefox-esr38 --- unaffected

People

(Reporter: RyanVM, Assigned: franziskus)

References

Details

(Keywords: intermittent-failure)

Attachments

(2 files, 2 obsolete files)

Attached image test screenshot
Quite the interesting screenshot this one has :)

22:31:34 INFO - 711 INFO TEST-START | browser/base/content/test/referrer/browser_referrer_open_link_in_private.js
22:32:01 INFO - 1426743121217 Browser.Experiments.Experiments TRACE Experiments #0::enabled=true, true
22:32:01 INFO - 1426743121218 Browser.Experiments.Experiments TRACE Experiments #0::Registering instance with Addon Manager.
22:32:01 INFO - 1426743121218 Browser.Experiments.Experiments TRACE Experiments #0::Registering previous experiment add-on provider.
22:32:01 INFO - 1426743121219 Browser.Experiments.Experiments TRACE PreviousExperimentProvider #0::startup()
22:32:01 INFO - 1426743121219 Browser.Experiments.Experiments TRACE Experiments #0::_loadFromCache
22:32:01 INFO - 1426743121225 Browser.Experiments.Experiments TRACE Experiments #0::_loadTask finished ok
22:32:01 INFO - 1426743121226 Browser.Experiments.Experiments TRACE Experiments #0::_run
22:32:01 INFO - 1426743121226 Browser.Experiments.Experiments TRACE Experiments #0::_main iteration
22:32:01 INFO - 1426743121226 Browser.Experiments.Experiments TRACE Experiments #0::_evaluateExperiments
22:32:01 INFO - 1426743121228 Browser.Experiments.Experiments TRACE Experiments #0::_main finished, scheduling next run
22:35:19 INFO - TEST-INFO | screenshot: exit status 0
22:35:19 INFO - 712 INFO checking window state
22:35:19 INFO - 713 INFO Console message: [JavaScript Warning: "unsafe CPOW usage" {file: "resource:///modules/sessionstore/TabState.jsm" line: 96}]
22:35:19 INFO - 714 INFO Console message: [JavaScript Warning: "unsafe CPOW usage" {file: "resource:///modules/sessionstore/TabState.jsm" line: 96}]
22:35:19 INFO - 715 INFO Console message: [JavaScript Error: "NS_ERROR_FACTORY_EXISTS: Component returned failure code: 0xc1f30100 (NS_ERROR_FACTORY_EXISTS) [nsIComponentRegistrar.registerFactory]" {file: "resource://shumway/ShumwayBootstrapUtils.jsm" line: 71}]
22:35:19 INFO - 716 INFO browser_referrer_open_link_in_private: policy=[undefined] rel=[undefined] http:// -> http://
22:35:19 INFO - 717 INFO TEST-PASS | browser/base/content/test/referrer/browser_referrer_open_link_in_private.js | policy=[undefined] rel=[undefined] http:// -> http://
22:35:19 INFO - 718 INFO TEST-PASS | browser/base/content/test/referrer/browser_referrer_open_link_in_private.js | two tabs open
22:35:19 INFO - 719 INFO Console message: [JavaScript Warning: "unsafe CPOW usage" {file: "resource:///modules/sessionstore/TabState.jsm" line: 96}]
22:35:19 INFO - 720 INFO Console message: [JavaScript Warning: "unsafe CPOW usage" {file: "resource:///modules/sessionstore/TabState.jsm" line: 96}]
22:35:19 INFO - 721 INFO Console message: [JavaScript Warning: "unsafe CPOW usage" {file: "resource:///modules/sessionstore/TabState.jsm" line: 96}]
22:35:19 INFO - 722 INFO Console message: [JavaScript Warning: "unsafe CPOW usage" {file: "resource:///modules/sessionstore/TabState.jsm" line: 96}]
22:35:19 INFO - 723 INFO browser_referrer_open_link_in_private: policy=[undefined] rel=[undefined] https:// -> http://
22:35:19 INFO - 724 INFO TEST-PASS | browser/base/content/test/referrer/browser_referrer_open_link_in_private.js | policy=[undefined] rel=[undefined] https:// -> http://
22:35:19 INFO - 725 INFO TEST-PASS | browser/base/content/test/referrer/browser_referrer_open_link_in_private.js | two tabs open
22:35:19 INFO - 726 INFO Console message: [JavaScript Warning: "unsafe CPOW usage" {file: "resource:///modules/sessionstore/TabState.jsm" line: 96}]
22:35:19 INFO - 727 INFO Console message: [JavaScript Warning: "unsafe CPOW usage" {file: "resource:///modules/sessionstore/TabState.jsm" line: 96}]
22:35:19 INFO - 728 INFO Console message: [JavaScript Warning: "unsafe CPOW usage" {file: "resource:///modules/sessionstore/TabState.jsm" line: 96}]
22:35:19 INFO - 729 INFO Console message: [JavaScript Warning: "unsafe CPOW usage" {file: "resource:///modules/sessionstore/TabState.jsm" line: 96}]
22:35:19 INFO - 730 INFO browser_referrer_open_link_in_private: policy=[origin] rel=[undefined] https:// -> http://
22:35:19 INFO - 731 INFO TEST-PASS | browser/base/content/test/referrer/browser_referrer_open_link_in_private.js | policy=[origin] rel=[undefined] https:// -> http://
22:35:19 INFO - 732 INFO TEST-PASS | browser/base/content/test/referrer/browser_referrer_open_link_in_private.js | two tabs open
22:35:19 INFO - 733 INFO Console message: [JavaScript Warning: "unsafe CPOW usage" {file: "resource:///modules/sessionstore/TabState.jsm" line: 96}]
22:35:19 INFO - 734 INFO Console message: [JavaScript Warning: "unsafe CPOW usage" {file: "resource:///modules/sessionstore/TabState.jsm" line: 96}]
22:35:19 INFO - 735 INFO Console message: [JavaScript Warning: "unsafe CPOW usage" {file: "resource:///modules/sessionstore/TabState.jsm" line: 96}]
22:35:19 INFO - 736 INFO Console message: [JavaScript Warning: "unsafe CPOW usage" {file: "resource:///modules/sessionstore/TabState.jsm" line: 96}]
22:35:19 INFO - 737 INFO browser_referrer_open_link_in_private: policy=[origin] rel=[noreferrer] https:// -> http://
22:35:19 INFO - 738 INFO TEST-PASS | browser/base/content/test/referrer/browser_referrer_open_link_in_private.js | policy=[origin] rel=[noreferrer] https:// -> http://
22:35:19 INFO - 739 INFO TEST-PASS | browser/base/content/test/referrer/browser_referrer_open_link_in_private.js | two tabs open
22:35:19 INFO - 740 INFO Console message: [JavaScript Warning: "unsafe CPOW usage" {file: "resource:///modules/sessionstore/TabState.jsm" line: 96}]
22:35:19 INFO - 741 INFO Console message: [JavaScript Warning: "unsafe CPOW usage" {file: "resource:///modules/sessionstore/TabState.jsm" line: 96}]
22:35:19 INFO - 742 INFO Console message: [JavaScript Warning: "unsafe CPOW usage" {file: "resource:///modules/sessionstore/TabState.jsm" line: 96}]
22:35:19 INFO - 743 INFO Console message: [JavaScript Warning: "unsafe CPOW usage" {file: "resource:///modules/sessionstore/TabState.jsm" line: 96}]
22:35:19 INFO - 744 INFO browser_referrer_open_link_in_private: policy=[origin-when-crossorigin] rel=[undefined] https:// -> https://
22:35:19 INFO - 745 INFO TEST-PASS | browser/base/content/test/referrer/browser_referrer_open_link_in_private.js | policy=[origin-when-crossorigin] rel=[undefined] https:// -> https://
22:35:19 INFO - 746 INFO TEST-PASS | browser/base/content/test/referrer/browser_referrer_open_link_in_private.js | two tabs open
22:35:19 INFO - 747 INFO Console message: [JavaScript Warning: "unsafe CPOW usage" {file: "resource:///modules/sessionstore/TabState.jsm" line: 96}]
22:35:19 INFO - 748 INFO Console message: [JavaScript Warning: "unsafe CPOW usage" {file: "resource:///modules/sessionstore/TabState.jsm" line: 96}]
22:35:19 INFO - 749 INFO Console message: [JavaScript Warning: "unsafe CPOW usage" {file: "resource:///modules/sessionstore/TabState.jsm" line: 96}]
22:35:19 INFO - 750 INFO Console message: [JavaScript Warning: "unsafe CPOW usage" {file: "resource:///modules/sessionstore/TabState.jsm" line: 96}]
22:35:19 INFO - 751 INFO Console message: 1426743121217 Browser.Experiments.Experiments TRACE Experiments #0::enabled=true, true
22:35:19 INFO - 752 INFO Console message: 1426743121218 Browser.Experiments.Experiments TRACE Experiments #0::Registering instance with Addon Manager.
22:35:19 INFO - 753 INFO Console message: 1426743121218 Browser.Experiments.Experiments TRACE Experiments #0::Registering previous experiment add-on provider.
22:35:19 INFO - 754 INFO Console message: 1426743121219 Browser.Experiments.Experiments TRACE PreviousExperimentProvider #0::startup()
22:35:19 INFO - 755 INFO Console message: 1426743121219 Browser.Experiments.Experiments TRACE Experiments #0::_loadFromCache
22:35:19 INFO - 756 INFO Console message: 1426743121225 Browser.Experiments.Experiments TRACE Experiments #0::_loadTask finished ok
22:35:19 INFO - 757 INFO Console message: 1426743121226 Browser.Experiments.Experiments TRACE Experiments #0::_run
22:35:19 INFO - 758 INFO Console message: 1426743121226 Browser.Experiments.Experiments TRACE Experiments #0::_main iteration
22:35:19 INFO - 759 INFO Console message: 1426743121226 Browser.Experiments.Experiments TRACE Experiments #0::_evaluateExperiments
22:35:19 INFO - 760 INFO Console message: 1426743121228 Browser.Experiments.Experiments TRACE Experiments #0::_main finished, scheduling next run
22:35:19 INFO - 761 INFO Longer timeout required, waiting longer... Remaining timeouts: 4
22:35:19 INFO - 762 INFO Console message: 1426743151865 Toolkit.GMP WARN GMPInstallManager.parseResponseXML got node name: html, expected: updates
22:35:19 INFO - 763 INFO Console message: [JavaScript Error: "1426743151865 Toolkit.GMP ERROR GMPInstallManager.simpleCheckAndInstall Could not check for addons: {"target":{},"message":"got node name: html, expected: updates"}" {file: "resource://gre/modules/Log.jsm" line: 749}]
22:35:19 INFO - 764 INFO Console message: 1426743151986 Services.HealthReport.HealthReporter WARN Saved state file does not exist.
22:35:19 INFO - 765 INFO Console message: 1426743154863 Toolkit.GMP WARN GMPInstallManager.parseResponseXML got node name: html, expected: updates
22:35:19 INFO - 766 INFO Console message: [JavaScript Error: "1426743154864 Toolkit.GMP ERROR GMPInstallManager.simpleCheckAndInstall Could not check for addons: {"target":{},"message":"got node name: html, expected: updates"}" {file: "resource://gre/modules/Log.jsm" line: 749}]
22:35:19 INFO - 767 INFO Longer timeout required, waiting longer... Remaining timeouts: 3
22:35:19 INFO - 768 INFO Longer timeout required, waiting longer... Remaining timeouts: 2
22:35:19 INFO - 769 INFO Longer timeout required, waiting longer... Remaining timeouts: 1
22:35:19 INFO - 770 INFO TEST-UNEXPECTED-FAIL | browser/base/content/test/referrer/browser_referrer_open_link_in_private.js | Test timed out - expected PASS
22:35:19 INFO - 771 INFO MEMORY STAT vsize after test: 742486016
22:35:19 INFO - 772 INFO MEMORY STAT vsizeMaxContiguous after test: 8577624555520
22:35:19 INFO - 773 INFO MEMORY STAT residentFast after test: 134430720
22:35:19 INFO - 774 INFO MEMORY STAT heapAllocated after test: 64104376
22:35:19 INFO - 775 INFO TEST-OK | browser/base/content/test/referrer/browser_referrer_open_link_in_private.js | took 224868ms
Browser thinks it's offline?  May the wonders never cease!

Since it's unrelated to this particular test, it probably shouldn't block bug 1113431 (which I'm hoping to ship :-).

We're probably going to disable this test in e10s in bug 1144816 for a different reason, but that's totally coincidental, so they're not really duplicates.
Yeah, I'm not entirely convinced this wasn't just an infrastructure issue. Let's see if it happens more before panicking too much :)
(In reply to Ryan VanderMeulen [:RyanVM UTC-4] from comment #3)
> Yeah, I'm not entirely convinced this wasn't just an infrastructure issue.
> Let's see if it happens more before panicking too much :)

It does happen more, but it's still beyond my expertise to fix, I'm afraid.  This is all windows e10s, and all the screenshots say the browser is offline.  So, either the browser comes up without network connectivity, or the test framework is not waiting for it to realize that it is connected.  Either way, this seems beyond the scope of what the test itself should be dealing with.

Shall we disable the test on windows e10s?  Other suggestions?
@Daniel - looks like windows e10s sometimes thinks it's offline while running tests.  Is this a known issue?

Screenshot:

http://mozilla-releng-blobs.s3.amazonaws.com/blobs/mozilla-inbound/sha512/bc10819f3f5f34d145fa3eebead167186f7b196bdee6c2bf34550c564f36b987102b013d90e84699f278e4ae1eb6f4ef84445dc5a3e796949c33fb65be394cb8

Another possibility is that e10s occasionally freezes long enough for the offline detector to think it's offline.  It certainly did freeze for a minute or so on linux dbg, and for several minutes on mac.  But thought I'd check first if there's something windows-e10s-offline specific that you know of.
Flags: needinfo?(daniel)
This is not a known issue (to me).

Windows builds don't have 'network.manage-offline-status' set true by default so there should be nothing that sets the browser in offline mode due to the network situation. The online/offline-detection works the exact same way e10s or not.

nsIOService does however start off in offline mode and sets itself "online" when ->Init() is called which thus begs the question of there's possibly a race?
Flags: needinfo?(daniel)
Summary: Intermittent browser_referrer_open_link_in_private.js | Test timed out → Intermittent browser_referrer_open_link_in_private.js,browser_referrer_open_link_in_window.js | Test timed out
This fails a lot, should we disable the test or is anyone going to poke at it in the near future?
Assignee: nobody → franziskuskiefer
(In reply to Ryan VanderMeulen [:RyanVM UTC-4] from comment #3)
> Yeah, I'm not entirely convinced this wasn't just an infrastructure issue.
> Let's see if it happens more before panicking too much :)

So, it seems this one fails quite often :-( We have Franziskus who is willing to take on the work to get this problem resolved, but at the moment we don't know where to get started. Any ideas what we could try?
Flags: needinfo?(ryanvm)
(In reply to Christoph Kerschbaumer [:ckerschb] from comment #443)
> So, it seems this one fails quite often :-( We have Franziskus who is
> willing to take on the work to get this problem resolved, but at the moment
> we don't know where to get started. Any ideas what we could try?

Sorry for the delay in getting back to you. I was out of the office for most of last week and am still getting back up to speed.

Anyway, there's a few approaches you can Try (based on what I've seen other devs do):
* Try adding logging to the test to figure out where things are going wrong. For a test that's failing as often as this is, it would hopefully work well. You can do it with a Try push or an actual in-tree push.
* Get a loaner slave and try to reproduce the failures and debug there. (https://wiki.mozilla.org/ReleaseEngineering/How_To/Request_a_slave)

Also, you might take a look at the MDN page for test writing to see if anything there stands out for how these tests are written:
https://developer.mozilla.org/en-US/docs/Mozilla/QA/Avoiding_intermittent_oranges

Hope that helps.
Flags: needinfo?(ryanvm)
Christoph, it doesn't look like bug 1161221 helped here. :-(
Flags: needinfo?(mozilla)
(In reply to :Gijs Kruitbosch from comment #538)
> Christoph, it doesn't look like bug 1161221 helped here. :-(

Bug 1161221 was mainly to enable tests on more platforms to get more coverage. Franziskus is still investigating on how we can resolve this intermittents. If you have any suggestions how to go about this, please let us know. At the moment we are following suggestion from Comment 485.
Flags: needinfo?(mozilla)
Flags: needinfo?(gijskruitbosch+bugs)
S(In reply to Christoph Kerschbaumer [:ckerschb] from comment #539)
> (In reply to :Gijs Kruitbosch from comment #538)
> > Christoph, it doesn't look like bug 1161221 helped here. :-(
> 
> Bug 1161221 was mainly to enable tests on more platforms to get more
> coverage. Franziskus is still investigating on how we can resolve this
> intermittents. If you have any suggestions how to go about this, please let
> us know. At the moment we are following suggestion from Comment 485.

From looking at some of the build screenshots it looks like the context menu isn't opening / staying up. From looking at the code, I have two suggestions:

1) make the test wait for the new window actually being closed (move promiseWindowWillBeClosed from ../general/head.js to BrowserTestUtils and use that, and .then() chain the starting of the next test)
2) make the test either retry opening the context menu if it detects it being hidden (ie also add a hide listener, and just redo the thing you did to trigger it), and/or check if the tests can't be made to work while the context menu is closed. I'm not sure doCommand really depends on the menu being visible.
Flags: needinfo?(gijskruitbosch+bugs)
this should significantly reduce the number of intermittent test failures

https://treeherder.mozilla.org/#/jobs?repo=try&revision=a8696a284b5a
Attachment #8616753 - Flags: review?(gijskruitbosch+bugs)
Comment on attachment 8616753 [details] [diff] [review]
reducing intermittent test failures (r=gijs)

Review of attachment 8616753 [details] [diff] [review]:
-----------------------------------------------------------------

Did the dump in the try push actually ever fire?

(clearing r? because of the issues below)

::: browser/base/content/test/referrer/head.js
@@ +224,5 @@
>    return new Promise(function(resolve) {
>      aWindow.document.addEventListener("popupshown",
>                                        function handleMenu(aEvent) {
>        aWindow.document.removeEventListener("popupshown", handleMenu, false);
> +      aWindow.document.removeEventListener("popuphiding", handleMenu, false);

This removeEventListener call clearly doesn't do the right thing. Use a different name for the hiding callback.

@@ +230,4 @@
>        resolve(aEvent.target);
>      }, false);
>  
> +    aWindow.document.addEventListener("popuphiding",

Shouldn't this be "popuphidden", also so that the clicking actually works and doesn't hit the context menu which might still be up while popuphiding is being called?
Attachment #8616753 - Flags: review?(gijskruitbosch+bugs)
Seems progress has stalled here. I think it's time to disable the test.
Flags: needinfo?(franziskuskiefer)
We started working on it again, should have updates soon.
Flags: needinfo?(franziskuskiefer) → needinfo?(birunthan)
(In reply to Franziskus Kiefer [:fkiefer or :franziskus] from comment #719)
> We started working on it again, should have updates soon.

Ryan, I just chatted with Franziskus, he is going to try yet another approach (maybe even to rewrite the test). If the intermittents become to annoying I am all for disabling the tests for now and we can re-enable them once we have found a solution. If you want, we can provide the patch to disable them.
Flags: needinfo?(ryanvm)
That sounds good to me. It's trivial enough to revert for Try pushes. Thanks.
Flags: needinfo?(ryanvm)
Attached patch disabling failing tests for now (obsolete) — Splinter Review
disabling both tests on all platforms for now
Attachment #8616753 - Attachment is obsolete: true
Flags: needinfo?(birunthan)
Attachment #8624473 - Flags: review?(ryanvm)
(In reply to Franziskus Kiefer [:fkiefer or :franziskus] from comment #724)
> Created attachment 8624473 [details] [diff] [review]
> disabling failing tests for now
> 
> disabling both tests on all platforms for now

Personally, considering the failures over the last months, I would prefer to just skip-if these on linux only (don't see any failures on Mac, and the only recent handful of failures on Windows were in the middle_click test) but I'll leave the decision to Ryan.
Comment on attachment 8624473 [details] [diff] [review]
disabling failing tests for now

Review of attachment 8624473 [details] [diff] [review]:
-----------------------------------------------------------------

Yeah, looks like all the recent failures have been on Linux. Let's go with |skip-if = os == 'linux' # Bug 1145199|
Attachment #8624473 - Flags: review?(ryanvm) → review-
Attachment #8624473 - Attachment is obsolete: true
Attachment #8624748 - Flags: review?(ryanvm)
Attachment #8624748 - Flags: review?(ryanvm) → review+
Keywords: checkin-needed
Depends on: 1176281
https://hg.mozilla.org/mozilla-central/rev/9c8c8fb58f87
Status: NEW → RESOLVED
Closed: 9 years ago
Resolution: --- → FIXED
Target Milestone: --- → Firefox 41
You need to log in before you can comment on or make changes to this bug.