Closed Bug 1024734 Opened 10 years ago Closed 7 years ago

Intermittent test_import.html | Exception: Unable to add project to the AppProjects indexedDB: ConstraintError - A mutation operation in the transaction failed because a constraint was not satisfied. For example, an object such as an object store or index

Categories

(DevTools Graveyard :: WebIDE, defect, P3)

Product:
DevTools Graveyard
Component:
WebIDE
Version:
31 Branch
Platform:
x86
Linux
Type:
defect

Tracking

(firefox51 fixed, firefox52 fixed, firefox53 fixed)

Status:
RESOLVED FIXED
Milestone:
Firefox 53
Tracking Flags:
Tracking Status
firefox51 --- fixed
firefox52 --- fixed
firefox53 --- fixed

People

(Reporter: RyanVM, Unassigned)

References

Details

(Keywords: intermittent-failure)

Attachments

(2 files, 1 obsolete file)

Bug 1024734 - Wait correctly for project import in test_import.html.
58 bytes, text/x-review-board-request
jryans
: review+
Details
Wait correctly when calling importPackagedApp in WebIDE tests.
7.75 KB, patch
jryans
: review+
Details | Diff | Splinter Review 
Is this the logging you were looking for, Paul?

https://tbpl.mozilla.org/php/getParsedLog.php?id=41627946&tree=Fx-Team

Ubuntu VM 12.04 fx-team pgo test mochitest-other on 2014-06-12 13:36:57 PDT for push c14df983ff08
slave: tst-linux32-spot-340

13:40:10     INFO -  132 INFO TEST-START | chrome://mochitests/content/chrome/browser/devtools/webide/test/test_import.html
13:40:10     INFO -  133 INFO TEST-PASS | chrome://mochitests/content/chrome/browser/devtools/webide/test/test_import.html | IDB is empty
13:40:10     INFO -  134 INFO TEST-INFO | chrome://mochitests/content/chrome/browser/devtools/webide/test/test_import.html | to call importPackagedApp(/builds/slave/test/build/tests/mochitest/chrome/browser/devtools/webide/test/app)
13:40:10     INFO -  135 INFO TEST-PASS | chrome://mochitests/content/chrome/browser/devtools/webide/test/test_import.html | UI is not busy
13:40:10     INFO -  136 INFO TEST-INFO | dumping last 2 message(s)
13:40:10     INFO -  137 INFO TEST-INFO | if you need more context, please use SimpleTest.requestCompleteLog() in your test
13:40:10     INFO -  138 INFO TEST-INFO | chrome://mochitests/content/chrome/browser/devtools/webide/test/test_import.html | opening WebIDE
13:40:10     INFO -  139 INFO TEST-INFO | chrome://mochitests/content/chrome/browser/devtools/webide/test/test_import.html | WebIDE open
13:40:10     INFO -  140 INFO TEST-UNEXPECTED-FAIL | chrome://mochitests/content/chrome/browser/devtools/webide/test/test_import.html | Exception: Unable to add project to the AppProjects indexedDB: ConstraintError - A mutation operation in the transaction failed because a constraint was not satisfied. For example, an object such as an object store or index already exists and a new one was being attempted to be created.
13:40:10     INFO -  141 INFO TEST-INFO | MEMORY STAT vsize after test: 641646592
13:40:10     INFO -  142 INFO TEST-INFO | MEMORY STAT residentFast after test: 165830656
13:40:10     INFO -  143 INFO TEST-INFO | MEMORY STAT heapAllocated after test: 73537208
13:40:10     INFO -  144 INFO TEST-END | chrome://mochitests/content/chrome/browser/devtools/webide/test/test_import.html | finished in 167ms
13:40:10     INFO -  145 INFO TEST-START | chrome://mochitests/content/chrome/browser/devtools/webide/test/test_manifestUpdate.html
13:40:22     INFO -  1402605622949	Browser.Experiments.Experiments	TRACE	Experiments #0::enabled=true, true
13:40:22     INFO -  1402605622951	Browser.Experiments.Experiments	TRACE	Experiments #0::Registering instance with Addon Manager.
13:40:22     INFO -  1402605622952	Browser.Experiments.Experiments	TRACE	Experiments #0::Registering previous experiment add-on provider.
13:40:22     INFO -  1402605622953	Browser.Experiments.Experiments	TRACE	PreviousExperimentProvider #0::startup()
13:40:22     INFO -  1402605622954	Browser.Experiments.Experiments	TRACE	Experiments #0::_loadFromCache
13:40:22     INFO -  1402605622960	Browser.Experiments.Experiments	TRACE	Experiments #0::_loadTask finished ok
13:40:22     INFO -  1402605622961	Browser.Experiments.Experiments	TRACE	Experiments #0::_run
13:40:22     INFO -  1402605622962	Browser.Experiments.Experiments	TRACE	Experiments #0::_main iteration
13:40:22     INFO -  1402605622962	Browser.Experiments.Experiments	TRACE	Experiments #0::_evaluateExperiments
13:40:22     INFO -  1402605622966	Browser.Experiments.Experiments	TRACE	Experiments #0::_main finished, scheduling next run
13:45:25     INFO -  146 INFO TEST-INFO | dumping last 1 message(s)
13:45:25     INFO -  147 INFO TEST-INFO | if you need more context, please use SimpleTest.requestCompleteLog() in your test
13:45:25     INFO -  148 INFO TEST-INFO | chrome://mochitests/content/chrome/browser/devtools/webide/test/test_manifestUpdate.html | opening WebIDE
13:45:25     INFO -  Xlib:  extension "RANDR" missing on display ":0".
13:45:26     INFO -  TEST-INFO | screentopng: exit 0
13:45:26     INFO -  149 INFO TEST-UNEXPECTED-FAIL | chrome://mochitests/content/chrome/browser/devtools/webide/test/test_manifestUpdate.html | Test timed out.
13:45:26     INFO -  150 INFO TEST-INFO | MEMORY STAT vsize after test: 634314752
13:45:26     INFO -  151 INFO TEST-INFO | MEMORY STAT residentFast after test: 147001344
13:45:26     INFO -  152 INFO TEST-INFO | MEMORY STAT heapAllocated after test: 57831176
13:45:26     INFO -  153 INFO TEST-END | chrome://mochitests/content/chrome/browser/devtools/webide/test/test_manifestUpdate.html | finished in 316009ms
13:45:27     INFO -  154 INFO TEST-START | chrome://mochitests/content/chrome/browser/devtools/webide/test/test_newapp.html
13:47:51     INFO -  1402606071732	Browser.Experiments.Experiments	TRACE	Experiments #0::updateManifest()
13:47:51     INFO -  1402606071734	Browser.Experiments.Experiments	TRACE	Experiments #0::_run
13:47:51     INFO -  1402606071735	Browser.Experiments.Experiments	TRACE	Experiments #0::_main iteration
13:47:51     INFO -  1402606071736	Browser.Experiments.Experiments	TRACE	Experiments #0::_loadManifest
13:47:51     INFO -  1402606071737	Browser.Experiments.Experiments	TRACE	Experiments #0::httpGetRequest(http://127.0.0.1:8888/experiments-dummy/manifest)
13:47:51     INFO -  1402606071751	Browser.Experiments.Experiments	ERROR	Experiments #0::httpGetRequest::onLoad() - Request to http://127.0.0.1:8888/experiments-dummy/manifest returned status 404
13:47:51     INFO -  1402606071751	Browser.Experiments.Experiments	ERROR	Experiments #0::_loadManifest - failure to fetch/parse manifest (continuing anyway): Error: Experiments - XHR status for http://127.0.0.1:8888/experiments-dummy/manifest is 404
13:47:51     INFO -  1402606071752	Browser.Experiments.Experiments	TRACE	Experiments #0::_evaluateExperiments
13:47:51     INFO -  1402606071754	Browser.Experiments.Experiments	TRACE	Experiments #0::_main finished, scheduling next run
13:50:55     INFO -  155 INFO TEST-INFO | dumping last 1 message(s)
13:50:55     INFO -  156 INFO TEST-INFO | if you need more context, please use SimpleTest.requestCompleteLog() in your test
13:50:55     INFO -  157 INFO TEST-INFO | chrome://mochitests/content/chrome/browser/devtools/webide/test/test_newapp.html | opening WebIDE
13:50:55     INFO -  Not taking screenshot here: see the one that was previously logged
13:50:55     INFO -  158 INFO TEST-UNEXPECTED-FAIL | chrome://mochitests/content/chrome/browser/devtools/webide/test/test_newapp.html | Test timed out.
13:50:56     INFO -  159 INFO TEST-INFO | MEMORY STAT vsize after test: 633135104
13:50:56     INFO -  160 INFO TEST-INFO | MEMORY STAT residentFast after test: 149471232
13:50:56     INFO -  161 INFO TEST-INFO | MEMORY STAT heapAllocated after test: 56020040
13:50:56     INFO -  162 INFO TEST-END | chrome://mochitests/content/chrome/browser/devtools/webide/test/test_newapp.html | finished in 328974ms
13:50:56     INFO -  163 INFO TEST-START | chrome://mochitests/content/chrome/browser/devtools/webide/test/test_runtime.html
13:56:25     INFO -  164 INFO TEST-INFO | dumping last 1 message(s)
13:56:25     INFO -  165 INFO TEST-INFO | if you need more context, please use SimpleTest.requestCompleteLog() in your test
13:56:25     INFO -  166 INFO TEST-INFO | chrome://mochitests/content/chrome/browser/devtools/webide/test/test_runtime.html | opening WebIDE
13:56:25     INFO -  Not taking screenshot here: see the one that was previously logged
13:56:25     INFO -  167 INFO TEST-UNEXPECTED-FAIL | chrome://mochitests/content/chrome/browser/devtools/webide/test/test_runtime.html | Test timed out.
13:56:26     INFO -  168 INFO TEST-INFO | MEMORY STAT vsize after test: 633069568
13:56:26     INFO -  169 INFO TEST-INFO | MEMORY STAT residentFast after test: 146718720
13:56:26     INFO -  170 INFO TEST-INFO | MEMORY STAT heapAllocated after test: 55987792
13:56:26     INFO -  171 INFO TEST-END | chrome://mochitests/content/chrome/browser/devtools/webide/test/test_runtime.html | finished in 329969ms
Flags: needinfo?(paul)
Yes! I'll look at this.
Flags: needinfo?(paul)
Assignee: nobody → paul
test_import.html fails with:

> TEST-UNEXPECTED-FAIL | test_import.html |
> Exception: Unable to add project to the AppProjects indexedDB:
> ConstraintError - A mutation operation in the transaction failed
> because a constraint was not satisfied. For example, an object
> such as an object store or index already exists and a new one was
> being attempted to be created.

test_cli.html (that runs right before test_import.html), adds to the IndexedDB a JSON object that is exactly the same as the one we import in test_import.html.

So this sounds like a race where we add a JSON object to the IDB (in test_import.html) before it's actually removed (test_cli.html).

But, at the beginning of test_import.html, we make sure the IDB is empty:

> INFO TEST-PASS | test_import.html | IDB is empty

There must be something about IndexedDB I don't understand.
Alex, you worked on the IDB storage. Any idea what is going on here?
Flags: needinfo?(poirot.alex)
There is something suspicious with log message order:
 IDB is empty
 to call importPackagedApp(/builds/slave/test/build/tests/mochitest/chrome/browser/devtools/webide/test/app)
 UI is not busy
 dumping last 2 message(s)
 if you need more context, please use SimpleTest.requestCompleteLog() in your test
 opening WebIDE
 WebIDE open

We see logs related to openWebIDE() at the end, whereas it is the first thing being called.
If log order really represent call order... there is some dark matter here!
Otherwise I can't think of anything special regarding indexedDB itself. It just looks like we are adding the same index value twice, but the remove() method looks good and only resolves once it is removed from the db...
Flags: needinfo?(poirot.alex)
Note: only happening with Ubuntu.
(In reply to Alexandre Poirot (:ochameau) from comment #8)
> There is something suspicious with log message order:
>  IDB is empty
>  to call
> importPackagedApp(/builds/slave/test/build/tests/mochitest/chrome/browser/
> devtools/webide/test/app)
>  UI is not busy
>  dumping last 2 message(s)
>  if you need more context, please use SimpleTest.requestCompleteLog() in
> your test
>  opening WebIDE
>  WebIDE open
> 
> We see logs related to openWebIDE() at the end, whereas it is the first
> thing being called.
> If log order really represent call order... there is some dark matter here!

I believe it's because of how logs are displayed on error:
http://mxr.mozilla.org/mozilla-central/source/testing/mochitest/tests/SimpleTest/SimpleTest.js#373

First the pass/fail, then if error, show the logs (info).
Assignee: paul → nobody
Bulk assigning P3 to all open intermittent bugs without a priority set in Firefox components per bug 1298978.
Priority: -- → P3
Something made this spike a couple weeks ago. Any idea what that might have been, Paul?
Flags: needinfo?(paul)
:ochameau, is this related to the other WebIDE fix you made recently?  Does it help with this bug too?
Flags: needinfo?(paul) → needinfo?(poirot.alex)
The exception looks very different, so I would say it is some other reason, but it is worth trying!
No matter if that fixes this particular intermittent it you save us from some other..
Attachment #8797069 - Flags: review?(jryans)
Comment on attachment 8797069 [details] [diff] [review]
Wait correctly for project import in test_import.html.

I was unable to push to try locally, so going the mozreview way...
Attachment #8797069 - Attachment is obsolete: true
Flags: needinfo?(poirot.alex)
Attachment #8797069 - Flags: review?(jryans)
Still intermittent with this patch. But I see a call to `yield nextTick();`...
Comment on attachment 8797078 [details]
Bug 1024734 - Wait correctly for project import in test_import.html.

https://reviewboard.mozilla.org/r/82730/#review81806

Thanks for looking into it!
Attachment #8797078 - Flags: review?(jryans) → review+
Let's see if that at least make it less intermittent.
Keywords: leave-open
Pushed by apoirot@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/c8299e3e3d1c
Wait correctly for project import in test_import.html. r=jryans
Aaaaah mozreview! It's not just a backout issue. What if I want to submit just new patch queue?

May be waiting correctly in all test will fix that?
(The idea being that this exception is related to a previous test still doing thing in the next one?)
Attachment #8799443 - Flags: review?(jryans)
https://hg.mozilla.org/integration/fx-team/rev/687572ea20cb84f1842ad00dcc8ca1712868a361
Bug 1024734 - Wait correctly when calling importPackagedApp in WebIDE tests. r=jryans
Any updates here, Alexandre?
Flags: needinfo?(poirot.alex)
My patches don't fix this intermittent. I was able to see them in try pushes. That's why I hold landing them.

Also, WebIDE is a ghost. Noone is maintaining it. We keep saying we will remove it once bug 1243329 lands.
But that bug is also somewhat low priority.

Looking at the last orangefactor comments it looks like it mostly happens on beta/aurora.
May be some other patches I made to fix webide tests while I worked on this one had an impact.

I'll try to rebase these patches and land them, they may make this one slightly less frequent.
Flags: needinfo?(poirot.alex)
I mainly don't want to see this high-frequency failure throughout the duration of the ESR52 cycle. If WebIDE isn't a priority anymore, can we disable the test?
Oh wait, both patches already landed. Is it still a frequent intermittent on m-c?
May be it is mostly about uplifting these two?
13 failures on trunk in the last week. And the patches landed when trunk was still 52.
Given WebIDE's priority, I think disabling the test is the best use of our efforts here.
As fixed as it's ever going to be.
Status: NEW → RESOLVED
Closed: 7 years ago
status-firefox51: --- → affected
status-firefox52: --- → affected
status-firefox53: --- → fixed
Keywords: leave-open
Resolution: --- → FIXED
Target Milestone: --- → Firefox 53
Product: Firefox → DevTools
Product: DevTools → DevTools Graveyard
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: