886719 - Failure 'about:blank page has been unloaded' and 'controller.waitForPageLoad(): Timeout waiting for page loaded.' in testStopReloadButtons.js::testStopAndReload

Status: RESOLVED INVALID

(Mozilla QA Graveyard :: Mozmill Tests, defect, P2)

Description

[Andrei Eftimie]

We've seen this fail a few (8) times during the last couple of months.
The 2 failures 'about:blank page has been unloaded' and 'controller.waitForPageLoad(): Timeout waiting for page loaded.' have a high chance of being related.

Cross referencing bug 826693 which tracks most waitForPageLoad() failures.

Logged this separately since the unload event on about:blank should be triggered before the next onload event might fail.

Failed on Windows and OSX

Comment 1

[Andrei Eftimie]

'about:blank page has been unloaded' last failure in May.
'controller.waitForPageLoad(): Timeout waiting for page loaded.' last failure in this test about 1 month ago.

Comment 2

[Cosmin Malutan, [:cosmin-malutan]]

Happened again on Mac 10.6.8 (x86_64) with Nightly en-US
http://mozmill-daily.blargon7.com/#/functional/report/fb97b6210ae70da1b9ace67445bfdfc5

Comment 3

[Andrei Eftimie]

The mentioned failure is on 25.0 (Aurora)

Comment 4

[Andrei Eftimie]

Another failure on Aurora, Windows, en-US:
http://mozmill-daily.blargon7.com/#/remote/report/1039ea48a9d69a5a1cc4fd228cb9fecb

Comment 5

[Henrik Skupin [:whimboo][⌚️UTC+1] (away from Feb 12th - Feb 22nd)]

Lets see if mozmill 2.0 with its improved page load handling will solve it.

Comment 6

[Andrei Eftimie]

Updating status for 27 (de, Linux):
http://mozmill-daily.blargon7.com/#/remote/report/837c1e0f361ac93453ee69721970b270

Comment 7

[Andrei Eftimie]

I've seen this a lot today locally.
Doesn't seem to fail in our CI system.

Only fails when I do a full testrun, running the test individually doesn't reproduce the issue.
I do have some weird messages in the log a few tests before this one (not sure if related):
> TEST-START | testSecurity/testSafeBrowsingNotificationBar.js | setupModule
> TEST-START | testSecurity/testSafeBrowsingNotificationBar.js | testNotificationBar
> 1407498882027 GMPInstallManager.simpleCheckAndInstall INFO  Last check was: 1407498882 seconds ago, minimum seconds: 86400
> 1407498882028 GMPInstallManager._getURL INFO  Using url: https://aus4.mozilla.org/update/3/GMP/%VERSION%/%BUILD_ID%/%BUILD_TARGET%/%LOCALE%/%CHANNEL%/%OS_VERSION%/%DISTRIBUTION%/%DISTRIBUTION_VERSION%/update.xml
> 1407498882028 GMPInstallManager._getURL INFO  Using url (with replacement): https://aus4.mozilla.org/update/3/GMP/34.0a1/20140807084340/Darwin_x86_64-gcc3-u-i386-x86_64/en-US/nightly/Darwin%2013.3.0/default/default/update.xml
> 1407498882030 GMPInstallManager.checkForAddons  INFO  sending request to: https://aus4.mozilla.org/update/3/GMP/34.0a1/20140807084340/Darwin_x86_64-gcc3-u-i386-x86_64/en-US/nightly/Darwin%2013.3.0/default/default/update.xml
> 1407498883732 GMPInstallManager.onLoadXML INFO  request completed downloading document
> 1407498883732 GMPInstallManager.onLoadXML INFO  allowNonBuiltIn: false
> 1407498883745 GMPInstallManager.simpleCheckAndInstall INFO  Found 1 addons advertised.
> 1407498883745 GMPInstallManager.simpleCheckAndInstall INFO  Found addon: gmp-gmpopenh264 (isValid: true, isInstalled: false, isOpenH264: true, hashFunction: SHA512, hashValue: 0eac05de3b9dd939ece57450bcddf6fee04415a99744a0ce46ddb19c1205cbaf4d8c5a7b5efc2158c9fb257a7948024ed1604890b56382513922107e22273165, size: 282746)
> 1407498884850 GMPInstallManager.simpleCheckAndInstall INFO  Addon installed successfully: gmp-gmpopenh264 (isValid: true, isInstalled: true, isOpenH264: true, hashFunction: SHA512, hashValue: 0eac05de3b9dd939ece57450bcddf6fee04415a99744a0ce46ddb19c1205cbaf4d8c5a7b5efc2158c9fb257a7948024ed1604890b56382513922107e22273165, size: 282746)
> TEST-PASS | testSecurity/testSafeBrowsingNotificationBar.js | testNotificationBar
> TEST-START | testSecurity/testSafeBrowsingNotificationBar.js | teardownModule

I've seen this on both 34 and 33 on OSX

Comment 8

[Andrei Eftimie]

I can reproduce this consistently.
I thought of creating a new issue, but since this was never fixed, and we fail with the same message in the same place I think we can use it.

Comment 9

[Andrei Eftimie]

I can actually reproduce it by running just the /testStopReloadButtons.js test, its not 100%, but at a pretty large rate.

Comment 10

[Andrei Eftimie]

Attachment: testcase.js

Testcase attached. It seems to fail randomly between 10% and 80% (got long stretches of failing and of passing).

Reproduces on 34, 33, 32, 31

Comment 11

[Andrei Eftimie]

Attachment: log_debugBuild_with_debug.txt

Here's a log with --debug with a Debug Nightly build.

Comment 12

[Andrei Eftimie]

Attachment: log_debugBuild_with_debug_PASS.txt

PASSing log (same as the above).

Besides some timing differences, on the FAILing log I have the following items:
> JavaScript strict warning: https://cdn.optimizely.com/js/246059135.js, line 10: variable a redeclares argument
(about 100 lines)
And after these I have a few lines:
> [6862] WARNING: NS_ENSURE_SUCCESS(status, status) failed with result 0x804B0002: file /builds/slave/m-cen-osx64-d-0000000000000000/build/content/base/src/nsCrossSiteListenerProxy.cpp, line 523

And just before the testfailure:
> JavaScript strict warning: about:home, line 8: anonymous function does not always return a value
> JavaScript strict warning: about:home, line 84: function chooseSnippet does not always return a value
> JavaScript strict warning: about:home, line 8: reference to undefined property d[a]
> [6862] WARNING: NS_ENSURE_TRUE(isFileURI) failed: file /builds/slave/m-cen-osx64-d-0000000000000000/build/content/base/src/ThirdPartyUtil.cpp, line 284
> [6862] WARNING: NS_ENSURE_TRUE(isFileURI) failed: file /builds/slave/m-cen-osx64-d-0000000000000000/build/content/base/src/ThirdPartyUtil.cpp, line 284
> ++DOCSHELL 0x12a9b9800 == 8 [pid = 6862] [id = 8]
> ++DOMWINDOW == 19 (0x12aa09000) [pid = 6862] [serial = 19] [outer = 0x0]
> [6862] WARNING: NS_ENSURE_TRUE(globalObject && globalObject->GetGlobalJSObject()) failed: file /builds/slave/m-cen-osx64-d-0000000000000000/build/content/html/document/src/nsHTMLContentSink.cpp, line 741

Comment 13

[Henrik Skupin [:whimboo][⌚️UTC+1] (away from Feb 12th - Feb 22nd)]

(In reply to Andrei Eftimie from comment #11)
> Here's a log with --debug with a Debug Nightly build.

Debug does not help here and it not what I have requested from you on IRC. What I was looking for are the commented out dump lines in window.js of Mozmill.

Comment 14

[Andrei Eftimie]

Attachment: fail.txt

Comment 15

[Andrei Eftimie]

Attachment: pass.txt

Well, the logging from window.js doesn't seem to help either.

The only difference between these logs is the Failure vs Pass message.
All page status updates are identical.

Comment 16

[Henrik Skupin [:whimboo][⌚️UTC+1] (away from Feb 12th - Feb 22nd)]

Oh, I missed to mention that you will also have to uncomment the line in controller.js, which handles the page id stuff. That will indicate a failure in waitForPageLoad.

Comment 17

[Andrei Eftimie]

That doesn't help. I get the correct window id (7) once (for the about:blank) page.
We seem to be perfectly fine loading the page (and unloading it).

It might be that we're not able to attach the listener for unload fast enough for us to catch the event, but I've yet been unable to prove or disprove this.

Comment 18

[Henrik Skupin [:whimboo][⌚️UTC+1] (away from Feb 12th - Feb 22nd)]

(In reply to Andrei Eftimie from comment #17)
> That doesn't help. I get the correct window id (7) once (for the
> about:blank) page.
> We seem to be perfectly fine loading the page (and unloading it).

I'm not interested in the id for loading about:blank. As you say it's fine loading this page. Important is all the information for the following open/waitforpageload calls. Please attach such a log.

> It might be that we're not able to attach the listener for unload fast
> enough for us to catch the event, but I've yet been unable to prove or
> disprove this.

That should not be related if it also doesn't work with a sleep inserted.

Comment 19

[Henrik Skupin [:whimboo][⌚️UTC+1] (away from Feb 12th - Feb 22nd)]

So I added a for loop inside the test and run it 100 times. The test never failed for me on Ubuntu 64bit with latest Nightly.

Comment 20

[Daniel Gherasim]

I also run the testcase & this are the results:

Max OSX 10.8    :: Firefox Nightly th    --- 63/100 FAILED
Linux 14.10 x64 :: Fireofx Mightly th    --- 0/100 FAILED
Linux 14.10 x64 :: Fireofx Mightly en-US --- 0/100 FAILED

Comment 21

[Henrik Skupin [:whimboo][⌚️UTC+1] (away from Feb 12th - Feb 22nd)]

It doesn't even fail for me with Mozmill master on OS X with the given th Nightly build. So I'm dependent on your help. Otherwise I'm not sure how much time we should invest here. This failure is not visible on CI and we have pretty more important tasks to work on. Maybe we should delay that bug.

Comment 22

[Andrei Eftimie]

I agree, I can ignore it locally since its the last test.
It doesn't fail in CI, lets leave this for a later date.

Comment 23

[Henrik Skupin [:whimboo][⌚️UTC+1] (away from Feb 12th - Feb 22nd)]

Mozmill tests have been superseded by Marionette tests.