1455931 - Intermittent browser/extensions/activity-stream/test/functional/mochitest/browser_topsites_contextMenu_options.js | A promise chain failed to handle a rejection: cache is undefined - stack: maybeCacheScreenshot@resource://activity-stream/lib/Screenshots

Status: RESOLVED FIXED

(Firefox :: New Tab Page, defect, P5)

Description

[Treeherder Bug Filer]

Filed by: nbeleuzu [at] mozilla.com

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

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

Relevant log info:

23:37:59     INFO - TEST-INFO | started process screencapture
23:37:59     INFO - TEST-INFO | screencapture: exit 0
23:37:59     INFO - Buffered messages logged at 23:37:57
23:37:59     INFO - Entering test bound defaultTopSites_menuOptions
23:37:59     INFO - Buffered messages logged at 23:37:58
23:37:59     INFO - Console message: [JavaScript Error: "Problem getting stored prefs for TopSites" {file: "resource://activity-stream/lib/TopSitesFeed.jsm" line: 182}]
23:37:59     INFO - refresh@resource://activity-stream/lib/TopSitesFeed.jsm:182:7
23:37:59     INFO - async*onAction@resource://activity-stream/lib/TopSitesFeed.jsm:398:9
23:37:59     INFO - _middleware/</<@resource://activity-stream/lib/Store.jsm:51:11
23:37:59     INFO - Store/this[method]@resource://activity-stream/lib/Store.jsm:29:55
23:37:59     INFO - customDispatch/this.placesChangedTimer<@resource://activity-stream/lib/PlacesFeed.jsm:205:11
23:37:59     INFO - 
23:37:59     INFO - Console message: [JavaScript Error: "TypeError: cache is undefined" {file: "resource://activity-stream/lib/Screenshots.jsm" line: 125}]
23:37:59     INFO - Console message: [JavaScript Error: "TypeError: cache is undefined" {file: "resource://activity-stream/lib/Screenshots.jsm" line: 125}]
23:37:59     INFO - Console message: [JavaScript Error: "TypeError: cache is undefined" {file: "resource://activity-stream/lib/Screenshots.jsm" line: 125}]
23:37:59     INFO - Console message: [JavaScript Error: "TypeError: cache is undefined" {file: "resource://activity-stream/lib/Screenshots.jsm" line: 125}]
23:37:59     INFO - Console message: [JavaScript Error: "TypeError: cache is undefined" {file: "resource://activity-stream/lib/Screenshots.jsm" line: 125}]
23:37:59     INFO - Console message: [JavaScript Error: "TypeError: cache is undefined" {file: "resource://activity-stream/lib/Screenshots.jsm" line: 125}]
23:37:59     INFO - TEST-PASS | browser/extensions/activity-stream/test/functional/mochitest/browser_topsites_contextMenu_options.js | Number of options is correct - 5 == 5 - 
23:37:59     INFO - TEST-PASS | browser/extensions/activity-stream/test/functional/mochitest/browser_topsites_contextMenu_options.js | Name option is correct - "Pin" == "Pin" - 
23:37:59     INFO - TEST-PASS | browser/extensions/activity-stream/test/functional/mochitest/browser_topsites_contextMenu_options.js | Name option is correct - "Edit" == "Edit" - 
23:37:59     INFO - TEST-PASS | browser/extensions/activity-stream/test/functional/mochitest/browser_topsites_contextMenu_options.js | Name option is correct - "Open in a New Window" == "Open in a New Window" - 
23:37:59     INFO - TEST-PASS | browser/extensions/activity-stream/test/functional/mochitest/browser_topsites_contextMenu_options.js | Name option is correct - "Open in a New Private Window" == "Open in a New Private Window" - 
23:37:59     INFO - TEST-PASS | browser/extensions/activity-stream/test/functional/mochitest/browser_topsites_contextMenu_options.js | Name option is correct - "Dismiss" == "Dismiss" - 
23:37:59     INFO - Buffered messages finished
23:37:59     INFO - TEST-UNEXPECTED-FAIL | browser/extensions/activity-stream/test/functional/mochitest/browser_topsites_contextMenu_options.js | A promise chain failed to handle a rejection: cache is undefined - stack: maybeCacheScreenshot@resource://activity-stream/lib/Screenshots.jsm:125:1
23:37:59     INFO - async*_fetchScreenshot@resource://activity-stream/lib/TopSitesFeed.jsm:226:11
23:37:59     INFO - async*_fetchIcon@resource://activity-stream/lib/TopSitesFeed.jsm:214:11
23:37:59     INFO - async*getLinksWithDefaults@resource://activity-stream/lib/TopSitesFeed.jsm:159:11
23:37:59     INFO - async*refresh@resource://activity-stream/lib/TopSitesFeed.jsm:175:25
23:37:59     INFO - async*onAction@resource://activity-stream/lib/TopSitesFeed.jsm:398:9
23:37:59     INFO - _middleware/</<@resource://activity-stream/lib/Store.jsm:51:11
23:37:59     INFO - Store/this[method]@resource://activity-stream/lib/Store.jsm:29:55
23:37:59     INFO - customDispatch/this.placesChangedTimer<@resource://activity-stream/lib/PlacesFeed.jsm:205:11
23:37:59     INFO - Rejection date: Sat Apr 21 2018 23:37:58 GMT-0700 (PDT) - false == true - JS frame :: resource://testing-common/PromiseTestUtils.jsm :: assertNoUncaughtRejections :: line 257
23:37:59     INFO - Stack trace:
23:37:59     INFO - resource://testing-common/PromiseTestUtils.jsm:assertNoUncaughtRejections:257
23:37:59     INFO - chrome://mochikit/content/browser-test.js:Tester_execTest/<:1103
23:37:59     INFO - Not taking screenshot here: see the one that was previously logged
23:37:59     INFO - TEST-UNEXPECTED-FAIL | browser/extensions/activity-stream/test/functional/mochitest/browser_topsites_contextMenu_options.js | A promise chain failed to handle a rejection: cache is undefined - stack: maybeCacheScreenshot@resource://activity-stream/lib/Screenshots.jsm:125:1
23:37:59     INFO - async*_fetchScreenshot@resource://activity-stream/lib/TopSitesFeed.jsm:226:11
23:37:59     INFO - async*_fetchIcon@resource://activity-stream/lib/TopSitesFeed.jsm:214:11
23:37:59     INFO - async*getLinksWithDefaults@resource://activity-stream/lib/TopSitesFeed.jsm:159:11
23:37:59     INFO - async*refresh@resource://activity-stream/lib/TopSitesFeed.jsm:175:25
23:37:59     INFO - async*onAction@resource://activity-stream/lib/TopSitesFeed.jsm:398:9
23:37:59     INFO - _middleware/</<@resource://activity-stream/lib/Store.jsm:51:11
23:37:59     INFO - Store/this[method]@resource://activity-stream/lib/Store.jsm:29:55
23:37:59     INFO - customDispatch/this.placesChangedTimer<@resource://activity-stream/lib/PlacesFeed.jsm:205:11
23:37:59     INFO - Rejection date: Sat Apr 21 2018 23:37:58 GMT-0700 (PDT) - false == true - JS frame :: resource://testing-common/PromiseTestUtils.jsm :: assertNoUncaughtRejections :: line 257
23:37:59     INFO - Stack trace:
23:37:59     INFO - resource://testing-common/PromiseTestUtils.jsm:assertNoUncaughtRejections:257
23:37:59     INFO - chrome://mochikit/content/browser-test.js:Tester_execTest/<:1103
23:37:59     INFO - Not taking screenshot here: see the one that was previously logged

Comment 1

[Intermittent Failures Robot]

5 failures in 782 pushes (0.006 failures/push) were associated with this bug in the last 7 days.    

Repository breakdown:
* mozilla-inbound: 2
* autoland: 2
* try: 1

Platform breakdown:
* osx-10-10: 5

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1455931&startday=2018-04-16&endday=2018-04-22&tree=trunk

Comment 2

[Cosmin Sabou [:CosminS]]

Hi! I did some retriggers to find where this started and worked on this range: http://tinyurl.com/yb4s53lr

It seems the push that started this fail is this one http://tinyurl.com/ybpa7laf and has at least two follow-ups. It fails around 2 times from 20 jobs.
Kris, could you take a look at this? Thank you

Comment 3

[Kris Maglione [:kmag]]

I can't see any reason those changes should affect activity stream. My best guess is that it's relying on callback timing that isn't guaranteed, but I don't know that code nearly well enough to say for sure.

Comment 4

[Ed Lee :Mardak]

(In reply to Treeherder Bug Filer from comment #0)
> 23:37:59     INFO - Console message: [JavaScript Error: "Problem getting
> stored prefs for TopSites" {file:
> "resource://activity-stream/lib/TopSitesFeed.jsm" line: 182}]
This first error is from the recently added indexeddb storage. andreio, any ideas?

Comment 5

[Andrei Oprea [:andreio]]

The indexedDB error should be irrelevant that's just a logging message (we expect it to fail sometimes) and it should continue to run anyway. The failure seems to be related to screenshots, although there are only default topsites (which already have icons) in the screenshot. I'll look into it.

Comment 6

[Andrei Oprea [:andreio]]

Running this locally I see a completely different stack trace which oddly enough contains the same variable name `cache`

0:16.42 INFO Console message: [JavaScript Error: "cache is null" {file: "resource://gre/modules/NewTabUtils.jsm" line: 1673}]
_adjustSiteMapAndNotify@resource://gre/modules/NewTabUtils.jsm:1673:1
onLinkBlocked@resource://gre/modules/NewTabUtils.jsm:1685:5
_callObservers@resource://gre/modules/NewTabUtils.jsm:515:27
BlockedLinks_block@resource://gre/modules/NewTabUtils.jsm:461:5
blockURL@resource://gre/modules/NewTabUtils.jsm:1262:5
onAction@resource://activity-stream/lib/PlacesFeed.jsm:294:9
_middleware/</<@resource://activity-stream/lib/Store.jsm:51:11
Store/this[method]@resource://activity-stream/lib/Store.jsm:29:55
onActionFromContent@resource://activity-stream/lib/ActivityStreamMessageChannel.jsm:87:5
onMessage@resource://activity-stream/lib/ActivityStreamMessageChannel.jsm:275:5
callListeners@resource://gre/modules/RemotePageManager.jsm:33:9
portMessageReceived@resource://gre/modules/RemotePageManager.jsm:123:5
callListeners@resource://gre/modules/RemotePageManager.jsm:33:9
ChromeMessagePort.prototype.message@resource://gre/modules/RemotePageManager.jsm:381:3
MessageListener.receiveMessage*MessagePort@resource://gre/modules/RemotePageManager.jsm:235:3
ChromeMessagePort@resource://gre/modules/RemotePageManager.jsm:312:3
initPort@resource://gre/modules/RemotePageManager.jsm:527:16
MessageListener.receiveMessage*init@resource://gre/modules/RemotePageManager.jsm:478:5
@resource://gre/modules/RemotePageManager.jsm:533:3
@chrome://global/content/process-content.js:10:1
observe@file:///mozilla-central/objdir-frontend/dist/Nightly.app/Contents/Resources/components/MainProcessSingleton.js:72:7

Comment 7

[Ursula Sarracini (:ursula)]

That error, "cache is null" is from legacy NewTabUtils code and shouldn't be affecting activity stream stuff. It was a cache for the old tiles, not our cache. When we get rid of old NewTabUtils stuff for tiles, that error will go away. Unlikely that it's the cause of this failure (we even see that error while dismissing a top site in regular browser usage)

Comment 8

[Andrei Oprea [:andreio]]

Triggered the failure on try with a little bit of logging. We're trying to take screenshots of default sites which are not LinkCache objects.

06:52:31     INFO - GECKO(2033) | console.log: "Getting screenshot for" "https://www.youtube.com/"
06:52:31     INFO - GECKO(2033) | console.log: "Getting screenshot for" "https://www.facebook.com/"
06:52:31     INFO - GECKO(2033) | console.log: "Getting screenshot for" "https://www.amazon.com/"
06:52:31     INFO - GECKO(2033) | console.log: "Getting screenshot for" "https://www.reddit.com/"
06:52:31     INFO - GECKO(2033) | console.log: "Getting screenshot for" "https://www.wikipedia.org/"
06:52:31     INFO - GECKO(2033) | console.log: "Getting screenshot for" "https://twitter.com/"
06:52:31     INFO - GECKO(2033) | JavaScript error: resource://activity-stream/lib/Screenshots.jsm, line 126: TypeError: cache is undefined
06:52:31     INFO - GECKO(2033) | JavaScript error: resource://activity-stream/lib/Screenshots.jsm, line 126: TypeError: cache is undefined
06:52:31     INFO - GECKO(2033) | JavaScript error: resource://activity-stream/lib/Screenshots.jsm, line 126: TypeError: cache is undefined
06:52:31     INFO - GECKO(2033) | JavaScript error: resource://activity-stream/lib/Screenshots.jsm, line 126: TypeError: cache is undefined
06:52:31     INFO - GECKO(2033) | JavaScript error: resource://activity-stream/lib/Screenshots.jsm, line 126: TypeError: cache is undefined
06:52:31     INFO - GECKO(2033) | JavaScript error: resource://activity-stream/lib/Screenshots.jsm, line 126: TypeError: cache is undefined

https://treeherder.mozilla.org/logviewer.html#?job_id=175531672&repo=try&lineNumber=12019-12030

Comment 9

[Ed Lee :Mardak]

I would guess that some action is triggering a top sites refresh before TippyTopProvider.jsm is done initializing. The stack seems to point to PLACES_LINKS_CHANGED.

So something in places is changing while activity stream is starting up?

Comment 10

[Ed Lee :Mardak]

Sounds like this could have regressed with bug 1449223 no longer awaiting for tippy top to be initialized:
https://github.com/mozilla/activity-stream/pull/4060/files#diff-3c9ab687b10408604222f1cb5b298d0eL168

Comment 11

[GitHub Bugzilla PR Linker]

Attachment: Link to GitHub pull-request: https://github.com/mozilla/activity-stream/pull/4124

Comment 12

[[github robot]]

Commit pushed to master at https://github.com/mozilla/activity-stream

https://github.com/mozilla/activity-stream/commit/9a5e4d28dfba6a603d5b0f2210097a03c2973481
fix(topsites): Restore refresh waiting for tippytop provider to initialize (#4124)

Fix Bug 1455931 - Intermittent browser/extensions/activity-stream/test/functional/mochitest/browser_topsites_contextMenu_options.js | A promise chain failed to handle a rejection: cache is undefined - stack: maybeCacheScreenshot@resource://activity-stream/lib/Screenshots

Comment 13

[Ed Lee :Mardak]

Keeping open until the fix lands in m-c, so it can still be starred

Comment 14

[Ed Lee :Mardak]

https://hg.mozilla.org/mozilla-central/rev/9edd64fc07d3

Comment 15

[Intermittent Failures Robot]

33 failures in 780 pushes (0.042 failures/push) were associated with this bug in the last 7 days.   

** This failure happened more than 30 times this week! Resolving this bug is a high priority. **

** Try to resolve this bug as soon as possible. If unresolved for 2 weeks, the affected test(s) may be disabled. **  

Repository breakdown:
* mozilla-inbound: 16
* autoland: 15
* mozilla-central: 1
* mozilla-beta: 1

Platform breakdown:
* osx-10-10: 32
* windows10-64: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1455931&startday=2018-04-23&endday=2018-04-29&tree=trunk