Filed by: dluca [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=302362342&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/f-CzbD7_SDKZilrSU3v22w/runs/0/artifacts/public/logs/live_backing.log

INFO - TEST-PASS | remote/test/browser/runtime/browser_executionContextEvents.js | The execution context has a frame id set - 
[task 2020-05-14T23:59:48.589Z] 23:59:48     INFO - Buffered messages logged at 23:59:47
[task 2020-05-14T23:59:48.589Z] 23:59:48     INFO - Received Runtime.executionContextDestroyed for id 1
[task 2020-05-14T23:59:48.589Z] 23:59:48     INFO - Received Runtime.executionContextsCleared
[task 2020-05-14T23:59:48.589Z] 23:59:48     INFO - Expected events: Runtime.executionContextDestroyed,Runtime.executionContextsCleared,Runtime.executionContextCreated
[task 2020-05-14T23:59:48.589Z] 23:59:48     INFO - Received events: Runtime.executionContextDestroyed,Runtime.executionContextsCleared
[task 2020-05-14T23:59:48.589Z] 23:59:48     INFO - Buffered messages finished
[task 2020-05-14T23:59:48.589Z] 23:59:48     INFO - TEST-UNEXPECTED-FAIL | remote/test/browser/runtime/browser_executionContextEvents.js | Received expected number of Runtime context events - Got 2, expected 3
[task 2020-05-14T23:59:48.589Z] 23:59:48     INFO - Stack trace:
[task 2020-05-14T23:59:48.589Z] 23:59:48     INFO - chrome://mochikit/content/browser-test.js:test_is:1327
[task 2020-05-14T23:59:48.589Z] 23:59:48     INFO - chrome://mochitests/content/browser/remote/test/browser/runtime/browser_executionContextEvents.js:assertEventOrder:314
[task 2020-05-14T23:59:48.589Z] 23:59:48     INFO - chrome://mochitests/content/browser/remote/test/browser/runtime/browser_executionContextEvents.js:eventsWhenNavigatingByLocationWithNoFrames:249
[task 2020-05-14T23:59:48.589Z] 23:59:48     INFO - chrome://mochitests/content/browser/remote/test/browser/head.js:fn:69
[task 2020-05-14T23:59:48.589Z] 23:59:48     INFO - chrome://mochikit/content/browser-test.js:Tester_execTest/<:1064
[task 2020-05-14T23:59:48.589Z] 23:59:48     INFO - chrome://mochikit/content/browser-test.js:Tester_execTest:1104
[task 2020-05-14T23:59:48.589Z] 23:59:48     INFO - chrome://mochikit/content/browser-test.js:nextTest/<:927
[task 2020-05-14T23:59:48.589Z] 23:59:48     INFO - chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:SimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<:918
[task 2020-05-14T23:59:48.589Z] 23:59:48     INFO - Not taking screenshot here: see the one that was previously logged
[task 2020-05-14T23:59:48.589Z] 23:59:48     INFO - TEST-UNEXPECTED-FAIL | remote/test/browser/runtime/browser_executionContextEvents.js | Received Runtime context events in expected order - ["Runtime.executionContextDestroyed","Runtime.executionContextsCleared"] deepEqual ["Runtime.executionContextDestroyed","Runtime.executionContextsCleared","Runtime.executionContextCreated"] - JS frame :: chrome://mochitests/content/browser/remote/test/browser/runtime/browser_executionContextEvents.js :: assertEventOrder :: line 319
[task 2020-05-14T23:59:48.589Z] 23:59:48     INFO - Stack trace:
[task 2020-05-14T23:59:48.589Z] 23:59:48     INFO - chrome://mochitests/content/browser/remote/test/browser/runtime/browser_executionContextEvents.js:assertEventOrder:319
[task 2020-05-14T23:59:48.589Z] 23:59:48     INFO - chrome://mochitests/content/browser/remote/test/browser/runtime/browser_executionContextEvents.js:eventsWhenNavigatingByLocationWithNoFrames:249
[task 2020-05-14T23:59:48.589Z] 23:59:48     INFO - chrome://mochitests/content/browser/remote/test/browser/head.js:fn:69
[task 2020-05-14T23:59:48.589Z] 23:59:48     INFO - chrome://mochikit/content/browser-test.js:Tester_execTest/<:1064
[task 2020-05-14T23:59:48.589Z] 23:59:48     INFO - chrome://mochikit/content/browser-test.js:Tester_execTest:1104
[task 2020-05-14T23:59:48.589Z] 23:59:48     INFO - chrome://mochikit/content/browser-test.js:nextTest/<:927
[task 2020-05-14T23:59:48.589Z] 23:59:48     INFO - chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:SimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<:918
[task 2020-05-14T23:59:48.589Z] 23:59:48     INFO - TEST-PASS | remote/test/browser/runtime/browser_executionContextEvents.js | The destroyed event reports the previous context id - 
[task 2020-05-14T23:59:48.589Z] 23:59:48     INFO - CDP client closed
[task 2020-05-14T23:59:48.589Z] 23:59:48     INFO - GECKO(5277) | 1589500788009	RemoteAgent	TRACE	<-(connection {613e693b-68bd-4948-9147-c0f5e69098eb}) {"method":"Target.targetDestroyed","params":{"targetId":"ea61f1fb-af69-4875-97c7-0beae5d40ca8"}}
[task 2020-05-14T23:59:48.598Z] 23:59:48     INFO - GECKO(5277) | 1589500788010	RemoteAgent	TRACE	<-(connection {613e693b-68bd-4948-9147-c0f5e69098eb}) {"method":"Target.targetDestroyed","params":{"targetId":"355f3c6d-2fab-4383-84bf-ebfe9f4ff307"}}
[task 2020-05-14T23:59:48.598Z] 23:59:48     INFO - GECKO(5277) | 1589500788010	RemoteAgent	TRACE	<-(connection {613e693b-68bd-4948-9147-c0f5e69098eb}) {"method":"Target.targetDestroyed","params":{"targetId":"b1e62b7d-f608-438b-9e19-7c365272906c"}}
[task 2020-05-14T23:59:48.598Z] 23:59:48     INFO - CDP server stopped
[task 2020-05-14T23:59:48.598Z] 23:59:48     INFO - Not taking screenshot here: see the one that was previously logged
[task 2020-05-14T23:59:48.598Z] 23:59:48     INFO - TEST-UNEXPECTED-FAIL | remote/test/browser/runtime/browser_executionContextEvents.js | Uncaught exception - at chrome://mochitests/content/browser/remote/test/browser/runtime/browser_executionContextEvents.js:327 - TypeError: can't access property "id", context is undefined
[task 2020-05-14T23:59:48.598Z] 23:59:48     INFO - Stack trace:
[task 2020-05-14T23:59:48.598Z] 23:59:48     INFO - checkDefaultContext@chrome://mochitests/content/browser/remote/test/browser/runtime/browser_executionContextEvents.js:327:7
[task 2020-05-14T23:59:48.598Z] 23:59:48     INFO - eventsWhenNavigatingByLocationWithNoFrames@chrome://mochitests/content/browser/remote/test/browser/runtime/browser_executionContextEvents.js:259:22
[task 2020-05-14T23:59:48.598Z] 23:59:48     INFO - async*fn@chrome://mochitests/content/browser/remote/test/browser/head.js:69:13
[task 2020-05-14T23:59:48.598Z] 23:59:48     INFO - Async*Tester_execTest/<@chrome://mochikit/content/browser-test.js:1064:34
[task 2020-05-14T23:59:48.598Z] 23:59:48     INFO - async*Tester_execTest@chrome://mochikit/content/browser-test.js:1104:11
[task 2020-05-14T23:59:48.598Z] 23:59:48     INFO - nextTest/<@chrome://mochikit/content/browser-test.js:927:14
[task 2020-05-14T23:59:48.598Z] 23:59:48     INFO - SimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:918:23
[task 2020-05-14T23:59:48.598Z] 23:59:48     INFO - Leaving test bound eventsWhenNavigatingByLocationWithNoFrames
[task 2020-05-14T23:59:48.598Z] 23:59:48     INFO - GECKO(5277) | MEMORY STAT | vsize 3462MB | residentFast 515MB | heapAllocated 182MB
[task 2020-05-14T23:59:48.598Z] 23:59:48     INFO - TEST-OK | remote/test/browser/runtime/browser_executionContextEvents.js | took 31459ms

This misses the executionContextCreated event like:

[task 2020-05-14T23:59:48.589Z] 23:59:48     INFO - Expected events: Runtime.executionContextDestroyed,Runtime.executionContextsCleared,Runtime.executionContextCreated
[task 2020-05-14T23:59:48.589Z] 23:59:48     INFO - Received events: Runtime.executionContextDestroyed,Runtime.executionContextsCleared

This happens here:
https://hg.mozilla.org/mozilla-central/file/tip/remote/test/browser/runtime/browser_executionContextEvents.js#l247

This should happen because setting window.location within Runtime.evaluate() doesn't actually wait for the page to be loaded. So that's a race condition here. My patch on bug 1593226 didn't actually change that particular part, but looks like due to the changed test order, it started to fail now.

Note that this only happens on Linux for debug builds and might be similar to the observation as I did on bug 1637363. The test here uses the history recorder for events with no specific timeout, and as such it falls back to 1s. That seems to be too short on that platform and build type. As such I bumped up the default timeout to 2s on that other bug.

Actually for a faster landing I will put this patch up here, and mark my other bug being blocked on it.

On Ubuntu 18.04 tests are failing more often for debug builds
due to not received events. Bumping up the value here seems to
help.

https://hg.mozilla.org/mozilla-central/rev/8eb4fd8e6b4d