Closed Bug 1257746 Opened 8 years ago Closed 8 years ago

Intermittent browser_social_chatwindow.js | Test timed out followed by a slew of failures in other Social tests

Categories

(Firefox Graveyard :: SocialAPI, defect)

defect
Not set
normal

Tracking

(firefox48 fixed)

RESOLVED FIXED
Firefox 48
Tracking Status
firefox48 --- fixed

People

(Reporter: RyanVM, Assigned: mixedpuppy)

References

Details

(Keywords: intermittent-failure)

Attachments

(1 file)

So much for that idea. This is failing pretty frequently on OSX and Windows since bug 898706 landed.

https://treeherder.mozilla.org/logviewer.html#?job_id=8093986&repo=fx-team

18:33:50     INFO -  98 INFO TEST-START | browser/base/content/test/social/browser_social_chatwindow.js
18:33:51     INFO -  JavaScript error: jar:file:///C:/slave/test/build/application/firefox/omni.ja!/components/Weave.js, line 13: NS_ERROR_NOT_AVAILABLE: Component returned failure code: 0x80040111 (NS_ERROR_NOT_AVAILABLE) [nsIXPCComponents_Utils.import]
18:35:20     INFO -  TEST-INFO | started process screenshot
18:35:20     INFO -  TEST-INFO | screenshot: exit 0
18:35:20     INFO -  99 INFO checking window state
18:35:20     INFO -  100 INFO runSocialTestWithProvider: [{name:"provider@example.com", origin:"https://example.com", sidebarURL:"https://example.com/browser/browser/base/content/test/social/social_sidebar.html?example.com", iconURL:"chrome://branding/content/icon48.png"}, {name:"provider@test1", origin:"https://test1.example.com", sidebarURL:"https://test1.example.com/browser/browser/base/content/test/social/social_sidebar.html?test1", iconURL:"chrome://branding/content/icon48.png"}, {name:"provider@test2", origin:"https://test2.example.com", sidebarURL:"https://test2.example.com/browser/browser/base/content/test/social/social_sidebar.html?test2", iconURL:"chrome://branding/content/icon48.png"}]
18:35:20     INFO -  101 INFO runSocialTestWithProvider: provider added
18:35:20     INFO -  102 INFO runSocialTestWithProvider: provider added
18:35:20     INFO -  103 INFO runSocialTestWithProvider: provider added
18:35:20     INFO -  104 INFO provider has been enabled
18:35:20     INFO -  105 INFO TEST-PASS | browser/base/content/test/social/browser_social_chatwindow.js | Social is enabled -
18:35:20     INFO -  106 INFO runSocialTests: start test run with 3 providers
18:35:20     INFO -  107 INFO pre-test: starting with 3 providers
18:35:20     INFO -  108 INFO sub-test testOpenCloseChat starting
18:35:20     INFO -  109 INFO making a chat window 'chat 1'
18:35:20     INFO -  110 INFO chat window has opened
18:35:20     INFO -  111 INFO TEST-PASS | browser/base/content/test/social/browser_social_chatwindow.js | chatbox got minimized -
18:35:20     INFO -  112 INFO Console message: [JavaScript Warning: "Empty string passed to getElementById()." {file: "chrome://global/content/bindings/remote-browser.xml" line: 232}]
18:35:20     INFO -  113 INFO Longer timeout required, waiting longer...  Remaining timeouts: 1
18:35:20     INFO -  114 INFO Console message: [JavaScript Error: "1458264882933	Toolkit.GMP	ERROR	GMPInstallManager.simpleCheckAndInstall Could not check for addons: Error: got node name: html, expected: updates (resource://gre/modules/addons/ProductAddonChecker.jsm:147:11) JS Stack trace: parseXML@ProductAddonChecker.jsm:147:11 < promise callback*ProductAddonChecker.getProductAddonList@ProductAddonChecker.jsm:301:12 < GMPInstallManager.prototype.checkForAddons@GMPInstallManager.jsm:107:5 < GMPInstallManager.prototype.simpleCheckAndInstall<@GMPInstallManager.jsm:204:29 < gBrowserInit._delayedStartup/<@browser.js:1323:7 < setTimeout handler*gBrowserInit._delayedStartup@browser.js:1319:5 < EventListener.handleEvent*gBrowserInit.onLoad@browser.js:1034:5 < onload@browser.xul:1:1" {file: "resource://gre/modules/Log.jsm" line: 751}]
18:35:20     INFO -  App_append@resource://gre/modules/Log.jsm:751:9
18:35:20     INFO -  Logger.prototype.log@resource://gre/modules/Log.jsm:388:7
18:35:20     INFO -  LoggerRepository.prototype.getLoggerWithMessagePrefix/proxy.log@resource://gre/modules/Log.jsm:503:44
18:35:20     INFO -  Logger.prototype.error@resource://gre/modules/Log.jsm:396:5
18:35:20     INFO -  GMPInstallManager.prototype.simpleCheckAndInstall<@resource://gre/modules/GMPInstallManager.jsm:285:7
18:35:20     INFO -  TaskImpl_run@resource://gre/modules/Task.jsm:320:40
18:35:20     INFO -  Handler.prototype.process@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:940:21
18:35:20     INFO -  this.PromiseWalker.walkerLoop@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:816:7
18:35:20     INFO -  Promise*this.PromiseWalker.scheduleWalkerLoop@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:747:11
18:35:20     INFO -  this.PromiseWalker.schedulePromise@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:779:7
18:35:20     INFO -  this.PromiseWalker.completePromise@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:714:7
18:35:20     INFO -  GMPInstallManager.prototype.checkForAddons/<@resource://gre/modules/GMPInstallManager.jsm:116:7
18:35:21     INFO -  promise callback*GMPInstallManager.prototype.checkForAddons@resource://gre/modules/GMPInstallManager.jsm:107:5
18:35:21     INFO -  GMPInstallManager.prototype.simpleCheckAndInstall<@resource://gre/modules/GMPInstallManager.jsm:204:29
18:35:21     INFO -  TaskImpl_run@resource://gre/modules/Task.jsm:319:40
18:35:21     INFO -  TaskImpl@resource://gre/modules/Task.jsm:280:3
18:35:21     INFO -  createAsyncFunction/asyncFunction@resource://gre/modules/Task.jsm:254:14
18:35:21     INFO -  gBrowserInit._delayedStartup/<@chrome://browser/content/browser.js:1323:7
18:35:21     INFO -  setTimeout handler*gBrowserInit._delayedStartup@chrome://browser/content/browser.js:1319:5
18:35:21     INFO -  EventListener.handleEvent*gBrowserInit.onLoad@chrome://browser/content/browser.js:1034:5
18:35:21     INFO -  onload@chrome://browser/content/browser.xul:1:1
18:35:21     INFO -  115 INFO TEST-UNEXPECTED-FAIL | browser/base/content/test/social/browser_social_chatwindow.js | Test timed out -
18:35:21     INFO -  MEMORY STAT | vsize 703MB | vsizeMaxContiguous 865MB | residentFast 218MB | heapAllocated 57MB
18:35:21     INFO -  116 INFO TEST-OK | browser/base/content/test/social/browser_social_chatwindow.js | took 90136ms
Flags: needinfo?(mixedpuppy)
Seems bug 1032398 also landed just before this was reported.  Not sure if that was ruled out or not.  This is our top orange at the moment.
Bug 898706 landed prior to bug 1032398, and the first failures were on bug 898706's push.
This is strange...18:33:50 we see the start of the test, the first output is at 18:35:20, 90 seconds after the start.  That first output is at the very beginning of the test.  The only obvious thing in this test file that is happening between is a call to window.moveTo() here:

https://mxr.mozilla.org/mozilla-central/source/browser/base/content/test/social/browser_social_chatwindow.js#57

I wonder if I'm reading the log wrong, would the timestamps be accurate?  Or is output cached and stamped when it actually gets written?
Flags: needinfo?(mixedpuppy)
Assignee: nobody → mixedpuppy
I believe automation buffers the output and then spams it all at once.  So the timestamps are not accurate.  There is some config setting you can use to disable that in a try build I think.  Not sure exactly what that is, though.
ignore that first try, it included another patch I was working on.  second try contains a change to the test that I hope addresses this issue.
This patch it looking good initially, though try is terribly slow these days.  Of course I ran extra jobs on the first try rather than the second...but given the change I think that is still valid.
https://hg.mozilla.org/mozilla-central/rev/37cf1aab905f
Status: NEW → RESOLVED
Closed: 8 years ago
Resolution: --- → FIXED
Target Milestone: --- → Firefox 48
Product: Firefox → Firefox Graveyard
You need to log in before you can comment on or make changes to this bug.