Closed Bug 1503074 Opened Last year Closed Last year

Intermittent browser/components/payments/test/browser/<random_test> | [JavaScript Error: "TelemetryStopwatch: requesting elapsed time for nonexisting stopwatch. Histogram: "FX_TAB_SWITCH_COMPOSITE_E10S_MS", key: "null"" {file: "resource:

Categories

(Firefox :: Tabbed Browser, defect, P2)

defect

Tracking

()

RESOLVED FIXED
Firefox 65
Tracking Status
firefox65 --- fixed

People

(Reporter: intermittent-bug-filer, Assigned: ehsan)

References

Details

(Keywords: intermittent-failure)

Attachments

(1 file)

Filed by: btara [at] mozilla.com

https://treeherder.mozilla.org/logviewer.html#?job_id=208517493&repo=autoland

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

[task 2018-10-30T00:59:36.018Z] 00:59:36     INFO - TEST-START | browser/components/payments/test/browser/browser_payment_completion.js
[task 2018-10-30T00:59:36.056Z] 00:59:36     INFO - TEST-INFO | started process screentopng
[task 2018-10-30T00:59:36.482Z] 00:59:36     INFO - TEST-INFO | screentopng: exit 0
[task 2018-10-30T00:59:36.482Z] 00:59:36     INFO - Buffered messages logged at 00:59:36
[task 2018-10-30T00:59:36.484Z] 00:59:36     INFO - Entering test bound setup_head
[task 2018-10-30T00:59:36.485Z] 00:59:36     INFO - Leaving test bound setup_head
[task 2018-10-30T00:59:36.486Z] 00:59:36     INFO - Entering test bound test_complete_success
[task 2018-10-30T00:59:36.488Z] 00:59:36     INFO - Console message: [JavaScript Error: "TelemetryStopwatch: requesting elapsed time for nonexisting stopwatch. Histogram: "FX_TAB_SWITCH_COMPOSITE_E10S_MS", key: "null"" {file: "resource://gre/modules/TelemetryStopwatch.jsm" line: 388}]
[task 2018-10-30T00:59:36.489Z] 00:59:36     INFO - timeElapsed@resource://gre/modules/TelemetryStopwatch.jsm:388:9
[task 2018-10-30T00:59:36.490Z] 00:59:36     INFO - timeElapsed@resource://gre/modules/TelemetryStopwatch.jsm:208:12
[task 2018-10-30T00:59:36.491Z] 00:59:36     INFO - onPaint@resource:///modules/AsyncTabSwitcher.jsm:744:18
[task 2018-10-30T00:59:36.492Z] 00:59:36     INFO - handleEvent@resource:///modules/AsyncTabSwitcher.jsm:1046:9
[task 2018-10-30T00:59:36.494Z] 00:59:36     INFO - EventListener.handleEvent*AsyncTabSwitcher@resource:///modules/AsyncTabSwitcher.jsm:140:5
[task 2018-10-30T00:59:36.495Z] 00:59:36     INFO - _getSwitcher@chrome://browser/content/tabbrowser.js:4139:24
[task 2018-10-30T00:59:36.496Z] 00:59:36     INFO - updateCurrentBrowser@chrome://browser/content/tabbrowser.js:860:9
[task 2018-10-30T00:59:36.497Z] 00:59:36     INFO - _setupEventListeners/<@chrome://browser/content/tabbrowser.js:4507:9
[task 2018-10-30T00:59:36.498Z] 00:59:36     INFO - set selectedIndex@chrome://global/content/elements/tabbox.js:201:7
[task 2018-10-30T00:59:36.499Z] 00:59:36     INFO - set selectedPanel@chrome://global/content/elements/tabbox.js:215:5
[task 2018-10-30T00:59:36.500Z] 00:59:36     INFO - set_selectedIndex@chrome://global/content/bindings/tabbox.xml:172:15
[task 2018-10-30T00:59:36.501Z] 00:59:36     INFO - set_selectedItem@chrome://global/content/bindings/tabbox.xml:197:34
[task 2018-10-30T00:59:36.502Z] 00:59:36     INFO - set selectedTab@chrome://global/content/elements/tabbox.js:80:9
[task 2018-10-30T00:59:36.503Z] 00:59:36     INFO - set selectedTab@chrome://browser/content/tabbrowser.js:274:5
[task 2018-10-30T00:59:36.504Z] 00:59:36     INFO - _blurTab@chrome://browser/content/tabbrowser.js:3188:24
[task 2018-10-30T00:59:36.506Z] 00:59:36     INFO - _beginRemoveTab@chrome://browser/content/tabbrowser.js:2888:5
[task 2018-10-30T00:59:36.507Z] 00:59:36     INFO - removeTab@chrome://browser/content/tabbrowser.js:2796:10
[task 2018-10-30T00:59:36.508Z] 00:59:36     INFO - removeTab@resource://testing-common/BrowserTestUtils.jsm:1208:5
[task 2018-10-30T00:59:36.509Z] 00:59:36     INFO - test_openPreferences/<@chrome://mochitests/content/browser/browser/components/payments/test/browser/browser_openPreferences.js:55:11
[task 2018-10-30T00:59:36.510Z] 00:59:36     INFO - async*withNewTab@resource://testing-common/BrowserTestUtils.jsm:111:24
[task 2018-10-30T00:59:36.511Z] 00:59:36     INFO - async*test_openPreferences@chrome://mochitests/content/browser/browser/components/payments/test/browser/browser_openPreferences.js:13:9
[task 2018-10-30T00:59:36.512Z] 00:59:36     INFO - Async*Tester_execTest/<@chrome://mochikit/content/browser-test.js:1093:34
[task 2018-10-30T00:59:36.513Z] 00:59:36     INFO - async*Tester_execTest@chrome://mochikit/content/browser-test.js:1084:16
[task 2018-10-30T00:59:36.514Z] 00:59:36     INFO - nextTest/<@chrome://mochikit/content/browser-test.js:986:9
[task 2018-10-30T00:59:36.515Z] 00:59:36     INFO - SimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:795:59
[task 2018-10-30T00:59:36.516Z] 00:59:36     INFO - 
[task 2018-10-30T00:59:36.517Z] 00:59:36     INFO - Buffered messages finished
[task 2018-10-30T00:59:36.519Z] 00:59:36     INFO - TEST-UNEXPECTED-FAIL | browser/components/payments/test/browser/browser_payment_completion.js | [JavaScript Error: "TelemetryStopwatch: requesting elapsed time for nonexisting stopwatch. Histogram: "FX_TAB_SWITCH_COMPOSITE_E10S_MS", key: "null"" {file: "resource://gre/modules/TelemetryStopwatch.jsm" line: 388}]
[task 2018-10-30T00:59:36.520Z] 00:59:36     INFO - timeElapsed@resource://gre/modules/TelemetryStopwatch.jsm:388:9
[task 2018-10-30T00:59:36.521Z] 00:59:36     INFO - timeElapsed@resource://gre/modules/TelemetryStopwatch.jsm:208:12
[task 2018-10-30T00:59:36.522Z] 00:59:36     INFO - onPaint@resource:///modules/AsyncTabSwitcher.jsm:744:18
[task 2018-10-30T00:59:36.523Z] 00:59:36     INFO - handleEvent@resource:///modules/AsyncTabSwitcher.jsm:1046:9
[task 2018-10-30T00:59:36.526Z] 00:59:36     INFO - EventListener.handleEvent*AsyncTabSwitcher@resource:///modules/AsyncTabSwitcher.jsm:140:5
[task 2018-10-30T00:59:36.526Z] 00:59:36     INFO - _getSwitcher@chrome://browser/content/tabbrowser.js:4139:24
[task 2018-10-30T00:59:36.526Z] 00:59:36     INFO - updateCurrentBrowser@chrome://browser/content/tabbrowser.js:860:9
[task 2018-10-30T00:59:36.526Z] 00:59:36     INFO - _setupEventListeners/<@chrome://browser/content/tabbrowser.js:4507:9
[task 2018-10-30T00:59:36.526Z] 00:59:36     INFO - set selectedIndex@chrome://global/content/elements/tabbox.js:201:7
[task 2018-10-30T00:59:36.526Z] 00:59:36     INFO - set selectedPanel@chrome://global/content/elements/tabbox.js:215:5
[task 2018-10-30T00:59:36.526Z] 00:59:36     INFO - set_selectedIndex@chrome://global/content/bindings/tabbox.xml:172:15
[task 2018-10-30T00:59:36.528Z] 00:59:36     INFO - set_selectedItem@chrome://global/content/bindings/tabbox.xml:197:34
[task 2018-10-30T00:59:36.529Z] 00:59:36     INFO - set selectedTab@chrome://global/content/elements/tabbox.js:80:9
[task 2018-10-30T00:59:36.530Z] 00:59:36     INFO - set selectedTab@chrome://browser/content/tabbrowser.js:274:5
[task 2018-10-30T00:59:36.533Z] 00:59:36     INFO - _blurTab@chrome://browser/content/tabbrowser.js:3188:24
[task 2018-10-30T00:59:36.534Z] 00:59:36     INFO - _beginRemoveTab@chrome://browser/content/tabbrowser.js:2888:5
[task 2018-10-30T00:59:36.535Z] 00:59:36     INFO - removeTab@chrome://browser/content/tabbrowser.js:2796:10
[task 2018-10-30T00:59:36.536Z] 00:59:36     INFO - removeTab@resource://testing-common/BrowserTestUtils.jsm:1208:5
[task 2018-10-30T00:59:36.537Z] 00:59:36     INFO - test_openPreferences/<@chrome://mochitests/content/browser/browser/components/payments/test/browser/browser_openPreferences.js:55:11
[task 2018-10-30T00:59:36.538Z] 00:59:36     INFO - async*withNewTab@resource://testing-common/BrowserTestUtils.jsm:111:24
[task 2018-10-30T00:59:36.539Z] 00:59:36     INFO - async*test_openPreferences@chrome://mochitests/content/browser/browser/components/payments/test/browser/browser_openPreferences.js:13:9
[task 2018-10-30T00:59:36.540Z] 00:59:36     INFO - Async*Tester_execTest/<@chrome://mochikit/content/browser-test.js:1093:34
[task 2018-10-30T00:59:36.542Z] 00:59:36     INFO - async*Tester_execTest@chrome://mochikit/content/browser-test.js:1084:16
[task 2018-10-30T00:59:36.542Z] 00:59:36     INFO - nextTest/<@chrome://mochikit/content/browser-test.js:986:9
[task 2018-10-30T00:59:36.544Z] 00:59:36     INFO - SimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:795:59
[task 2018-10-30T00:59:36.545Z] 00:59:36     INFO -  - 
[task 2018-10-30T00:59:36.546Z] 00:59:36     INFO - Stack trace:
[task 2018-10-30T00:59:36.547Z] 00:59:36     INFO - chrome://mochitests/content/browser/browser/components/payments/test/browser/head.js:onConsoleMessage:365
[task 2018-10-30T00:59:36.549Z] 00:59:36     INFO - chrome://mochikit/content/tests/SimpleTest/specialpowersAPI.js:observe/<:388
[task 2018-10-30T00:59:36.550Z] 00:59:36     INFO - waitForMessageFromWidget: paymentDialogReady
[task 2018-10-30T00:59:36.551Z] 00:59:36     INFO - TEST-PASS | browser/components/payments/test/browser/browser_payment_completion.js | requestId should be defined -
Component: WebPayments UI → Tabbed Browser
Summary: Intermittent browser/components/payments/test/browser/browser_payment_completion.js | [JavaScript Error: "TelemetryStopwatch: requesting elapsed time for nonexisting stopwatch. Histogram: "FX_TAB_SWITCH_COMPOSITE_E10S_MS", key: "null"" {file: "resource: → Intermittent browser/components/payments/test/* | [JavaScript Error: "TelemetryStopwatch: requesting elapsed time for nonexisting stopwatch. Histogram: "FX_TAB_SWITCH_COMPOSITE_E10S_MS", key: "null"" {file: "resource:
Summary: Intermittent browser/components/payments/test/* | [JavaScript Error: "TelemetryStopwatch: requesting elapsed time for nonexisting stopwatch. Histogram: "FX_TAB_SWITCH_COMPOSITE_E10S_MS", key: "null"" {file: "resource: → Intermittent browser/components/payments/test/browser/browser_payment_completion.js | [JavaScript Error: "TelemetryStopwatch: requesting elapsed time for nonexisting stopwatch. Histogram: "FX_TAB_SWITCH_COMPOSITE_E10S_MS", key: "null"" {file: "resource:
Summary: Intermittent browser/components/payments/test/browser/browser_payment_completion.js | [JavaScript Error: "TelemetryStopwatch: requesting elapsed time for nonexisting stopwatch. Histogram: "FX_TAB_SWITCH_COMPOSITE_E10S_MS", key: "null"" {file: "resource: → Intermittent browser/components/payments/test/browser/<random_test> | [JavaScript Error: "TelemetryStopwatch: requesting elapsed time for nonexisting stopwatch. Histogram: "FX_TAB_SWITCH_COMPOSITE_E10S_MS", key: "null"" {file: "resource:
See Also: → 1508577
Duplicate of this bug: 1508577
For unknown reasons, my patch in bug 1509047 seems to turn this into a perma-failure on Linux64 debug mochitest-bc7, so I had to fix this...

The bug is actually trivial to fix.  We can cancel the stopwatch but this code isn't checking to see whether it has been canceled before.
Assignee: nobody → ehsan
Blocks: 1509047
Status: NEW → ASSIGNED
Priority: P5 → P2
Pushed by eakhgari@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/63cbd79e897d
Only touch the FX_TAB_SWITCH_COMPOSITE_E10S_MS stopwatch when we have actually started it in the past
https://hg.mozilla.org/mozilla-central/rev/63cbd79e897d
Status: ASSIGNED → RESOLVED
Closed: Last year
Resolution: --- → FIXED
Target Milestone: --- → Firefox 65
ni?ing ehsan just to make sure my review comment for this appears on his radar, since this has already landed.
Flags: needinfo?(ehsan)
Flags: needinfo?(ehsan)
Depends on: 1510418
You need to log in before you can comment on or make changes to this bug.