Closed Bug 1275958 Opened 3 years ago Closed 3 years ago

Intermittent jetpack-package/addon-sdk/source/test/test-clipboard.js.test Get Image | Test timed out (after: START) | Should not be any unexpected tabs open

Categories

(Add-on SDK Graveyard :: General, defect)

defect
Not set

Tracking

(firefox-esr52 fixed, firefox53 fixed, firefox54 fixed, firefox55 fixed)

RESOLVED FIXED
mozilla55
Tracking Status
firefox-esr52 --- fixed
firefox53 --- fixed
firefox54 --- fixed
firefox55 --- fixed

People

(Reporter: RyanVM, Assigned: rpl)

Details

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

Attachments

(1 file)

keeping an eye on this, the failures are increasing, but not over our 30 failures/week threshold yet.
this has picked up in frequency in the last week on March 7th, mostly on linux64-debug e10s.


here is a clip from a recent log:
[task 2017-03-10T12:15:18.539780Z] 12:15:18     INFO -  TEST-START | jetpack-package/addon-sdk/source/test/test-clipboard.js.test Get Image
[task 2017-03-10T12:15:18.547747Z] 12:15:18     INFO -  [Parent 7462] WARNING: Oh no, couldn't write data to the cache file: file /home/worker/workspace/build/src/widget/nsTransferable.cpp, line 73
[task 2017-03-10T12:15:18.854925Z] 12:15:18     INFO -  [Parent 7462] WARNING: NS_ENSURE_TRUE(standardURL) failed: file /home/worker/workspace/build/src/caps/nsPrincipal.cpp, line 229
[task 2017-03-10T12:15:18.865300Z] 12:15:18     INFO -  ### XPCOM_MEM_BLOAT_LOG defined -- logging bloat/leaks to /tmp/tmpiETgU2.mozrunner/runtests_leaks_tab_pid7569.log
[task 2017-03-10T12:15:18.926232Z] 12:15:18     INFO -  [Child 7569] WARNING: '!compMgr', file /home/worker/workspace/build/src/xpcom/components/nsComponentManagerUtils.cpp, line 63
[task 2017-03-10T12:15:19.056600Z] 12:15:19     INFO -  ++DOCSHELL 0x7fc34688d800 == 7 [pid = 7462] [id = {b95382d9-8543-4c11-9566-f54ff1efcb9c}]
[task 2017-03-10T12:15:19.057429Z] 12:15:19     INFO -  ++DOMWINDOW == 15 (0x7fc338990c00) [pid = 7462] [serial = 15] [outer = (nil)]
[task 2017-03-10T12:15:19.140734Z] 12:15:19     INFO -  [Child 7569] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80004005: file /home/worker/workspace/build/src/toolkit/xre/nsXREDirProvider.cpp, line 1699
[task 2017-03-10T12:15:19.223906Z] 12:15:19     INFO -  [Parent 7462] WARNING: NS_ENSURE_TRUE(standardURL) failed: file /home/worker/workspace/build/src/caps/nsPrincipal.cpp, line 229
[task 2017-03-10T12:15:19.224184Z] 12:15:19     INFO -  ++DOMWINDOW == 16 (0x7fc33888e800) [pid = 7462] [serial = 16] [outer = 0x7fc338990c00]
[task 2017-03-10T12:15:19.224386Z] 12:15:19     INFO -  [Parent 7462] WARNING: NS_ENSURE_TRUE(standardURL) failed: file /home/worker/workspace/build/src/caps/nsPrincipal.cpp, line 229
[task 2017-03-10T12:15:19.224961Z] 12:15:19     INFO -  [Parent 7462] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80004005: file /home/worker/workspace/build/src/extensions/cookie/nsPermissionManager.cpp, line 107
[task 2017-03-10T12:15:19.225127Z] 12:15:19     INFO -  [Parent 7462] WARNING: 'NS_FAILED(aResult)', file /home/worker/workspace/build/src/extensions/cookie/nsPermissionManager.cpp, line 614
[task 2017-03-10T12:15:19.225285Z] 12:15:19     INFO -  [Parent 7462] WARNING: NS_ENSURE_TRUE(standardURL) failed: file /home/worker/workspace/build/src/caps/nsPrincipal.cpp, line 229
[task 2017-03-10T12:15:19.226033Z] 12:15:19     INFO -  [Parent 7462] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80004005: file /home/worker/workspace/build/src/extensions/cookie/nsPermissionManager.cpp, line 107
[task 2017-03-10T12:15:19.226795Z] 12:15:19     INFO -  [Parent 7462] WARNING: 'NS_FAILED(aResult)', file /home/worker/workspace/build/src/extensions/cookie/nsPermissionManager.cpp, line 614
[task 2017-03-10T12:15:19.241036Z] 12:15:19     INFO -  [Parent 7462] WARNING: NS_ENSURE_TRUE(standardURL) failed: file /home/worker/workspace/build/src/caps/nsPrincipal.cpp, line 229
[task 2017-03-10T12:15:19.241155Z] 12:15:19     INFO -  [Parent 7462] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80004005: file /home/worker/workspace/build/src/extensions/cookie/nsPermissionManager.cpp, line 107
[task 2017-03-10T12:15:19.242024Z] 12:15:19     INFO -  [Parent 7462] WARNING: 'NS_FAILED(aResult)', file /home/worker/workspace/build/src/extensions/cookie/nsPermissionManager.cpp, line 614
[task 2017-03-10T12:15:19.430054Z] 12:15:19     INFO -  ++DOMWINDOW == 17 (0x7fc338c43800) [pid = 7462] [serial = 17] [outer = 0x7fc338990c00]
[task 2017-03-10T12:15:19.453932Z] 12:15:19     INFO -  TEST-INFO | [JavaScript Warning: "Use of nsIFile in content process is deprecated." {file: "resource://gre/modules/commonjs/toolkit/loader.js" line: 278}]
[task 2017-03-10T12:15:19.833485Z] 12:15:19     INFO -  [Parent 7462] WARNING: GetDefaultCharsetForLocale: need to add multi locale support: file /home/worker/workspace/build/src/intl/locale/unix/nsUNIXCharset.cpp, line 98
[task 2017-03-10T12:15:19.855244Z] 12:15:19     INFO -  [Parent 7462] WARNING: 'NS_FAILED(rv)', file /home/worker/workspace/build/src/dom/xhr/XMLHttpRequestMainThread.cpp, line 2000
[task 2017-03-10T12:15:19.871183Z] 12:15:19     INFO -  [Parent 7462] WARNING: 'NS_FAILED(rv)', file /home/worker/workspace/build/src/dom/xhr/XMLHttpRequestMainThread.cpp, line 2000
[task 2017-03-10T12:15:19.915275Z] 12:15:19     INFO -  ++DOCSHELL 0x7f92b7b50000 == 1 [pid = 7569] [id = {b09865db-34f3-49f1-aa03-385a999a1b86}]
[task 2017-03-10T12:15:19.935927Z] 12:15:19     INFO -  ++DOMWINDOW == 1 (0x7f92b7be1400) [pid = 7569] [serial = 1] [outer = (nil)]
[task 2017-03-10T12:15:19.998321Z] 12:15:19     INFO -  [Parent 7462] WARNING: 'NS_FAILED(rv)', file /home/worker/workspace/build/src/dom/xhr/XMLHttpRequestMainThread.cpp, line 2000
[task 2017-03-10T12:15:20.147134Z] 12:15:20     INFO -  [Child 7569] WARNING: NS_ENSURE_TRUE(standardURL) failed: file /home/worker/workspace/build/src/caps/nsPrincipal.cpp, line 229
[task 2017-03-10T12:15:20.147593Z] 12:15:20     INFO -  ++DOMWINDOW == 2 (0x7f92b146e000) [pid = 7569] [serial = 2] [outer = 0x7f92b7be1400]
[task 2017-03-10T12:15:20.168563Z] 12:15:20     INFO -  [Child 7569] WARNING: NS_ENSURE_TRUE(standardURL) failed: file /home/worker/workspace/build/src/caps/nsPrincipal.cpp, line 229
[task 2017-03-10T12:15:20.168801Z] 12:15:20     INFO -  [Child 7569] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80004005: file /home/worker/workspace/build/src/extensions/cookie/nsPermissionManager.cpp, line 107
[task 2017-03-10T12:15:20.168950Z] 12:15:20     INFO -  [Child 7569] WARNING: 'NS_FAILED(aResult)', file /home/worker/workspace/build/src/extensions/cookie/nsPermissionManager.cpp, line 614
[task 2017-03-10T12:15:20.169081Z] 12:15:20     INFO -  [Child 7569] WARNING: NS_ENSURE_TRUE(standardURL) failed: file /home/worker/workspace/build/src/caps/nsPrincipal.cpp, line 229
[task 2017-03-10T12:15:20.170029Z] 12:15:20     INFO -  [Child 7569] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80004005: file /home/worker/workspace/build/src/extensions/cookie/nsPermissionManager.cpp, line 107
[task 2017-03-10T12:15:20.170503Z] 12:15:20     INFO -  [Child 7569] WARNING: 'NS_FAILED(aResult)', file /home/worker/workspace/build/src/extensions/cookie/nsPermissionManager.cpp, line 614
[task 2017-03-10T12:15:20.189389Z] 12:15:20     INFO -  [Child 7569] WARNING: NS_ENSURE_TRUE(standardURL) failed: file /home/worker/workspace/build/src/caps/nsPrincipal.cpp, line 229
[task 2017-03-10T12:15:20.190452Z] 12:15:20     INFO -  [Child 7569] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80004005: file /home/worker/workspace/build/src/extensions/cookie/nsPermissionManager.cpp, line 107
[task 2017-03-10T12:15:20.190848Z] 12:15:20     INFO -  [Child 7569] WARNING: 'NS_FAILED(aResult)', file /home/worker/workspace/build/src/extensions/cookie/nsPermissionManager.cpp, line 614
[task 2017-03-10T12:15:20.548966Z] 12:15:20     INFO -  [Child 7569] WARNING: NS_ENSURE_TRUE(standardURL) failed: file /home/worker/workspace/build/src/caps/nsPrincipal.cpp, line 229
[task 2017-03-10T12:15:20.549367Z] 12:15:20     INFO -  [Child 7569] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80004005: file /home/worker/workspace/build/src/caps/BasePrincipal.cpp, line 289
[task 2017-03-10T12:15:20.549715Z] 12:15:20     INFO -  [Child 7569] WARNING: 'NS_FAILED(rv)', file /home/worker/workspace/build/src/dom/workers/ServiceWorkerManager.cpp, line 1976
[task 2017-03-10T12:15:20.550021Z] 12:15:20     INFO -  [Child 7569] WARNING: NS_ENSURE_TRUE(standardURL) failed: file /home/worker/workspace/build/src/caps/nsPrincipal.cpp, line 229
[task 2017-03-10T12:15:20.550325Z] 12:15:20     INFO -  [Child 7569] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80004005: file /home/worker/workspace/build/src/extensions/cookie/nsPermissionManager.cpp, line 107
[task 2017-03-10T12:15:20.550977Z] 12:15:20     INFO -  [Child 7569] WARNING: 'NS_FAILED(aResult)', file /home/worker/workspace/build/src/extensions/cookie/nsPermissionManager.cpp, line 614
[task 2017-03-10T12:15:20.768619Z] 12:15:20     INFO -  [Parent 7462] WARNING: NS_ENSURE_TRUE(standardURL) failed: file /home/worker/workspace/build/src/caps/nsPrincipal.cpp, line 229
[task 2017-03-10T12:15:20.917648Z] 12:15:20     INFO -  TEST-INFO | [JavaScript Warning: "Use of nsIFile in content process is deprecated." {file: "resource://gre/modules/commonjs/toolkit/loader.js" line: 278}]
[task 2017-03-10T12:15:24.096772Z] 12:15:24     INFO -  --DOCSHELL 0x7fc344d5f000 == 6 [pid = 7462] [id = {7381fc8e-b696-47bb-8df6-1ad07c8ba8c3}]
[task 2017-03-10T12:15:34.543047Z] 12:15:34     INFO -  --DOMWINDOW == 16 (0x7fc33888e800) [pid = 7462] [serial = 16] [outer = (nil)] [url = about:blank]
[task 2017-03-10T12:15:34.543287Z] 12:15:34     INFO -  --DOMWINDOW == 15 (0x7fc3536ad800) [pid = 7462] [serial = 2] [outer = (nil)] [url = about:blank]
[task 2017-03-10T12:15:34.543577Z] 12:15:34     INFO -  --DOMWINDOW == 14 (0x7fc33a482800) [pid = 7462] [serial = 13] [outer = (nil)] [url = about:blank]
[task 2017-03-10T12:15:36.372201Z] 12:15:36     INFO -  --DOMWINDOW == 3 (0x7f2295c84800) [pid = 7528] [serial = 2] [outer = (nil)] [url = about:blank]
[task 2017-03-10T12:15:36.372416Z] 12:15:36     INFO -  --DOMWINDOW == 2 (0x7f2295c86800) [pid = 7528] [serial = 3] [outer = (nil)] [url = about:blank]
[task 2017-03-10T12:15:36.992682Z] 12:15:36     INFO -  --DOMWINDOW == 13 (0x7fc344da6800) [pid = 7462] [serial = 8] [outer = (nil)] [url = about:blank]
[task 2017-03-10T12:15:42.744153Z] 12:15:42     INFO -  --DOMWINDOW == 12 (0x7fc344b7a000) [pid = 7462] [serial = 9] [outer = (nil)] [url = about:blank]
[task 2017-03-10T12:20:18.542115Z] 12:20:18  WARNING -  TEST-UNEXPECTED-FAIL | jetpack-package/addon-sdk/source/test/test-clipboard.js.test Get Image | Test timed out (after: START)
[task 2017-03-10T12:20:18.571266Z] 12:20:18     INFO -  TEST-INFO | Traceback (most recent call last):
[task 2017-03-10T12:20:18.571367Z] 12:20:18     INFO -    File "resource://gre/modules/commonjs/sdk/timers.js", line 40, in notify
[task 2017-03-10T12:20:18.571418Z] 12:20:18     INFO -      callback.apply(null, args);
[task 2017-03-10T12:20:18.571487Z] 12:20:18     INFO -    File "resource://gre/modules/commonjs/sdk/deprecated/unit-test.js", line 505, in tiredOfWaiting
[task 2017-03-10T12:20:18.571542Z] 12:20:18     INFO -      self.console.testMessage(false, false, self.test.name,
[task 2017-03-10T12:20:18.571604Z] 12:20:18     INFO -    File "resource://gre/modules/commonjs/sdk/test/harness.js", line 541, in testMessage
[task 2017-03-10T12:20:18.571665Z] 12:20:18     INFO -      this.trace();
[task 2017-03-10T12:20:18.571880Z] 12:20:18     INFO -  TEST-PASS | jetpack-package/addon-sdk/source/test/test-clipboard.js.test Get Image | This test is done.
[task 2017-03-10T12:20:18.574932Z] 12:20:18  WARNING -  TEST-UNEXPECTED-FAIL | jetpack-package/addon-sdk/source/test/test-clipboard.js.test Get Image | Should not be any unexpected tabs open
[task 2017-03-10T12:20:18.611136Z] 12:20:18     INFO -  TEST-INFO | Traceback (most recent call last):
[task 2017-03-10T12:20:18.611571Z] 12:20:18     INFO -    File "resource://gre/modules/Promise-backend.js", line 806, in walkerLoop
[task 2017-03-10T12:20:18.611882Z] 12:20:18     INFO -      this.handlers.shift().process();
[task 2017-03-10T12:20:18.612362Z] 12:20:18     INFO -    File "resource://gre/modules/Promise-backend.js", line 922, in process
[task 2017-03-10T12:20:18.612823Z] 12:20:18     INFO -      nextValue = this.onResolve.call(undefined, nextValue);
[task 2017-03-10T12:20:18.613221Z] 12:20:18     INFO -    File "resource://gre/modules/commonjs/sdk/deprecated/unit-test.js", line 345, in done/<
[task 2017-03-10T12:20:18.613598Z] 12:20:18     INFO -      this.fail("Should not be any unexpected tabs open");
[task 2017-03-10T12:20:18.614001Z] 12:20:18     INFO -    File "resource://gre/modules/commonjs/sdk/deprecated/unit-test.js", line 104, in fail
[task 2017-03-10T12:20:18.614469Z] 12:20:18     INFO -      this.console.testMessage(false, false, this.test.name, message);
[task 2017-03-10T12:20:18.614906Z] 12:20:18     INFO -    File "resource://gre/modules/commonjs/sdk/test/harness.js", line 541, in testMessage
[task 2017-03-10T12:20:18.615267Z] 12:20:18     INFO -      this.trace();
[task 2017-03-10T12:20:18.615736Z] 12:20:18     INFO -  TEST-INFO | Windows open:
[task 2017-03-10T12:20:18.616200Z] 12:20:18     INFO -  TEST-INFO | chrome://browser/content/browser.xul - about:blank, data:text/html,%3Chtml%3E%20%20%20%20%3Cbody%3E%20%20%20%20%20%20%3Ccanvas%20width%3D'32'%20height%3D'32'%3E%3C%2Fcanvas%3E%20%20%20%20%3C%2Fbody%3E%20%20%3C%2Fhtml%3E
[task 2017-03-10T12:20:18.690509Z] 12:20:18     INFO -  TEST-PASS | jetpack-package/addon-sdk/source/test/test-clipboard.js.test Get Image | There is a clean UI.
[task 2017-03-10T12:20:18.733302Z] 12:20:18     INFO -  TEST-END | jetpack-package/addon-sdk/source/test/test-clipboard.js.test Get Image


and a link to the full log:
https://public-artifacts.taskcluster.net/PYuVe0BDSD-CABcAACzxgA/0/public/logs/live_backing.log


:mossop, do you know who would be able to look into this? (there is no triage owner for this component and I don't know who to bug for jetpack tests)
Flags: needinfo?(dtownsend)
Whiteboard: [stockwell needswork]
I think Luca is the first point of contact here. Andym should probably be the triage owner though.
Flags: needinfo?(dtownsend) → needinfo?(lgreco)
I took a brief look at this, the reason of the intermittent is not related to the SDK clipboard API, it is related to the SDK tabs API used by the "Get Image" test case:
When the test fails, the `comparePixelImages` utility function has never  received the expected onReady event from the tab opened by the utility function itself.

I increased the logging on the SDK tabs-firefox.js and tab-events.js internal modules to get more information about the issue, and it looks like that the onReady event is not fired because the document's "readyState" is already "complete" when the SDK framescript send the "sdk/tab/event" of type "init" (http://searchfox.org/mozilla-central/rev/ef0b6a528e0e7b354ddf8cdce08392be8b8ca679/addon-sdk/source/lib/sdk/content/tab-events.js#57) and in that case no tab event is fired, because it is filtered out as for the existent tabs (tabs that already exists when the addon has been installed): http://searchfox.org/mozilla-central/rev/ef0b6a528e0e7b354ddf8cdce08392be8b8ca679/addon-sdk/source/lib/sdk/tabs/tab-firefox.js#322-326

I'm currently using "./mach mochitest addon-sdk/source/test/test-clipboard.js --run-until-failure --repeat 200" to reproduce the failure locally and see if we can "hg bisect" the issue, but the commits that I've got so far do not look as related (which is probably due to the command that I'm using to bisect the issue is failing to mark as "bad" some of the tested commits).
:rpl, thanks for looking into this and it sounds promising that we can fix this!  I don't know if finding a root cause is going to work as this bug has been around for a long time and has increased in frequency lately.
:rpl, at this current rate we are on trend for even more failures than last week- just a reminder that we want to see this fixed in the short term.
Attachment #8848066 - Flags: review?(dtownsend)
Hi :jmaher,
My apologies for the waiting time.

The attached patch rewrites the "test Get Image" clipboard test case to get a canvas neeed to check that the image read from the clipboard has the same pixels of the expected image from the hiddenWindow instead of using a new tab.

This should fix the intermittency (given that the intermittency is due to the tabs API ready event not being received when expected), and as a nice side-effect this test file should now run faster (given that there isn't the latency due to opening a new tab and waiting for the port messages that provides the image URLs to be checked using the canvas element).

I'm still curious about what has generated an higher rate of failures (which in other words means that the onReady is being missed with an higher rate than before), but given how many times this test is failing and that the target of the test case is not ensuring that the tabs SDK API does not miss the onReady event but testing that the clipboard API is working correctly, I think that rewriting this test to fix its intermittency can be a reasonable choice.
Flags: needinfo?(lgreco)
Comment on attachment 8848066 [details]
Bug 1275958 - Rewrite SDK 'Get Image' clipboard test to prevent its intermittent failures.

https://reviewboard.mozilla.org/r/121040/#review123018
Attachment #8848066 - Flags: review?(dtownsend) → review+
Assignee: nobody → lgreco
Status: NEW → ASSIGNED
Keywords: checkin-needed
thanks for the patch and review, excited to see this fixed
Whiteboard: [stockwell needswork] → [stockwell fixed]
Pushed by ryanvm@gmail.com:
https://hg.mozilla.org/integration/autoland/rev/fc2516eb9423
Rewrite SDK 'Get Image' clipboard test to prevent its intermittent failures. r=mossop
Keywords: checkin-needed
https://hg.mozilla.org/mozilla-central/rev/fc2516eb9423
Status: ASSIGNED → RESOLVED
Closed: 3 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla55
You need to log in before you can comment on or make changes to this bug.