Closed Bug 781547 Opened 12 years ago Closed 11 years ago

Failure in "/testBookmarks_OpenAllInTabs/test1.js" with "Default bookmarks have been imported"

Categories

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

defect

Tracking

(firefox19 fixed, firefox20 fixed, firefox21 fixed, firefox22 fixed, firefox-esr10 wontfix, firefox-esr17 fixed)

RESOLVED FIXED
Tracking Status
firefox19 --- fixed
firefox20 --- fixed
firefox21 --- fixed
firefox22 --- fixed
firefox-esr10 --- wontfix
firefox-esr17 --- fixed

People

(Reporter: virgil.dicu, Assigned: daniela.p98911)

References

()

Details

(Whiteboard: [mozmill-test-failure] s=121022 u=failure c=bookmarks p=1)

Attachments

(7 files, 6 obsolete files)

1.80 KB, patch
AndreeaMatei
: review+
davehunt
: checkin+
Details | Diff | Splinter Review
1.85 KB, patch
AndreeaMatei
: review+
whimboo
: checkin+
Details | Diff | Splinter Review
36.10 KB, patch
Details | Diff | Splinter Review
1.84 KB, text/plain
Details
1.82 KB, text/plain
Details
901 bytes, patch
davehunt
: feedback-
Details | Diff | Splinter Review
1.02 KB, patch
AndreeaMatei
: review+
Details | Diff | Splinter Review
Happened today on Mac OS 10.7 on Nightly. Couldn't reproduce locally.
Looks to me like a hang in restoreDefaultBookmarks() from places.js 
The test timeout for restoring default bookmarks in teardownModule - so this failed at the cleanup stage of the test. 

Lets monitor this for a couple of days, I'd say. 
I am going to assign myself to this so I can easily track the bug number.
Assignee: nobody → vlad.mozbugs
Status: NEW → ASSIGNED
Whiteboard: [mozmill-test-failure][endurance]
What timeout have we set currently? If it is 5s we should increase it but anything larger than that I wonder if it is a regression. It really shouldn't take that long.
Whiteboard: [mozmill-test-failure][endurance] → [mozmill-test-failure]
(In reply to Henrik Skupin (:whimboo) from comment #2)
> What timeout have we set currently? If it is 5s we should increase it but
> anything larger than that I wonder if it is a regression. It really
> shouldn't take that long.

Its default, that is 5s - should I prepare a quick patch with the timeout increased to 10s? I would not suggest more in this case, as you said, we should worry about a regression given a larger timeout value. 

More, it appear that reports for today are clean for default
http://mozmill-ci.blargon7.com/#/endurance/report/d87d47fd1034f072b9bece6ee604db40
Ups - I was looking in the wrong place by mistake. 

  mozmill.utils.waitFor(function () {
    return importSuccessful;
  }, "Default bookmarks have been imported", BOOKMARKS_TIMEOUT);

It seems that we have a timeout set to 10s (const BOOKMARKS_TIMEOUT = 10000;) 
We should definitely not increase this value. 

Please ignore comment 3 then, only the clean report from there applies as good data
Would you mind to re-test on a heavily loaded system? Would be good to know how the times varies in restoring the bookmarks.
(In reply to Henrik Skupin (:whimboo) from comment #5)
> Would you mind to re-test on a heavily loaded system? Would be good to know
> how the times varies in restoring the bookmarks.
http://mozmill-crowd.blargon7.com/#/endurance/reports?branch=17.0&platform=Mac&from=2012-08-07&to=2012-08-10 

Just an update, until now no errors
Final results after a couple of days of testing: 

Normally loaded environment and default configuration(10 iterations 10 entities): PASS 
http://mozmill-crowd.blargon7.com/#/endurance/report/d87d47fd1034f072b9bece6ee625441e

Heavily loaded system and default test config(10 iterations 10 entities): PASS
http://mozmill-crowd.blargon7.com/#/endurance/report/d87d47fd1034f072b9bece6ee607a1db
Note: Memory consumption increased with 40MB 

Heavily loaded system and edge case test configuration(10 iterations 100 entities): PASS
http://mozmill-crowd.blargon7.com/#/endurance/report/d87d47fd1034f072b9bece6ee6255142
Note: Memory consumption increased with more than 100MB 

Heavily loaded system and obscene test configuration (meaning 200 entities): FAIL 
http://mozmill-crowd.blargon7.com/#/endurance/report/d87d47fd1034f072b9bece6ee6255a00

Error: "Disconnect Error: Application unexpectedly closed" 

So I think our test is reliable enough and we just had a one time situation. 
I was really running 3 VMs at a time, listening to youtube, chatting and other network connected apps opened but still did not catch our wanted error once.
Let's close this for now and reopen if it occurs again.
Status: ASSIGNED → RESOLVED
Closed: 12 years ago
Resolution: --- → WORKSFORME
Happened again today on Mac 10.7.5
http://mozmill-ci.blargon7.com/#/endurance/report/2e7486a8c08b5541b9074117e062d5f0
Status: RESOLVED → REOPENED
Resolution: WORKSFORME → ---
Thanks for the report Alex. The fix will be addressed in bug 783197
Depends on: 783197
Happened a couple times in the last days. So let get this investigated and fixed next week.
Status: REOPENED → NEW
Priority: -- → P2
Summary: Failure in /testBookmarks_OpenAllInTabs/test1.js on Mac OS 10.7.4 → Failure in "/testBookmarks_OpenAllInTabs/test1.js" with "Default bookmarks have been imported"
Whiteboard: [mozmill-test-failure] → [mozmill-test-failure] s=121022 u=failure c=bookmarks p=1
OS: Mac OS X → All
Hardware: x86_64 → All
Status: NEW → ASSIGNED
Depends on: 800800
No longer depends on: 783197
Assignee: vlad.mozbugs → dpetrovici
Unable to reproduce locally on any of the VMs here. I have tried on MAC OS 10.6.8 and Windows 7 SP1.
Failure reproduced again on Nightly en_US MAC OS 10.7.5
http://mozmill-ci.blargon7.com/#/endurance/report/674977957b923f4905160d1b9acc8439
Reproducible in Aurora branch on Mac OS X 10.7.5 (x86_64):
http://mozmill-ci.blargon7.com/#/endurance/report/352218d7e3125c857fc1d371671de5f2
Looking into the latest report, all iterations were executed and only in tearDown did the error occur. Could we try to create a reduced test case that might replicate this more frequently? It should only need to add a number of bookmarks in a folder and then restore the default bookmarks. Most of this can be taken from the existing endurance test.
No longer depends on: 800800
We know how to fix that given bug 800800, so can we please get this fixed?
Attached patch patch v1.0 (obsolete) — Splinter Review
Added observer to the restoreDefaultBookmarks function. I have ran the test on Mac 10.7.5 with Nightly build:
http://mozmill-crowd.blargon7.com/#/endurance/report/a11aa7b15f4e571fd6fe21a2db826e44
Attachment #693485 - Flags: review?(hskupin)
Attachment #693485 - Flags: review?(dave.hunt)
Attachment #693485 - Flags: review?(andreea.matei)
Comment on attachment 693485 [details] [diff] [review]
patch v1.0

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

r=me with the mentioned change done.

::: lib/places.js
@@ +83,5 @@
>  /**
>   * Restore the default bookmarks for the current profile
>   */
>  function restoreDefaultBookmarks() {
> +  const TOPIC_BOOKMARKS_RESTORE_SUCCESS = "bookmarks-restore-success";  

nit: trailing white-space
Attachment #693485 - Flags: review?(hskupin)
Attachment #693485 - Flags: review?(dave.hunt)
Attachment #693485 - Flags: review?(andreea.matei)
Attachment #693485 - Flags: review+
Attached patch patch v1.1Splinter Review
removed trailing whitespaces
Attachment #693485 - Attachment is obsolete: true
Attachment #693806 - Flags: review?(hskupin)
Attachment #693806 - Flags: review?(dave.hunt)
Attachment #693806 - Flags: review?(andreea.matei)
Comment on attachment 693806 [details] [diff] [review]
patch v1.1

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

Lets see if this fixes the failure.
Attachment #693806 - Flags: review?(hskupin)
Attachment #693806 - Flags: review?(dave.hunt)
Attachment #693806 - Flags: review?(andreea.matei)
Attachment #693806 - Flags: review+
I assume both esr branches need the fix too?
An observer is already added in restoreDefaultBookmarks for esr10, but not for esr17. Also, can you please tell me if I need to make changes for aurora and beta too?
(In reply to Daniela Petrovici from comment #32)
> An observer is already added in restoreDefaultBookmarks for esr10, but not
> for esr17. Also, can you please tell me if I need to make changes for aurora
> and beta too?

What are the implications when we don't update other branches?
Attached patch patch for aurora branch v1.0 (obsolete) — Splinter Review
Patch for default cannot be applied clearly for other branches. I have added the patch for aurora which applies clearly for all branches:
Aurora:
MAC 10.7.5 x64 - http://mozmill-crowd.blargon7.com/#/endurance/reports
Windows XP SP3 - http://mozmill-crowd.blargon7.com/#/endurance/report/a11aa7b15f4e571fd6fe21a2db9fd38d
Linux - http://mozmill-crowd.blargon7.com/#/endurance/report/a11aa7b15f4e571fd6fe21a2dba00e0d
Beta:
http://mozmill-crowd.blargon7.com/#/endurance/report/a11aa7b15f4e571fd6fe21a2dba00ce9 - XP SP3
http://mozmill-crowd.blargon7.com/#/endurance/report/a11aa7b15f4e571fd6fe21a2dba02759 - Linux
http://mozmill-crowd.blargon7.com/#/endurance/report/a11aa7b15f4e571fd6fe21a2dba025bd - MAC 10.7.5 x64
ESR17:
http://mozmill-crowd.blargon7.com/#/endurance/report/a11aa7b15f4e571fd6fe21a2db9feb67 - XP SP3
http://mozmill-crowd.blargon7.com/#/endurance/report/a11aa7b15f4e571fd6fe21a2db9fde46 - mac 10.7.5
http://mozmill-crowd.blargon7.com/#/endurance/report/a11aa7b15f4e571fd6fe21a2dba000d3 - Linux
Release:
http://mozmill-crowd.blargon7.com/#/endurance/report/a11aa7b15f4e571fd6fe21a2dba018e1 - XP SP3
http://mozmill-crowd.blargon7.com/#/endurance/report/a11aa7b15f4e571fd6fe21a2dba1c041 - MAC
http://mozmill-crowd.blargon7.com/#/endurance/report/a11aa7b15f4e571fd6fe21a2dba2d7f4 - Linux

The patch does not need to be applied for esr10 since the restoreDefaultBookmarks() already has the observer that was added to default branch
Attachment #694358 - Flags: review?(hskupin)
Attachment #694358 - Flags: review?(dave.hunt)
Attachment #694358 - Flags: review?(andreea.matei)
Comment on attachment 694358 [details] [diff] [review]
patch for aurora branch v1.0

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

Just a few more nits to handle.

::: lib/places.js
@@ +89,3 @@
>    var importSuccessful = false;
> +  var observer = {
> +    observe: function(aSubject, aTopic, aData) {

We need a space here between function and "(".

@@ +91,5 @@
> +    observe: function(aSubject, aTopic, aData) {
> +      importSuccessful = true;
> +    }
> +  }
> +  

You have trailing whitespaces here.
Attachment #694358 - Flags: review?(hskupin)
Attachment #694358 - Flags: review?(dave.hunt)
Attachment #694358 - Flags: review?(andreea.matei)
Attachment #694358 - Flags: review-
Adding the observer did not fix the issue on Nightly builds. Report: http://mozmill-ci.blargon7.com/#/endurance/report/87220f551d53bd61286b3d93d903964a
Happened on Mac OS X 10.7.5 (x86_64).
Updated patch for Aurora based on review. This is to add missing code on all branches because the issue still reproduced with the proposed fix.
Attachment #694358 - Attachment is obsolete: true
Attachment #695990 - Flags: review?(hskupin)
Attachment #695990 - Flags: review?(dave.hunt)
Attachment #695990 - Flags: review?(andreea.matei)
Comment on attachment 695990 [details] [diff] [review]
patch for aurora branch v1.1

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

Too bad it didn't fix the issue, but I consider it is a good change to make anyway, in order to ensure we have removed the observer, as we did with the removeAllHistory().
Attachment #695990 - Flags: review?(hskupin)
Attachment #695990 - Flags: review?(dave.hunt)
Attachment #695990 - Flags: review?(andreea.matei)
Attachment #695990 - Flags: review+
Comment on attachment 695990 [details] [diff] [review]
patch for aurora branch v1.1

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

Please keep in mind to add a commit message to the patch which corresponds to the code you are updating and not necessarily the bug summary. Given that the attached bug doesn't fix the problem formerly set commit messages are invalid now. So please consider to not use the bug summary at all in the future.

http://hg.mozilla.org/qa/mozmill-tests/rev/bea8007340e5 (aurora)
http://hg.mozilla.org/qa/mozmill-tests/rev/61ac71003e87 (beta)
http://hg.mozilla.org/qa/mozmill-tests/rev/c70885387ea8 (release)
http://hg.mozilla.org/qa/mozmill-tests/rev/b11d56923858 (esr17)
Attachment #695990 - Flags: checkin+
Status: ASSIGNED → RESOLVED
Closed: 12 years ago11 years ago
Keywords: checkin-needed
Resolution: --- → FIXED
Happened again in 2013-01-03 on 17.0.1esrpre OS X:
http://mozmill-ci.blargon7.com/#/endurance/report/23d8fbdd0190d4b0496d6b129f465a87
Status: RESOLVED → REOPENED
Resolution: FIXED → ---
In that case it needs further investigation given that the missing observer handling was not the reason for this failure. :/
Priority: P2 → P3
Also reproduced today on Mac OSX 10.8.2 with Firefox 21.0a1:
http://mozmill-ci.blargon7.com/#/endurance/report/72e15dc943833b8fcba70aeb51bd0744
Daniela, do we have updates here?
I tried to reproduce the issue on the MAC OS 10.8.2 (release7-osx-107.qa.mtv1.mozilla.com) with FF 21.0a1 FR version and the failure did not reproduce. 

Next I will try on a Windows XP machine with the build from 1/21 and see if I can reproduce.
Since this won't reproduce locally, here's another report:
http://mozmill-ci.blargon7.com/#/endurance/report/72e15dc943833b8fcba70aeb51fa65f8
It reproduced locally on MAC OS 10.7.5 and Beta 19.0b4:
http://mozmill-crowd.blargon7.com/#/endurance/report/ad726b5c70cf80fbf8135edfca50f118

The observer is not called and we are not making importSuccessful = true. I am re-running the tests now to see if the import is failed, but it will take some time since the bug is not easily reproducible.
I don't think that will be helpful unless you already have added the other observer notifications which are send in case of a failure as discussed on IRC earlier today.
I already added the other observer for "bookmarks-restore-failed" as discussed and I am trying to reproduce the issue with the new code.
I added the observer for import failed and ran the test 300 times on MAC OS 10.7.5 with Beta version (under heavy load). The issue reproduced 3 times starting from yesterday evening:
http://mozmill-crowd.blargon7.com/#/endurance/report/1641bc2f6438595b86015bd901449f96

The problem does not appear to be the fact that the import has failed, but that the observer does not observe the import.

I have added the testing patch I have created to run the test. This patch removes all endurance tests except the one that is failing so that we can run it more easily, but it also contains the changes I made.

Please tell me if I should also try something else, or if I should talk to a developer about waiting for anything else when importing default bookmarks.

NOTE: I will also add the files with the results - when it passes and when it fails
Attachment #711214 - Flags: feedback?(hskupin)
Attachment #711214 - Flags: feedback?(dave.hunt)
Attachment #711215 - Attachment mime type: application/x-gzip → text/plain
Attachment #711215 - Attachment mime type: text/plain → application/gzip
Attached file log for test passing
Attachment #711215 - Attachment is obsolete: true
Attached file log for test failing
Comment on attachment 711214 [details] [diff] [review]
testing patch with dumps

Interesting findings... Does it make any difference if we add a short delay before calling importFromURL? I wonder if we're sometimes calling this before things are fully initialised, however I would expect that to trigger the failure observer.
Attachment #711214 - Flags: feedback?(hskupin)
Attachment #711214 - Flags: feedback?(dave.hunt)
Adding a controller.sleep(5000) before importing bookmarks works (tried about 50 runs), but since this is not a short delay I am trying now with 2 seconds to see if it works in 200 runs.

I managed to reproduce the issue once in 35 runs when increasing the BOOMARK_TIMEOUT to 60000 (one minute) => the observer was still not triggered. 

Since the issue started reproducing more frequently now on my machine (under heavy load), I will try:
1) to see what is the minimum amount of seconds we need to wait before importing (in 200 runs)
2) see if increasing the timeout more will not help

In case it doesn't help, I will talk next week with the developer that worked on this and try to see if we can wait for something else
Good work. The sleep before is not ideal but may be an indicator that we need to observe another event before attempting to import bookmarks. Perhaps look at any mochitests that cover this functionality for clues, or reach out to a developer that has worked on it.
So where are we currently failing? Is it in setupModule or teardownModule? I can remember the situation that we had to add sleeps of 4s to all of our awesomebar tests to get around the problem after startup that the database is getting initialized lazily. We might hit the same problem here if the failure is always raised in setupModule.
This happens in the teardown module. A sleep of 0.5 seconds before importing bookmarks helps - all tests passed last night with 200 runs.
Please talk with Marco Bonardo then. He might be able to help us to understand this issue.
The error happens in restoreDefaultBookmarks function in our places.js library (https://hg.mozilla.org/qa/mozmill-tests/file/945cbb978d10/lib/places.js#l88).

It seems that if I add a delay of 0.5 seconds just before BookmarkHTMLUtils.importFromURL(BOOKMARKS_RESOURCE, true); line the import of bookmarks is successful.

Marco, can you please tell us if there is any event we should wait for before importing the default bookmarks?
Flags: needinfo?(mak77)
(In reply to Daniela Petrovici from comment #61)
> The error happens in restoreDefaultBookmarks function in our places.js
> library
> (https://hg.mozilla.org/qa/mozmill-tests/file/945cbb978d10/lib/places.
> js#l88).
> 
> It seems that if I add a delay of 0.5 seconds just before
> BookmarkHTMLUtils.importFromURL(BOOKMARKS_RESOURCE, true); line the import
> of bookmarks is successful.
> 
> Marco, can you please tell us if there is any event we should wait for
> before importing the default bookmarks?

not that I'm aware of, though it's hard to evaluate without knowing what happens just before this, do you just launch the browser? what's the profile status when that happens, does an updated profile exist already?
On browser startup we already do some bookmarks import/restore and maybe it's overriding your work, but I can't tell if I don't know what the test is doing to the browser. On browser startup nsBrowserGlue initializes Places, it waits for the places-init-complete event, and then does any import/restore asynchronously, if needed (like if you start on a profile that doesn't already have a places.sqlite file). There is no event to listen for all of this, but we could add one if that's the case.
Flags: needinfo?(mak77)
Depends on: 839996
I tried the places-init-complete, but that does not work. After discussing with Dave on IRC, I have logged bug 839996 for adding an event to wait for to show us we are ready to import the bookmarks.

I will also create a patch with the sleep of 0.1 seconds before importing the bookmarks until the other bug is fixed.
No longer depends on: 839996
Depends on: 839996
We discussed on IRC about adding the sleep of 0.1s before importing the bookmarks. I added this patch with feedback because by making this change we are also changing five other tests (endurance and functional). The problem here is that the "/testBookmarks_OpenAllInTabs/test1.js" is the only one that fails with "Default bookmarks have been imported" error and it is not failing very often. In case this is not very important, I would like to propose that we wait for bug 839996 to be fixed.
Attachment #712849 - Flags: feedback?(hskupin)
Attachment #712849 - Flags: feedback?(dave.hunt)
Comment on attachment 712849 [details] [diff] [review]
adding the sleep before importing the patch

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

I hadn't realised we were failing in teardown, I had wrongly assumed it was setup. I'm not keen on adding this delay to unaffected tests. Could we revise the patch to add the delay only in the affected test? Even then, I would like to wait for some feedback on bug 839996 before we consider landing such a workaround.
Attachment #712849 - Flags: feedback?(hskupin)
Attachment #712849 - Flags: feedback?(dave.hunt)
Attachment #712849 - Flags: feedback-
Patch for adding sleep before importing the default bookmarks. Report:
http://mozmill-crowd.blargon7.com/#/endurance/report/a83c700664548dba07298b74bf39a055
Attachment #712849 - Attachment is obsolete: true
Attachment #713410 - Flags: feedback?(hskupin)
Attachment #713410 - Flags: feedback?(dave.hunt)
Comment on attachment 713410 [details] [diff] [review]
adding sleep before restoring the default bookmarks

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

Please add a comment mentioning bug 839996, so we can remove this once it's resolved.
Attachment #713410 - Flags: feedback?(hskupin)
Attachment #713410 - Flags: feedback?(dave.hunt)
Attachment #713410 - Flags: feedback-
Made the required changes
Attachment #713845 - Flags: feedback?(hskupin)
Attachment #713845 - Flags: feedback?(dave.hunt)
Comment on attachment 713845 [details] [diff] [review]
patch v1.2 - adding sleep before restoring default bookmarks

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

Thanks Daniela. Let's get Henrik's feedback when he returns from PTO.
Attachment #713845 - Flags: feedback?(dave.hunt) → feedback+
Reproducible again on MAC OS 10.6.8 and Beta:
http://mozmill-ci.blargon7.com/#/endurance/report/f36358d058daf73ddbf7815016699f3d
Comment on attachment 713845 [details] [diff] [review]
patch v1.2 - adding sleep before restoring default bookmarks

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

I like the approach to be a workaround for now but not the current value. It certainly can cause orangeness on slower test machines. Given that it is only a single test please increase the value to 500ms and make it clear in the comment that this is a workaround for the time being.
Attachment #713845 - Flags: feedback?(hskupin) → feedback+
Modified patch based on feedback.
Attachment #713845 - Attachment is obsolete: true
Attachment #717059 - Flags: review?(andreea.matei)
Comment on attachment 717059 [details] [diff] [review]
patch v1.3 - adding sleep before restoring default bookmarks

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

::: tests/endurance/testBookmarks_OpenAllInTabs/test1.js
@@ +32,5 @@
>  
>  function teardownModule() {
>    tabBrowser.closeAllTabs();
> +
> +  // XXX: Bug 839995

Wrong bug :)
Attachment #717059 - Flags: review?(andreea.matei) → review-
Modified the bug no. Sorry about that
Attachment #717059 - Attachment is obsolete: true
Attachment #717124 - Flags: review?(andreea.matei)
Comment on attachment 717124 [details] [diff] [review]
patch v1.4 - adding sleep before restoring default bookmarks

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

Landed as:
http://hg.mozilla.org/qa/mozmill-tests/rev/367d0a4dd295 (default)
Attachment #717124 - Flags: review?(andreea.matei) → review+
I think we can close it even if it is a workaround. Your work is done here. Whenever we get an event sent we can back this out in a follow-up bug.
Status: ASSIGNED → RESOLVED
Closed: 11 years ago11 years ago
Resolution: --- → FIXED
Product: Mozilla QA → Mozilla QA Graveyard
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Created:
Updated:
Size: