Closed Bug 1485569 Opened 6 years ago Closed 5 years ago

Intermittent test-verify toolkit/components/normandy/test/browser/browser_actions_AddonStudyAction.js | Uncaught exception - ConstraintError: A mutation operation in the transaction failed because a constraint was not satisfied.

Categories

(Firefox :: Normandy Client, defect)

defect
Not set
normal

Tracking

()

RESOLVED FIXED
Firefox 67
Tracking Status
firefox-esr60 --- unaffected
firefox62 --- unaffected
firefox63 --- wontfix
firefox64 --- wontfix
firefox65 --- wontfix
firefox66 --- wontfix
firefox67 --- fixed

People

(Reporter: intermittent-bug-filer, Assigned: rehandalal+mozilla)

References

Details

(Keywords: intermittent-failure, Whiteboard: [stockwell needswork:owner])

Attachments

(1 obsolete file)

Filed by: ebalazs [at] mozilla.com

https://treeherder.mozilla.org/logviewer.html#?job_id=195440849&repo=mozilla-central

https://queue.taskcluster.net/v1/task/fxGItsAIQHCCzVaVbLBXfg/runs/0/artifacts/public/logs/live_backing.log

INFO - TEST-PASS | toolkit/components/normandy/test/browser/browser_actions_AddonStudyAction.js | an end date should not be assigned - 
[task 2018-08-23T04:36:47.315Z] 04:36:47     INFO - TEST-PASS | toolkit/components/normandy/test/browser/browser_actions_AddonStudyAction.js | an enrollment event should be sent - [["enroll","addon_study","success",{"addonId":"normandydriver@example.com","addonVersion":"1.0"}]] deepEqual [["enroll","addon_study","success",{"addonId":"normandydriver@example.com","addonVersion":"1.0"}]] - 
[task 2018-08-23T04:36:47.316Z] 04:36:47     INFO - TEST-PASS | toolkit/components/normandy/test/browser/browser_actions_AddonStudyAction.js | sendEvent(unenroll, addon_study, success, {"addonId":"normandydriver@example.com","addonVersion":"1.0","reason":"uninstalled"}) should match spec - 
[task 2018-08-23T04:36:47.317Z] 04:36:47     INFO - TEST-PASS | toolkit/components/normandy/test/browser/browser_actions_AddonStudyAction.js | The add-ons should be same before and after the test - {} deepEqual {} - 
[task 2018-08-23T04:36:47.317Z] 04:36:47     INFO - Buffered messages finished
[task 2018-08-23T04:36:47.319Z] 04:36:47     INFO - TEST-UNEXPECTED-FAIL | toolkit/components/normandy/test/browser/browser_actions_AddonStudyAction.js | Uncaught exception - 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.
[task 2018-08-23T04:36:47.320Z] 04:36:47     INFO - Leaving test bound wrappedTestFunction
[task 2018-08-23T04:36:47.320Z] 04:36:47     INFO - Entering test bound wrappedTestFunction
[task 2018-08-23T04:36:47.321Z] 04:36:47     INFO - GECKO(17127) | JavaScript error: , line 0: uncaught exception: null
[task 2018-08-23T04:36:47.322Z] 04:36:47     INFO - Console message: [JavaScript Error: "uncaught exception: null"]
[task 2018-08-23T04:36:47.322Z] 04:36:47     INFO - TEST-PASS | toolkit/components/normandy/test/browser/browser_actions_AddonStudyAction.js | unenroll should fail when no study exists - 
[task 2018-08-23T04:36:47.324Z] 04:36:47     INFO - TEST-PASS | toolkit/components/normandy/test/browser/browser_actions_AddonStudyAction.js | The add-ons should be same before and after the test - {} deepEqual {} - 
[task 2018-08-23T04:36:47.325Z] 04:36:47     INFO - Not taking screenshot here: see the one that was previously logged
[task 2018-08-23T04:36:47.327Z] 04:36:47     INFO - TEST-UNEXPECTED-FAIL | toolkit/components/normandy/test/browser/browser_actions_AddonStudyAction.js | A promise chain failed to handle a rejection: (Unable to convert rejection reason to string.) - stack: Transaction/this._completionPromise</transaction.onerror@resource://gre/modules/IndexedDB.jsm:237:9
[task 2018-08-23T04:36:47.327Z] 04:36:47     INFO - EventHandlerNonNull*Transaction/this._completionPromise<@resource://gre/modules/IndexedDB.jsm:236:7
[task 2018-08-23T04:36:47.328Z] 04:36:47     INFO - Transaction@resource://gre/modules/IndexedDB.jsm:234:31
[task 2018-08-23T04:36:47.329Z] 04:36:47     INFO - transaction@resource://gre/modules/IndexedDB.jsm:349:23
[task 2018-08-23T04:36:47.330Z] 04:36:47     INFO - objectStore@resource://gre/modules/IndexedDB.jsm:377:23
[task 2018-08-23T04:36:47.330Z] 04:36:47     INFO - getStore@resource://normandy/lib/AddonStudies.jsm:82:10
[task 2018-08-23T04:36:47.331Z] 04:36:47     INFO - wrappedTestFunction@resource://normandy/lib/AddonStudies.jsm:113:19
[task 2018-08-23T04:36:47.332Z] 04:36:47     INFO - async*wrappedTestFunction@chrome://mochitests/content/browser/toolkit/components/normandy/test/browser/head.js:359:13
[task 2018-08-23T04:36:47.332Z] 04:36:47     INFO - async*wrappedTestFunction@chrome://mochitests/content/browser/toolkit/components/normandy/test/browser/browser_actions_AddonStudyAction.js:33:13
[task 2018-08-23T04:36:47.333Z] 04:36:47     INFO - Async*Tester_execTest/<@chrome://mochikit/content/browser-test.js:1106:34
[task 2018-08-23T04:36:47.334Z] 04:36:47     INFO - async*Tester_execTest@chrome://mochikit/content/browser-test.js:1097:16
[task 2018-08-23T04:36:47.334Z] 04:36:47     INFO - nextTest/<@chrome://mochikit/content/browser-test.js:994:9
Summary: Intermittent toolkit/components/normandy/test/browser/browser_actions_AddonStudyAction.js | Uncaught exception - ConstraintError: A mutation operation in the transaction failed because a constraint was not satisfied. → Intermittent test-verify toolkit/components/normandy/test/browser/browser_actions_AddonStudyAction.js | Uncaught exception - ConstraintError: A mutation operation in the transaction failed because a constraint was not satisfied.
I've noticed something similar to this(probably the same root issue) on Beta 53b3 and Nightly 54(09-06-2018) with app.normandy.logging.level to 0 and this seems to be related to bug 1440780. Not sure if I should move this issue to normandy or to create a separate one for the error I see in the console. 
Pinging :mythmon to take a look and decide on the above.


app.normandy.action.AddonStudyAction	DEBUG	Could not run postExecution hook for AddonStudyAction
InvalidStateError: A mutation operation was attempted on a database that did not allow mutations.
app.normandy.action.AddonStudyAction	DEBUG	Could not run postExecution hook for AddonStudyAction
InvalidStateError: A mutation operation was attempted on a database that did not allow mutations.
Blocks: 1440780
Flags: needinfo?(mcooper)
This is definitely a problem with Normandy, but I'm not sure what could be causing it. Good call that this is related to bug 1440780. The code in the traceback was added in that bug. Unfortunately that's about all the traceback can tell me.
Component: General → Normandy Client
Flags: needinfo?(mcooper)
Product: Toolkit → Firefox
Clearing the priority, since I don't think this is a P5 anymore. I've seen this enough in real-life runs that I think there is a problem that the tests aren't testing well enough.
Priority: P5 → --
See Also: → 1490069
Recent occurrences here are all on TV, this did not move to tier1 and seems the spike appeared when Bug 1506816 landed. 

Recent failure log: https://treeherder.mozilla.org/logviewer.html#?job_id=212762424&repo=mozilla-inbound&lineNumber=2976

00:45:08     INFO - TEST-PASS | toolkit/components/normandy/test/browser/browser_actions_AddonStudyAction.js | a start date should be assigned - 
00:45:08     INFO - TEST-PASS | toolkit/components/normandy/test/browser/browser_actions_AddonStudyAction.js | an end date should not be assigned - 
00:45:08     INFO - TEST-PASS | toolkit/components/normandy/test/browser/browser_actions_AddonStudyAction.js | an enrollment event should be sent - [["enroll","addon_study","success",{"addonId":"normandydriver@example.com","addonVersion":"1.0"}]] deepEqual [["enroll","addon_study","success",{"addonId":"normandydriver@example.com","addonVersion":"1.0"}]] - 
00:45:08     INFO - TEST-PASS | toolkit/components/normandy/test/browser/browser_actions_AddonStudyAction.js | sendEvent(unenroll, addon_study, success, {"addonId":"normandydriver@example.com","addonVersion":"1.0","reason":"uninstalled"}) should match spec - 
00:45:08     INFO - TEST-PASS | toolkit/components/normandy/test/browser/browser_actions_AddonStudyAction.js | The add-ons should be same before and after the test - {} deepEqual {} - 
00:45:08     INFO - Buffered messages finished
00:45:08     INFO - TEST-UNEXPECTED-FAIL | toolkit/components/normandy/test/browser/browser_actions_AddonStudyAction.js | Uncaught exception - ConstraintError: A mutation operation in the transaction failed because a constraint was not satisfied.
00:45:08     INFO - Leaving test bound wrappedTestFunction
00:45:08     INFO - Entering test bound wrappedTestFunction
00:45:08     INFO - GECKO(976) | JavaScript error: , line 0: uncaught exception: null
00:45:08     INFO - Console message: [JavaScript Error: "uncaught exception: null"]
00:45:08     INFO - TEST-PASS | toolkit/components/normandy/test/browser/browser_actions_AddonStudyAction.js | unenroll should fail when no study exists - 
00:45:08     INFO - TEST-PASS | toolkit/components/normandy/test/browser/browser_actions_AddonStudyAction.js | The add-ons should be same before and after the test - {} deepEqual {} - 
00:45:08     INFO - Not taking screenshot here: see the one that was previously logged
00:45:08     INFO - TEST-UNEXPECTED-FAIL | toolkit/components/normandy/test/browser/browser_actions_AddonStudyAction.js | A promise chain failed to handle a rejection: (Unable to convert rejection reason to string.) - stack: Transaction/this._completionPromise</transaction.onerror@resource://gre/modules/IndexedDB.jsm:237:9
00:45:08     INFO - EventHandlerNonNull*Transaction/this._completionPromise<@resource://gre/modules/IndexedDB.jsm:236:7
00:45:08     INFO - Transaction@resource://gre/modules/IndexedDB.jsm:234:31
00:45:08     INFO - transaction@resource://gre/modules/IndexedDB.jsm:349:23
00:45:08     INFO - objectStore@resource://gre/modules/IndexedDB.jsm:377:23
00:45:08     INFO - getStore@resource://normandy/lib/AddonStudies.jsm:88:10
00:45:08     INFO - wrappedTestFunction@resource://normandy/lib/AddonStudies.jsm:116:25
00:45:08     INFO - async*wrappedTestFunction@chrome://mochitests/content/browser/toolkit/components/normandy/test/browser/head.js:375:13
00:45:08     INFO - async*wrappedTestFunction@chrome://mochitests/content/browser/toolkit/components/normandy/test/browser/browser_actions_AddonStudyAction.js:33:13
00:45:08     INFO - Async*Tester_execTest/<@chrome://mochikit/content/browser-test.js:1093:34
00:45:08     INFO - async*Tester_execTest@chrome://mochikit/content/browser-test.js:1084:16
00:45:08     INFO - nextTest/<@chrome://mochikit/content/browser-test.js:977:9
00:45:08     INFO - SimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:803:59
00:45:08     INFO - Rejection date: Tue Nov 20 2018 00:45:08 GMT+0000 (Greenwich Mean Time) - false == true - JS frame :: resource://testing-common/PromiseTestUtils.jsm :: assertNoUncaughtRejections :: line 257
00:45:08     INFO - Stack trace:
00:45:08     INFO - resource://testing-common/PromiseTestUtils.jsm:assertNoUncaughtRejections:257
00:45:08     INFO - chrome://mochikit/content/browser-test.js:Tester_execTest/<:1118
00:45:08     INFO - chrome://mochikit/content/browser-test.js:Tester_execTest:1084
00:45:08     INFO - chrome://mochikit/content/browser-test.js:nextTest/<:977
00:45:08     INFO - chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:SimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<:803
00:45:08     INFO - Leaving test bound wrappedTestFunction
00:45:08     INFO - Entering test bound wrappedTestFunction
00:45:08     INFO - TEST-PASS | toolkit/components/normandy/test/browser/browser_actions_AddonStudyAction.js | unenroll should fail when the requested study is inactive - 
00:45:08     INFO - TEST-PASS | toolkit/components/normandy/test/browser/browser_actions_AddonStudyAction.js | The add-ons should be same before and after the test - {} deepEqual {} - 
00:45:08     INFO - Leaving test bound wrappedTestFunction
00:45:08     INFO - Entering test bound wrappedTestFunction
00:45:08     INFO - TEST-PASS | toolkit/components/normandy/test/browser/browser_actions_AddonStudyAction.js | the add-on should be installed before unenrolling -
Whiteboard: [stockwell needswork]
This bug has failed 37 times in the last 7 days. Occurs on all platforms except android.

Here is a recent log:
https://treeherder.mozilla.org/logviewer.html#?job_id=216966193&repo=mozilla-central

07:32:18     INFO - transaction@resource://gre/modules/IndexedDB.jsm:349:23
07:32:18     INFO - objectStore@resource://gre/modules/IndexedDB.jsm:377:23
07:32:18     INFO - getStore@resource://normandy/lib/AddonStudies.jsm:88:10
07:32:18     INFO - wrappedTestFunction@resource://normandy/lib/AddonStudies.jsm:116:25
07:32:18     INFO - async*wrappedTestFunction@chrome://mochitests/content/browser/toolkit/components/normandy/test/browser/head.js:377:13
07:32:18     INFO - async*wrappedTestFunction@chrome://mochitests/content/browser/toolkit/components/normandy/test/browser/browser_actions_AddonStudyAction.js:33:13
07:32:18     INFO - Async*Tester_execTest/<@chrome://mochikit/content/browser-test.js:1093:34
07:32:18     INFO - async*Tester_execTest@chrome://mochikit/content/browser-test.js:1084:16
07:32:18     INFO - nextTest/<@chrome://mochikit/content/browser-test.js:977:9
07:32:18     INFO - SimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:803:59
07:32:18     INFO - Rejection date: Fri Dec 14 2018 07:32:18 GMT+0000 (Greenwich Mean Time) - false == true - JS frame :: resource://testing-common/PromiseTestUtils.jsm :: assertNoUncaughtRejections :: line 257
07:32:18     INFO - Stack trace:
07:32:18     INFO - resource://testing-common/PromiseTestUtils.jsm:assertNoUncaughtRejections:257
07:32:18     INFO - chrome://mochikit/content/browser-test.js:Tester_execTest/<:1118
07:32:18     INFO - chrome://mochikit/content/browser-test.js:Tester_execTest:1084
07:32:18     INFO - chrome://mochikit/content/browser-test.js:nextTest/<:977
07:32:18     INFO - chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:SimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<:803
07:32:18     INFO - Leaving test bound unenrollNonexistent
07:32:18     INFO - Entering test bound 
07:32:18     INFO - TEST-PASS | toolkit/components/normandy/test/browser/browser_actions_AddonStudyAction.js | unenroll should fail when the requested study is inactive - 
07:32:18     INFO - TEST-PASS | toolkit/components/normandy/test/browser/browser_actions_AddonStudyAction.js | The add-ons should be same before and after the test - {} deepEqual {} - 
07:32:18     INFO - Leaving test bound 
07:32:18     INFO - Entering test bound unenrollTest
07:32:18     INFO - TEST-PASS | toolkit/components/normandy/test/browser/browser_actions_AddonStudyAction.js | the add-on should be installed before unenrolling - 
07:32:18     INFO - TEST-PASS | toolkit/components/normandy/test/browser/browser_actions_AddonStudyAction.js | sendEvent(unenroll, addon_study, Test study, {"addonId":"testStop@example.com","addonVersion":"1.0.0","reason":"test-reason"}) should match spec - 
07:32:18     INFO - TEST-PASS | toolkit/components/normandy/test/browser/browser_actions_AddonStudyAction.js | stop should mark the study as inactive - 
07:32:18     INFO - TEST-PASS | toolkit/components/normandy/test/browser/browser_actions_AddonStudyAction.js | the study should have an end date - 
07:32:18     INFO - TEST-PASS | toolkit/components/normandy/test/browser/browser_actions_AddonStudyAction.js | the add-on should be uninstalled after unenrolling - 
07:32:18     INFO - TEST-PASS | toolkit/components/normandy/test/browser/browser_actions_AddonStudyAction.js | an unenroll event should be sent - [["unenroll","addon_study","Test study",{"addonId":"testStop@example.com","addonVersion":"1.0.0","reason":"test-reason"}]] deepEqual [["unenroll","addon_study","Test study",{"addonId":"testStop@example.com","addonVersion":"1.0.0","reason":"test-reason"}]] - 
07:32:18     INFO - TEST-PASS | toolkit/components/normandy/test/browser/browser_actions_AddonStudyAction.js | Add-on should not be unexpectedly uninstalled during test - 
07:32:18     INFO - TEST-PASS | toolkit/components/normandy/test/browser/browser_actions_AddonStudyAction.js | The add-ons should be same before and after the test - {} deepEqual {} -

I spent some time looking at this today. I'll admit mostly ignorance. It seems like this is completely unrelated to the change I made in the linked bug. Here's what I've learned:

  • The successfulEnroll test is failing. It seems to be failing on the second time through when testing with --verify.
  • The failure remains even when you comment out every other test in the file.
  • It isn't the test itself that's failing but rather the restoration part of the AddonStudies.withStudies() decorator.
  • It seems that after the first time through the test, although AddonStudies.withStudies() calls AddonStudies.clear(), the addon study remains visible when you call AddonStudies.getAll(). I'm not certain that this is related to the failure but it seems like more than coincidence.
  • Although we have an ensureAddonCleanup decorator, it only ensures that the addons that are installed are removed, not that the addon studies cleared from the AddonStudies manager.
  • I thought maybe AddonStudies.clear() was returning before the clear actually happened. I tried looping for a while to wait until AddonStudies.getAll() returns an empty list, and even though entire seconds go by, it never does.
  • I think what's happening is that the line in the successfulEnroll test that does await addon.uninstall() is calling the onUninstalled callback asynchronously. This callback updates the state of the addon study by put()ing a record in the database, and I think this is happening after the clear() in AddonStudies.withStudies().
  • Indeed I don't see any asynchrony being respected in either https://searchfox.org/mozilla-central/source/toolkit/mozapps/extensions/AddonManager.jsm#1469-1487 or https://searchfox.org/mozilla-central/source/toolkit/mozapps/extensions/AddonManager.jsm#2863-2865, which is I think what is actually being called.

I'm not really sure what the way forward here is. I think this is the only test that calls this uninstall method -- maybe we could set up some kind of promise that gets resolved when the onUninstalled gets called? Maybe :mythmon has some idea?

Flags: needinfo?(eglassercamp) → needinfo?(mcooper)

Previously, the AddonStudies.onUninstalled would update its internal
information about the addon by doing an IndexedDB.put(). However, in
the meantime, we would have already cleared that IndexedDB, and doing
the put() would save data that we would then carry around from test to
test, and if this test re-ran it would fail.

Taking this from Ethan since it will be fixed by my patch in bug 1474413

Assignee: nobody → rdalal

Clearing my needinfo, since I think Ethan and Rehan have this covered.

Flags: needinfo?(mcooper)

This should have been fixed in bug 1474413.

Status: NEW → RESOLVED
Closed: 5 years ago
Resolution: --- → FIXED
Attachment #9045388 - Attachment is obsolete: true
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Created:
Updated:
Size: