1638196 - Intermittent remote/test/browser/runtime/browser_executionContextEvents.js | Received expected number of Runtime context events - Got x, expected y

Status: RESOLVED FIXED

(Remote Protocol :: CDP, defect, P5)

Description

[Treeherder Bug Filer]

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

Comment 1

[Henrik Skupin [:whimboo][⌚️UTC+2] (away 10/03 - 10/13)]

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.

Comment 2

[Intermittent Failures Robot]

10 failures in 5488 pushes (0.002 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 10

Platform breakdown:

• linux1804-64-qr: 9
• linux1804-64: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1638196&startday=2020-05-11&endday=2020-05-17&tree=all

Comment 3

[Intermittent Failures Robot]

19 failures in 4727 pushes (0.004 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• try: 1
• autoland: 15
• mozilla-central: 3

Platform breakdown:

• linux1804-64-qr: 17
• linux1804-64: 2

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1638196&startday=2020-05-18&endday=2020-05-24&tree=all

Comment 4

[Henrik Skupin [:whimboo][⌚️UTC+2] (away 10/03 - 10/13)]

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.

Comment 5

[Henrik Skupin [:whimboo][⌚️UTC+2] (away 10/03 - 10/13)]

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

Comment 6

[Henrik Skupin [:whimboo][⌚️UTC+2] (away 10/03 - 10/13)]

Attachment: Bug 1638196 - [remote] Use timeout multipler for RecordEvents.record().

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.

Comment 7

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/8eb4fd8e6b4d
[remote] Use timeout multipler for RecordEvents.record(). r=remote-protocol-reviewers,maja_zf

Comment 8

[Andreea Pavel [:apavel]]

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

Comment 9

[Intermittent Failures Robot]

6 failures in 5458 pushes (0.001 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 4
• mozilla-central: 2

Platform breakdown:

• linux1804-64-qr: 4
• linux1804-64: 2

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1638196&startday=2020-05-25&endday=2020-05-31&tree=all