Intermittent browser/extensions/shield-recipe-client/test/browser_Heartbeat.js | Uncaught exception - at chrome://mochitests/content/browser/browser/extensions/shield-recipe-client/test/browser_Heartbeat.js:60 - TypeError: hb.eventEmitter is null

RESOLVED INCOMPLETE

Status

()

RESOLVED INCOMPLETE
2 years ago
7 months ago

People

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

Tracking

({intermittent-failure})

unspecified
intermittent-failure
Points:
---

Firefox Tracking Flags

(firefox52 unaffected, firefox53 fixed, firefox54 fixed)

Details

(Whiteboard: [stockwell fixed])

Attachments

(2 attachments)

Component: General → General
Product: Firefox → Shield
I noticed that this test has crossed the threshold of 30 intermittents in a given week; marking this as a high frequency/priority intermittent.

this test was landed and disabled for a leak, then we re-enabled the test on the 15th and have had a consistent set of intermittent failures, effectively this was a new test that started out very intermittent:
https://brasstacks.mozilla.com/orangefactor/index.html?display=Bug&bugid=1325409&startday=2017-01-13&endday=2017-01-20&tree=trunk

in looking at the failure screenshot, I see a 404:
https://public-artifacts.taskcluster.net/THJv_ZtASKel9R7q0RW2Tw/0/public/test_info//mozilla-test-fail-screenshot_a6cdJh.png

is that expected?

here is the data I see in the log file [0]:
[task 2017-01-15T21:50:12.010304Z] 21:50:12     INFO - TEST-OK | browser/extensions/shield-recipe-client/test/browser_EventEmitter.js | took 657ms
[task 2017-01-15T21:50:12.028339Z] 21:50:12     INFO - ++DOCSHELL 0x7fbebb59b000 == 9 [pid = 1888] [id = {b6cf156c-b651-403a-80df-cbbf3019094a}]
[task 2017-01-15T21:50:12.028707Z] 21:50:12     INFO - ++DOMWINDOW == 21 (0x7fbebb59b800) [pid = 1888] [serial = 21] [outer = (nil)]
[task 2017-01-15T21:50:12.089232Z] 21:50:12     INFO - ++DOMWINDOW == 22 (0x7fbebb976800) [pid = 1888] [serial = 22] [outer = 0x7fbebb59b800]
[task 2017-01-15T21:50:12.295158Z] 21:50:12     INFO - checking window state
[task 2017-01-15T21:50:12.453772Z] 21:50:12     INFO - TEST-START | browser/extensions/shield-recipe-client/test/browser_Heartbeat.js
[task 2017-01-15T21:50:12.455864Z] 21:50:12     INFO - Chrome file doesn't exist: /home/worker/workspace/build/tests/mochitest/browser/browser/extensions/shield-recipe-client/test/head.js
[task 2017-01-15T21:50:12.500537Z] 21:50:12     INFO - [1888] WARNING: We should have hit the document element...: file /home/worker/workspace/build/src/layout/xul/BoxObject.cpp, line 174
[task 2017-01-15T21:50:12.562975Z] 21:50:12     INFO - ++DOCSHELL 0x7fbebc27d800 == 10 [pid = 1888] [id = {52465936-c7b5-4be9-8416-5e17ee17a7f6}]
[task 2017-01-15T21:50:12.563431Z] 21:50:12     INFO - ++DOMWINDOW == 23 (0x7fbebd1ca800) [pid = 1888] [serial = 23] [outer = (nil)]
[task 2017-01-15T21:50:12.619138Z] 21:50:12     INFO - ++DOMWINDOW == 24 (0x7fbebdfb0800) [pid = 1888] [serial = 24] [outer = 0x7fbebd1ca800]
[task 2017-01-15T21:50:12.720988Z] 21:50:12     INFO - [1888] WARNING: Could not get disk status from nsIDiskSpaceWatcher: file /home/worker/workspace/build/src/uriloader/prefetch/nsOfflineCacheUpdateService.cpp, line 283
[task 2017-01-15T21:50:13.512554Z] 21:50:13     INFO - ++DOMWINDOW == 25 (0x7fbebe9b1000) [pid = 1888] [serial = 25] [outer = 0x7fbebd1ca800]
[task 2017-01-15T21:50:13.893226Z] 21:50:13     INFO - [1888] WARNING: GetDefaultCharsetForLocale: need to add multi locale support: file /home/worker/workspace/build/src/intl/locale/unix/nsUNIXCharset.cpp, line 98
[task 2017-01-15T21:50:15.295362Z] 21:50:15     INFO - [1888] WARNING: We should have hit the document element...: file /home/worker/workspace/build/src/layout/xul/BoxObject.cpp, line 174
[task 2017-01-15T21:50:15.333185Z] 21:50:15     INFO - ++DOCSHELL 0x7fbec0790000 == 11 [pid = 1888] [id = {9509344d-434a-4a8d-801c-bca9f1cbd4e3}]
[task 2017-01-15T21:50:15.333567Z] 21:50:15     INFO - ++DOMWINDOW == 26 (0x7fbec0a58800) [pid = 1888] [serial = 26] [outer = (nil)]
[task 2017-01-15T21:50:15.397281Z] 21:50:15     INFO - ++DOMWINDOW == 27 (0x7fbec1311000) [pid = 1888] [serial = 27] [outer = 0x7fbec0a58800]
[task 2017-01-15T21:50:15.980180Z] 21:50:15     INFO - ++DOMWINDOW == 28 (0x7fbec9285800) [pid = 1888] [serial = 28] [outer = 0x7fbec0a58800]
[task 2017-01-15T21:50:16.889405Z] 21:50:16     INFO - --DOCSHELL 0x7fbeb6c47800 == 10 [pid = 1888] [id = {68ab5cad-b05b-4f60-9760-32d903bee243}]
[task 2017-01-15T21:50:16.891434Z] 21:50:16     INFO - --DOCSHELL 0x7fbebe2b1800 == 9 [pid = 1888] [id = {ac6b29e2-3761-4584-8948-e8ece81d4df3}]
[task 2017-01-15T21:50:17.753616Z] 21:50:17     INFO - --DOCSHELL 0x7fbebc27d800 == 8 [pid = 1888] [id = {52465936-c7b5-4be9-8416-5e17ee17a7f6}]
[task 2017-01-15T21:50:19.298566Z] 21:50:19     INFO - *************************
[task 2017-01-15T21:50:19.298909Z] 21:50:19     INFO - A coding exception was thrown and uncaught in a Task.
[task 2017-01-15T21:50:19.299185Z] 21:50:19     INFO - Full message: TypeError: hb.eventEmitter is null
[task 2017-01-15T21:50:19.299568Z] 21:50:19     INFO - Full stack: assertTelemetrySent/<@chrome://mochitests/content/browser/browser/extensions/shield-recipe-client/test/browser_Heartbeat.js:60:5
[task 2017-01-15T21:50:19.302300Z] 21:50:19     INFO - assertTelemetrySent@chrome://mochitests/content/browser/browser/extensions/shield-recipe-client/test/browser_Heartbeat.js:59:10
[task 2017-01-15T21:50:19.302718Z] 21:50:19     INFO - @chrome://mochitests/content/browser/browser/extensions/shield-recipe-client/test/browser_Heartbeat.js:156:32
[task 2017-01-15T21:50:19.304812Z] 21:50:19     INFO - process@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:917:23
[task 2017-01-15T21:50:19.310796Z] 21:50:19     INFO - walkerLoop@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:801:7
[task 2017-01-15T21:50:19.316023Z] 21:50:19     INFO - Promise*scheduleWalkerLoop@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:734:11
[task 2017-01-15T21:50:19.318772Z] 21:50:19     INFO - schedulePromise@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:765:7
[task 2017-01-15T21:50:19.324023Z] 21:50:19     INFO - completePromise@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:702:7
[task 2017-01-15T21:50:19.326128Z] 21:50:19     INFO - TaskImpl_run@resource://gre/modules/Task.jsm:324:15
[task 2017-01-15T21:50:19.328881Z] 21:50:19     INFO - promise callback*TaskImpl_handleResultValue@resource://gre/modules/Task.jsm:396:7
[task 2017-01-15T21:50:19.332327Z] 21:50:19     INFO - TaskImpl_run@resource://gre/modules/Task.jsm:327:15
[task 2017-01-15T21:50:19.334300Z] 21:50:19     INFO - promise callback*TaskImpl_handleResultValue@resource://gre/modules/Task.jsm:396:7
[task 2017-01-15T21:50:19.336440Z] 21:50:19     INFO - TaskImpl_run@resource://gre/modules/Task.jsm:327:15
[task 2017-01-15T21:50:19.338529Z] 21:50:19     INFO - promise callback*TaskImpl_handleResultValue@resource://gre/modules/Task.jsm:396:7
[task 2017-01-15T21:50:19.345143Z] 21:50:19     INFO - TaskImpl_run@resource://gre/modules/Task.jsm:327:15
[task 2017-01-15T21:50:19.349269Z] 21:50:19     INFO - promise callback*TaskImpl_handleResultValue@resource://gre/modules/Task.jsm:396:7
[task 2017-01-15T21:50:19.351009Z] 21:50:19     INFO - TaskImpl_run@resource://gre/modules/Task.jsm:327:15
[task 2017-01-15T21:50:19.355452Z] 21:50:19     INFO - promise callback*TaskImpl_handleResultValue@resource://gre/modules/Task.jsm:396:7
[task 2017-01-15T21:50:19.357653Z] 21:50:19     INFO - TaskImpl_run@resource://gre/modules/Task.jsm:327:15
[task 2017-01-15T21:50:19.359883Z] 21:50:19     INFO - TaskImpl@resource://gre/modules/Task.jsm:277:3
[task 2017-01-15T21:50:19.361748Z] 21:50:19     INFO - asyncFunction@resource://gre/modules/Task.jsm:252:14
[task 2017-01-15T21:50:19.363591Z] 21:50:19     INFO - Task_spawn@resource://gre/modules/Task.jsm:166:12
[task 2017-01-15T21:50:19.365544Z] 21:50:19     INFO - TaskImpl_handleResultValue@resource://gre/modules/Task.jsm:389:16
[task 2017-01-15T21:50:19.369647Z] 21:50:19     INFO - TaskImpl_run@resource://gre/modules/Task.jsm:327:15
[task 2017-01-15T21:50:19.371305Z] 21:50:19     INFO - TaskImpl@resource://gre/modules/Task.jsm:277:3
[task 2017-01-15T21:50:19.373477Z] 21:50:19     INFO - asyncFunction@resource://gre/modules/Task.jsm:252:14
[task 2017-01-15T21:50:19.375300Z] 21:50:19     INFO - Task_spawn@resource://gre/modules/Task.jsm:166:12
[task 2017-01-15T21:50:19.377140Z] 21:50:19     INFO - Tester_execTest@chrome://mochikit/content/browser-test.js:737:9
[task 2017-01-15T21:50:19.380129Z] 21:50:19     INFO - Tester.prototype.nextTest</<@chrome://mochikit/content/browser-test.js:657:7
[task 2017-01-15T21:50:19.382222Z] 21:50:19     INFO - SimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:744:59
[task 2017-01-15T21:50:19.386047Z] 21:50:19     INFO - *************************
[task 2017-01-15T21:50:19.396047Z] 21:50:19     INFO - TEST-INFO | started process screentopng
[task 2017-01-15T21:50:20.858856Z] 21:50:20     INFO - TEST-INFO | screentopng: exit 0
[task 2017-01-15T21:50:20.864874Z] 21:50:20     INFO - Buffered messages logged at 21:50:12
[task 2017-01-15T21:50:20.867023Z] 21:50:20     INFO - Entering test bound 
[task 2017-01-15T21:50:20.869541Z] 21:50:20     INFO - TEST-PASS | browser/extensions/shield-recipe-client/test/browser_Heartbeat.js | Correct number of notifications open - 1 == 1 - 
[task 2017-01-15T21:50:20.871773Z] 21:50:20     INFO - TEST-PASS | browser/extensions/shield-recipe-client/test/browser_Heartbeat.js | Correct number of stars - 5 == 5 - 
[task 2017-01-15T21:50:20.879218Z] 21:50:20     INFO - TEST-PASS | browser/extensions/shield-recipe-client/test/browser_Heartbeat.js | Engagement button not shown - 0 == 0 - 
[task 2017-01-15T21:50:20.881319Z] 21:50:20     INFO - TEST-PASS | browser/extensions/shield-recipe-client/test/browser_Heartbeat.js | Learn more url correct - "https://example.org/learnmore" == "https://example.org/learnmore" - 
[task 2017-01-15T21:50:20.883164Z] 21:50:20     INFO - TEST-PASS | browser/extensions/shield-recipe-client/test/browser_Heartbeat.js | Learn more label correct - "Learn More" == "Learn More" - 
[task 2017-01-15T21:50:20.885032Z] 21:50:20     INFO - TEST-PASS | browser/extensions/shield-recipe-client/test/browser_Heartbeat.js | Message is correct - "test" == "test" - 
[task 2017-01-15T21:50:20.886712Z] 21:50:20     INFO - Buffered messages logged at 21:50:14
[task 2017-01-15T21:50:20.888883Z] 21:50:20     INFO - TEST-PASS | browser/extensions/shield-recipe-client/test/browser_Heartbeat.js | Learn more link opened the right url - "https://example.org/learnmore" == "https://example.org/learnmore" - 
[task 2017-01-15T21:50:20.896228Z] 21:50:20     INFO - TEST-PASS | browser/extensions/shield-recipe-client/test/browser_Heartbeat.js | No notifications left - 0 == 0 - 
[task 2017-01-15T21:50:20.898403Z] 21:50:20     INFO - TEST-PASS | browser/extensions/shield-recipe-client/test/browser_Heartbeat.js | payload field offeredTS is a number - "number" == "number" - 
[task 2017-01-15T21:50:20.900223Z] 21:50:20     INFO - TEST-PASS | browser/extensions/shield-recipe-client/test/browser_Heartbeat.js | payload field learnMoreTS is a number - "number" == "number" - 
[task 2017-01-15T21:50:20.902511Z] 21:50:20     INFO - TEST-PASS | browser/extensions/shield-recipe-client/test/browser_Heartbeat.js | payload field closedTS is a number - "number" == "number" - 
[task 2017-01-15T21:50:20.906663Z] 21:50:20     INFO - TEST-PASS | browser/extensions/shield-recipe-client/test/browser_Heartbeat.js | element 0 is type "number" - "number" == "number" - 
[task 2017-01-15T21:50:20.908648Z] 21:50:20     INFO - TEST-PASS | browser/extensions/shield-recipe-client/test/browser_Heartbeat.js | element 1 is type "number" - "number" == "number" - 
[task 2017-01-15T21:50:20.910601Z] 21:50:20     INFO - TEST-PASS | browser/extensions/shield-recipe-client/test/browser_Heartbeat.js | element 2 is type "number" - "number" == "number" - 
[task 2017-01-15T21:50:20.915738Z] 21:50:20     INFO - TEST-PASS | browser/extensions/shield-recipe-client/test/browser_Heartbeat.js | element 3 is type "number" - "number" == "number" - 
[task 2017-01-15T21:50:20.917785Z] 21:50:20     INFO - TEST-PASS | browser/extensions/shield-recipe-client/test/browser_Heartbeat.js | element 4 is type "number" - "number" == "number" - 
[task 2017-01-15T21:50:20.919584Z] 21:50:20     INFO - TEST-PASS | browser/extensions/shield-recipe-client/test/browser_Heartbeat.js | element 0 is less than or equal to element 1 - 0 <= 1484517012516 - 
[task 2017-01-15T21:50:20.924650Z] 21:50:20     INFO - TEST-PASS | browser/extensions/shield-recipe-client/test/browser_Heartbeat.js | element 1 is less than or equal to element 2 - 1484517012516 <= 1484517012542 - 
[task 2017-01-15T21:50:20.926733Z] 21:50:20     INFO - TEST-PASS | browser/extensions/shield-recipe-client/test/browser_Heartbeat.js | element 2 is less than or equal to element 3 - 1484517012542 <= 1484517014768 - 
[task 2017-01-15T21:50:20.928861Z] 21:50:20     INFO - TEST-PASS | browser/extensions/shield-recipe-client/test/browser_Heartbeat.js | element 3 is less than or equal to element 4 - 1484517014768 <= 1484517014857 - 
[task 2017-01-15T21:50:20.930811Z] 21:50:20     INFO - Buffered messages logged at 21:50:15
[task 2017-01-15T21:50:20.932919Z] 21:50:20     INFO - Leaving test bound 
[task 2017-01-15T21:50:20.934869Z] 21:50:20     INFO - Entering test bound 
[task 2017-01-15T21:50:20.940080Z] 21:50:20     INFO - TEST-PASS | browser/extensions/shield-recipe-client/test/browser_Heartbeat.js | Stars not shown - 0 == 0 - 
[task 2017-01-15T21:50:20.946017Z] 21:50:20     INFO - TEST-PASS | browser/extensions/shield-recipe-client/test/browser_Heartbeat.js | Engagement button added - {"buttonInfo":{"label":"Click me!","callback":"() => {\n          // Let the consumer know user engaged.\n          this.maybeNo == true - 
[task 2017-01-15T21:50:20.947980Z] 21:50:20     INFO - TEST-PASS | browser/extensions/shield-recipe-client/test/browser_Heartbeat.js | Engagement button has correct label - "Click me!" == "Click me!" - 
[task 2017-01-15T21:50:20.949781Z] 21:50:20     INFO - Buffered messages logged at 21:50:19
[task 2017-01-15T21:50:20.951924Z] 21:50:20     INFO - TEST-PASS | browser/extensions/shield-recipe-client/test/browser_Heartbeat.js | Engagement button opened the right url - true == true - 
[task 2017-01-15T21:50:20.955788Z] 21:50:20     INFO - Buffered messages finished
[task 2017-01-15T21:50:20.958118Z] 21:50:20     INFO - TEST-UNEXPECTED-FAIL | browser/extensions/shield-recipe-client/test/browser_Heartbeat.js | Uncaught exception - at chrome://mochitests/content/browser/browser/extensions/shield-recipe-client/test/browser_Heartbeat.js:60 - TypeError: hb.eventEmitter is null
[task 2017-01-15T21:50:20.959624Z] 21:50:20     INFO - Stack trace:
[task 2017-01-15T21:50:20.961382Z] 21:50:20     INFO -     assertTelemetrySent/<@chrome://mochitests/content/browser/browser/extensions/shield-recipe-client/test/browser_Heartbeat.js:60:5
[task 2017-01-15T21:50:20.964935Z] 21:50:20     INFO -     assertTelemetrySent@chrome://mochitests/content/browser/browser/extensions/shield-recipe-client/test/browser_Heartbeat.js:59:10
[task 2017-01-15T21:50:20.966899Z] 21:50:20     INFO -     @chrome://mochitests/content/browser/browser/extensions/shield-recipe-client/test/browser_Heartbeat.js:156:32
[task 2017-01-15T21:50:20.968662Z] 21:50:20     INFO -     process@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:917:23
[task 2017-01-15T21:50:20.970295Z] 21:50:20     INFO -     walkerLoop@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:801:7
[task 2017-01-15T21:50:20.972053Z] 21:50:20     INFO -     Promise*scheduleWalkerLoop@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:734:11
[task 2017-01-15T21:50:20.974341Z] 21:50:20     INFO -     schedulePromise@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:765:7
[task 2017-01-15T21:50:20.976554Z] 21:50:20     INFO -     completePromise@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:702:7
[task 2017-01-15T21:50:20.979360Z] 21:50:20     INFO -     Tester_execTest@chrome://mochikit/content/browser-test.js:737:9
[task 2017-01-15T21:50:20.980987Z] 21:50:20     INFO -     Tester.prototype.nextTest</<@chrome://mochikit/content/browser-test.js:657:7
[task 2017-01-15T21:50:20.982824Z] 21:50:20     INFO -     SimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:744:59
[task 2017-01-15T21:50:20.985601Z] 21:50:20     INFO - Leaving test bound 
[task 2017-01-15T21:50:20.988979Z] 21:50:20     INFO - Entering test bound 
[task 2017-01-15T21:50:20.990911Z] 21:50:20     INFO - ++DOCSHELL 0x7fbebe447800 == 9 [pid = 1888] [id = {b5af0afb-c26a-4bea-8d7e-ffe2b3b1d77d}]
[task 2017-01-15T21:50:20.993142Z] 21:50:20     INFO - ++DOMWINDOW == 29 (0x7fbebe44c000) [pid = 1888] [serial = 29] [outer = (nil)]
[task 2017-01-15T21:50:20.996193Z] 21:50:20     INFO - ++DOMWINDOW == 30 (0x7fbebe453000) [pid = 1888] [serial = 30] [outer = 0x7fbebe44c000]
[task 2017-01-15T21:50:21.000254Z] 21:50:20     INFO - Not taking screenshot here: see the one that was previously logged
[task 2017-01-15T21:50:21.002723Z] 21:50:21     INFO - TEST-UNEXPECTED-FAIL | browser/extensions/shield-recipe-client/test/browser_Heartbeat.js | uncaught exception - TypeError: this.eventEmitter is null at maybeNotifyHeartbeat@resource://shield-recipe-client/lib/Heartbeat.jsm:264:5
[task 2017-01-15T21:50:21.004446Z] 21:50:21     INFO - this.Heartbeat</this.notice<@resource://shield-recipe-client/lib/Heartbeat.jsm:135:9
[task 2017-01-15T21:50:21.006313Z] 21:50:21     INFO - _removeNotificationElement@chrome://global/content/bindings/notification.xml:206:15
[task 2017-01-15T21:50:21.009058Z] 21:50:21     INFO - _finishAnimation@chrome://global/content/bindings/notification.xml:311:15
[task 2017-01-15T21:50:21.010594Z] 21:50:21     INFO - onxbltransitionend@chrome://global/content/bindings/notification.xml:376:11
[task 2017-01-15T21:50:21.012360Z] 21:50:21     INFO - 
[task 2017-01-15T21:50:21.014629Z] 21:50:21     INFO - Stack trace:
[task 2017-01-15T21:50:21.017255Z] 21:50:21     INFO - chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:simpletestOnerror:1583
[task 2017-01-15T21:50:21.019274Z] 21:50:21     INFO - JavaScript error: resource://shield-recipe-client/lib/Heartbeat.jsm, line 264: TypeError: this.eventEmitter is null
[task 2017-01-15T21:50:21.021482Z] 21:50:21     INFO - ++DOCSHELL 0x7fbebeaaf800 == 10 [pid = 1888] [id = {5661b944-1633-49c0-b82e-b56fd532f973}]
[task 2017-01-15T21:50:21.026434Z] 21:50:21     INFO - ++DOMWINDOW == 31 (0x7fbebeab0000) [pid = 1888] [serial = 31] [outer = (nil)]
[task 2017-01-15T21:50:21.028371Z] 21:50:21     INFO - ++DOCSHELL 0x7fbebeccf800 == 11 [pid = 1888] [id = {d25b4591-4a56-4051-b2a8-3cccb5a9ef60}]
[task 2017-01-15T21:50:21.030389Z] 21:50:21     INFO - ++DOMWINDOW == 32 (0x7fbebecd3800) [pid = 1888] [serial = 32] [outer = (nil)]
[task 2017-01-15T21:50:21.032436Z] 21:50:21     INFO - Console message: [JavaScript Error: "TypeError: this.eventEmitter is null" {file: "resource://shield-recipe-client/lib/Heartbeat.jsm" line: 264}]
[task 2017-01-15T21:50:21.034488Z] 21:50:21     INFO - maybeNotifyHeartbeat@resource://shield-recipe-client/lib/Heartbeat.jsm:264:5
[task 2017-01-15T21:50:21.036136Z] 21:50:21     INFO - this.Heartbeat</this.notice<@resource://shield-recipe-client/lib/Heartbeat.jsm:135:9
[task 2017-01-15T21:50:21.040266Z] 21:50:21     INFO - _removeNotificationElement@chrome://global/content/bindings/notification.xml:206:15
[task 2017-01-15T21:50:21.042213Z] 21:50:21     INFO - _finishAnimation@chrome://global/content/bindings/notification.xml:311:15
[task 2017-01-15T21:50:21.045406Z] 21:50:21     INFO - onxbltransitionend@chrome://global/content/bindings/notification.xml:376:11
[task 2017-01-15T21:50:21.046763Z] 21:50:21     INFO - 
[task 2017-01-15T21:50:21.048888Z] 21:50:21     INFO - ++DOCSHELL 0x7fbebf286000 == 12 [pid = 1888] [id = {d44e497b-6c01-45a9-be5c-9b76b505c098}]
[task 2017-01-15T21:50:21.051700Z] 21:50:21     INFO - ++DOMWINDOW == 33 (0x7fbebf290800) [pid = 1888] [serial = 33] [outer = (nil)]
[task 2017-01-15T21:50:21.054036Z] 21:50:21     INFO - ++DOMWINDOW == 34 (0x7fbec0797800) [pid = 1888] [serial = 34] [outer = 0x7fbebf290800]
[task 2017-01-15T21:50:21.377181Z] 21:50:21     INFO - ++DOMWINDOW == 35 (0x7fbec72a2800) [pid = 1888] [serial = 35] [outer = 0x7fbebeab0000]
[task 2017-01-15T21:50:21.393581Z] 21:50:21     INFO - ++DOMWINDOW == 36 (0x7fbec7a03000) [pid = 1888] [serial = 36] [outer = 0x7fbebecd3800]
[task 2017-01-15T21:50:21.414309Z] 21:50:21     INFO - ++DOMWINDOW == 37 (0x7fbec7aaf000) [pid = 1888] [serial = 37] [outer = 0x7fbebf290800]
[task 2017-01-15T21:50:22.596158Z] 21:50:22     INFO - [1888] WARNING: We should have hit the document element...: file /home/worker/workspace/build/src/layout/xul/BoxObject.cpp, line 174
[task 2017-01-15T21:50:22.961373Z] 21:50:22     INFO - --DOCSHELL 0x7fbebeaaf800 == 11 [pid = 1888] [id = {5661b944-1633-49c0-b82e-b56fd532f973}]
[task 2017-01-15T21:50:23.043104Z] 21:50:23     INFO - TEST-PASS | browser/extensions/shield-recipe-client/test/browser_Heartbeat.js | payload field offeredTS is a number - "number" == "number" - 
[task 2017-01-15T21:50:23.047486Z] 21:50:23     INFO - TEST-PASS | browser/extensions/shield-recipe-client/test/browser_Heartbeat.js | payload field windowClosedTS is a number - "number" == "number" - 
[task 2017-01-15T21:50:23.056465Z] 21:50:23     INFO - TEST-PASS | browser/extensions/shield-recipe-client/test/browser_Heartbeat.js | element 0 is type "number" - "number" == "number" - 
[task 2017-01-15T21:50:23.058071Z] 21:50:23     INFO - TEST-PASS | browser/extensions/shield-recipe-client/test/browser_Heartbeat.js | element 1 is type "number" - "number" == "number" - 
[task 2017-01-15T21:50:23.074982Z] 21:50:23     INFO - TEST-PASS | browser/extensions/shield-recipe-client/test/browser_Heartbeat.js | element 2 is type "number" - "number" == "number" - 
[task 2017-01-15T21:50:23.075393Z] 21:50:23     INFO - TEST-PASS | browser/extensions/shield-recipe-client/test/browser_Heartbeat.js | element 3 is type "number" - "number" == "number" - 
[task 2017-01-15T21:50:23.084239Z] 21:50:23     INFO - TEST-PASS | browser/extensions/shield-recipe-client/test/browser_Heartbeat.js | element 0 is less than or equal to element 1 - 0 <= 1484517022611 - 
[task 2017-01-15T21:50:23.088250Z] 21:50:23     INFO - TEST-PASS | browser/extensions/shield-recipe-client/test/browser_Heartbeat.js | element 1 is less than or equal to element 2 - 1484517022611 <= 1484517022670 - 
[task 2017-01-15T21:50:23.097071Z] 21:50:23     INFO - TEST-PASS | browser/extensions/shield-recipe-client/test/browser_Heartbeat.js | element 2 is less than or equal to element 3 - 1484517022670 <= 1484517023047 - 
[task 2017-01-15T21:50:23.387273Z] 21:50:23     INFO - Leaving test bound 
[task 2017-01-15T21:50:23.387641Z] 21:50:23     INFO - Entering test bound 
[task 2017-01-15T21:50:23.407821Z] 21:50:23     INFO - TEST-PASS | browser/extensions/shield-recipe-client/test/browser_Heartbeat.js | sandbox is nuked - 
[task 2017-01-15T21:50:23.415516Z] 21:50:23     INFO - Leaving test bound 
[task 2017-01-15T21:50:23.667638Z] 21:50:23     INFO - MEMORY STAT | vsize 1054MB | residentFast 270MB | heapAllocated 116MB
[task 2017-01-15T21:50:23.669470Z] 21:50:23     INFO - TEST-OK | browser/extensions/shield-recipe-client/test/browser_Heartbeat.js | took 11218ms
[task 2017-01-15T21:50:23.679945Z] 21:50:23     INFO - Not taking screenshot here: see the one that was previously logged
[task 2017-01-15T21:50:23.681570Z] 21:50:23     INFO - TEST-UNEXPECTED-FAIL | browser/extensions/shield-recipe-client/test/browser_Heartbeat.js | Found an unexpected tab at the end of test run: https://example.org/postAnswer?type=button&flowId=test - 


:mythmon, I see that you wrote this originally, would it be possible for you to take a look at this and help get this fixed up?

[0] https://public-artifacts.taskcluster.net/THJv_ZtASKel9R7q0RW2Tw/0/public/logs/live_backing.log
Flags: needinfo?(mcooper)
(Assignee)

Comment 2

2 years ago
I can help get this fixed up. We're still actively working on this add-on, and there is some work to re-do this part of the code already underway.

The 404 is expected, and not related to this. Thanks for checking. We have links to open tabs from a notification bar, and we put dummy data in them that doesn't need to really resolve.

Osmose: FYI, your changes to the hearbeat event emitter might fix this. Might be good to keep in mind.
Flags: needinfo?(mcooper)
30 failures in 143 pushes (0.21 failures/push) were associated with this bug yesterday.  

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

Platform breakdown:
* linux64: 16
* linux32: 13
* lint: 1

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1325409&startday=2017-01-20&endday=2017-01-20&tree=all
73 failures in 690 pushes (0.106 failures/push) were associated with this bug in the last 7 days. 

This is the #14 most frequent failure this week. 

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

Repository breakdown:
* mozilla-inbound: 52
* autoland: 16
* try: 3
* mozilla-central: 1
* graphics: 1

Platform breakdown:
* linux32: 39
* linux64: 33
* lint: 1

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1325409&startday=2017-01-16&endday=2017-01-22&tree=all
Comment hidden (mozreview-request)
(Assignee)

Comment 6

2 years ago
mozreview-review
Comment on attachment 8829676 [details]
Bug 1325409 - shield-recipe-client: Remove unnecessary cleanup

https://reviewboard.mozilla.org/r/106672/#review107694
(Assignee)

Comment 7

2 years ago
Comment on attachment 8829676 [details]
Bug 1325409 - shield-recipe-client: Remove unnecessary cleanup

This was reviewed on GitHub, and I'm just transferring the commit to mozilla-central here.
Attachment #8829676 - Flags: review+
31 failures in 127 pushes (0.244 failures/push) were associated with this bug yesterday.  

Repository breakdown:
* mozilla-inbound: 27
* autoland: 3
* mozilla-central: 1

Platform breakdown:
* linux64: 16
* linux32: 15

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1325409&startday=2017-01-23&endday=2017-01-23&tree=all
(Assignee)

Comment 9

2 years ago
mozreview-review
Comment on attachment 8829676 [details]
Bug 1325409 - shield-recipe-client: Remove unnecessary cleanup

https://reviewboard.mozilla.org/r/106674/#review107918

Comment 10

2 years ago
Pushed by mcooper@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/a13ecbafd932
shield-recipe-client: Remove unnecessary cleanup r=mythmon

Comment 11

2 years ago
Commits pushed to master at https://github.com/mozilla/normandy

https://github.com/mozilla/normandy/commit/5816fbc92c5b1cc3d9027b6b7a68263a7fd6d882
Bug 1325409: Remove unnecessary cleanup.

Cleanup is already run when the notification is removed, so calling it
in close() causes it to be called twice. Also, when the notification
is removed, it sends a Heartbeat event, which fails if cleanup has
already happened.

https://github.com/mozilla/normandy/commit/3ee13529e4939b7386bd0eda2e7ef0e7a80c15a3
Merge pull request #443 from Osmose/extra-cleanup

Bug 1325409: Remove unnecessary cleanup.
(Assignee)

Updated

2 years ago
Assignee: nobody → mcooper

Comment 12

2 years ago
bugherder
https://hg.mozilla.org/mozilla-central/rev/a13ecbafd932
Status: NEW → RESOLVED
Last Resolved: 2 years ago
Resolution: --- → FIXED
88 failures in 152 pushes (0.579 failures/push) were associated with this bug yesterday.  

Repository breakdown:
* autoland: 50
* mozilla-inbound: 35
* mozilla-central: 2
* graphics: 1

Platform breakdown:
* linux64: 55
* linux32: 33

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1325409&startday=2017-01-24&endday=2017-01-24&tree=all
Status: RESOLVED → REOPENED
Resolution: FIXED → ---
69 failures in 153 pushes (0.451 failures/push) were associated with this bug yesterday.  

Repository breakdown:
* autoland: 30
* mozilla-inbound: 29
* try: 5
* graphics: 3
* mozilla-central: 2

Platform breakdown:
* linux64: 43
* linux32: 26

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1325409&startday=2017-01-25&endday=2017-01-25&tree=all
the failures here have only spiked  primarily on linux32/64-debug and linux64-asan, all in e10s mode only.

:mythmon, can you take a look at this again- this is our #2 intermittent bug.
Flags: needinfo?(mcooper)
(Assignee)

Comment 16

2 years ago
Osmose currently has this PR in review: https://github.com/mozilla/normandy/pull/436, which is not targeted specifically at this issue, but I suspect that it might help since it re-works the event emitter, which seems related to the failures here.
Flags: needinfo?(mcooper)
73 failures in 108 pushes (0.676 failures/push) were associated with this bug yesterday.  

Repository breakdown:
* mozilla-inbound: 32
* autoland: 30
* try: 4
* mozilla-central: 4
* graphics: 3

Platform breakdown:
* linux64: 45
* linux32: 28

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1325409&startday=2017-01-26&endday=2017-01-26&tree=all
84 failures in 141 pushes (0.596 failures/push) were associated with this bug yesterday.  

Repository breakdown:
* autoland: 37
* mozilla-inbound: 34
* try: 6
* graphics: 5
* mozilla-central: 2

Platform breakdown:
* linux64: 54
* linux32: 30

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1325409&startday=2017-01-27&endday=2017-01-27&tree=all
361 failures in 749 pushes (0.482 failures/push) were associated with this bug in the last 7 days. 

This is the #2 most frequent failure this week. 

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

Repository breakdown:
* mozilla-inbound: 160
* autoland: 155
* try: 19
* graphics: 14
* mozilla-central: 13

Platform breakdown:
* linux64: 226
* linux32: 135

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1325409&startday=2017-01-23&endday=2017-01-29&tree=all
(Assignee)

Comment 20

2 years ago
Created attachment 8831770 [details] [diff] [review]
move-event-emitter.patch

From https://github.com/mozilla/normandy/pull/436, r=Gijs

Comment 21

2 years ago
Pushed by mcooper@mozilla.com:
https://hg.mozilla.org/integration/mozilla-inbound/rev/ad72edc63959
shield-recipe-client: Move event emitter out of sandbox r=Gijs

Comment 22

2 years ago
bugherder
https://hg.mozilla.org/mozilla-central/rev/ad72edc63959
Status: REOPENED → RESOLVED
Last Resolved: 2 years ago2 years ago
Resolution: --- → FIXED
IIUC, this bug was filed when trunk was tracking Gecko 53, but I'm not seeing any of these failures on OrangeFactor for Aurora. Do we need to uplift this there too?
Flags: needinfo?(mcooper)
(Assignee)

Comment 24

2 years ago
We should uplift this to Aurora, yes. I'm not sure why it wouldn't be causing errors there too, but this patch is definitely a change that should be included.
Flags: needinfo?(mcooper)
Please request approval in that case. It's a flag you can set on the attachment with some questions that'll need answering.
Component: General → Add-on
Flags: needinfo?(mcooper)
status-firefox52: --- → unaffected
status-firefox53: --- → affected
status-firefox54: --- → fixed
(Assignee)

Comment 26

2 years ago
Comment on attachment 8831770 [details] [diff] [review]
move-event-emitter.patch

Approval Request Comment
[Feature/Bug causing the regression]: This intermittent bug existed in code that has shipped to Aurora
[User impact if declined]: Less reliable code, since this causes tests to fail.
[Is this code covered by automated tests?]: Yes
[Has the fix been verified in Nightly?]: Yes. The test failures have stopped in automation.
[Needs manual test from QE? If yes, steps to reproduce]: No.
[List of other uplifts needed for the feature/fix]: None.
[Is the change risky?]: No
[Why is the change risky/not risky?]: The code is well validated by automated tests.
[String changes made/needed]: None
Flags: needinfo?(mcooper)
Attachment #8831770 - Flags: approval-mozilla-aurora?
Comment on attachment 8831770 [details] [diff] [review]
move-event-emitter.patch

Fix a intermittent-failure. Aurora53+.
Attachment #8831770 - Flags: approval-mozilla-aurora? → approval-mozilla-aurora+
needs rebase for aurora

merging browser/extensions/shield-recipe-client/bootstrap.js                                                                                                                                       
merging browser/extensions/shield-recipe-client/lib/Heartbeat.jsm                                                                                                                                  
merging browser/extensions/shield-recipe-client/lib/NormandyDriver.jsm                                                                                                                             
merging browser/extensions/shield-recipe-client/lib/RecipeRunner.jsm                                                                                                                               
merging browser/extensions/shield-recipe-client/lib/SandboxManager.jsm                                                                                                                             
merging browser/extensions/shield-recipe-client/test/.eslintrc.js                                                                                                                                  
warning: conflicts while merging browser/extensions/shield-recipe-client/lib/Heartbeat.jsm! (edit, then use 'hg resolve --mark')                                                                   
warning: conflicts while merging browser/extensions/shield-recipe-client/lib/RecipeRunner.jsm! (edit, then use 'hg resolve --mark')                                                                
warning: conflicts while merging browser/extensions/shield-recipe-client/lib/SandboxManager.jsm! (edit, then use 'hg resolve --mark')                                                              
warning: conflicts while merging browser/extensions/shield-recipe-client/test/.eslintrc.js! (edit, then use 'hg resolve --mark')                                                                   
abort: unresolved conflicts, can't continue
(use 'hg resolve' and 'hg graft --continue')
Tomcats-MacBook-Pro-300:mozilla-central Tomcat$
Flags: needinfo?(mcooper)

Comment 29

2 years ago
bugherderuplift
https://hg.mozilla.org/releases/mozilla-aurora/rev/c02020dd7e6e
status-firefox53: affected → fixed
(Assignee)

Updated

2 years ago
Flags: needinfo?(mcooper)
11 failures in 733 pushes (0.015 failures/push) were associated with this bug in the last 7 days.  

Repository breakdown:
* try: 9
* autoland: 2

Platform breakdown:
* linux64: 9
* linux32: 2

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1325409&startday=2017-01-30&endday=2017-02-05&tree=all
Whiteboard: [stockwell fixed]
1 failures in 947 pushes (0.001 failures/push) were associated with this bug in the last 7 days.    

Repository breakdown:
* mozilla-central: 1

Platform breakdown:
* linux32-stylo-disabled: 1

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1325409&startday=2017-10-09&endday=2017-10-15&tree=all

Updated

9 months ago
Product: Shield → Firefox
1 failures in 831 pushes (0.001 failures/push) were associated with this bug in the last 7 days.    

Repository breakdown:
* mozilla-inbound: 1

Platform breakdown:
* linux32: 1

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1325409&startday=2018-02-26&endday=2018-03-04&tree=all
https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
Status: REOPENED → RESOLVED
Last Resolved: 2 years ago7 months ago
Resolution: --- → INCOMPLETE
You need to log in before you can comment on or make changes to this bug.