Open Bug 1586503 Opened 2 months ago Updated 7 days ago

Intermittent Mac remote/test/browser/runtime/browser_executionContext.js | Test timed out -

Categories

(Remote Protocol :: Agent, defect, P5)

All
macOS
defect

Tracking

(firefox70 unaffected, firefox71 disabled)

Tracking Status
firefox70 --- unaffected
firefox71 --- disabled

People

(Reporter: aiakab, Unassigned)

References

(Regression)

Details

(4 keywords, Whiteboard: [stockwell disabled])

Attachments

(1 file)

+++ This bug was initially created as a clone of Bug #1547961 +++

Filed by: rgurzau [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=243601513&repo=autoland
Full log: https://queue.taskcluster.net/v1/task/ES4Ma6OvTj-y9mRSo6Vtgg/runs/0/artifacts/public/logs/live_backing.log
Reftest URL: https://hg.mozilla.org/mozilla-central/raw-file/tip/layout/tools/reftest/reftest-analyzer.xhtml#logurl=https://queue.taskcluster.net/v1/task/ES4Ma6OvTj-y9mRSo6Vtgg/runs/0/artifacts/public/logs/live_backing.log&only_show_unexpected=1


12:25:34 INFO - TEST-START | remote/test/browser/browser_runtime_executionContext.js
12:25:35 INFO - GECKO(823) | 1556627135707 RemoteAgent INFO Remote debugging agent listening on ws://localhost:9222/devtools/browser/dcebb924-f922-af49-b959-d305c1deab66
12:25:48 INFO - GECKO(823) | 2019-04-30 12:25:48.040 firefox[823:6126] Persistent UI failed to open file file:///Users/cltbld/Library/Saved%20Application%20State/org.mozilla.nightly.savedState/window_1.data: No such file or directory (2)
12:26:20 INFO - TEST-INFO | started process screencapture
12:26:20 INFO - TEST-INFO | screencapture: exit 0
12:26:20 INFO - Buffered messages logged at 12:25:34
12:26:20 INFO - Entering test bound
12:26:20 INFO - Buffered messages logged at 12:25:36
12:26:20 INFO - TEST-PASS | remote/test/browser/browser_runtime_executionContext.js | CDP client has been instantiated -
12:26:20 INFO - TEST-PASS | remote/test/browser/browser_runtime_executionContext.js | Runtime domain has been enabled -
12:26:20 INFO - TEST-PASS | remote/test/browser/browser_runtime_executionContext.js | The execution context has an id -
12:26:20 INFO - TEST-PASS | remote/test/browser/browser_runtime_executionContext.js | The execution context is the default one -
12:26:20 INFO - TEST-PASS | remote/test/browser/browser_runtime_executionContext.js | The execution context has a frame id set -
12:26:20 INFO - Navigate to a new URL
12:26:20 INFO - TEST-PASS | remote/test/browser/browser_runtime_executionContext.js | A new page has been loaded -
12:26:20 INFO - TEST-PASS | remote/test/browser/browser_runtime_executionContext.js | Page.navigate returns the same frameId than executionContextCreated -
12:26:20 INFO - TEST-PASS | remote/test/browser/browser_runtime_executionContext.js | The destroyed event reports the previous context id -
12:26:20 INFO - TEST-PASS | remote/test/browser/browser_runtime_executionContext.js | The execution context has an id -
12:26:20 INFO - TEST-PASS | remote/test/browser/browser_runtime_executionContext.js | The new execution context has a different id -
12:26:20 INFO - TEST-PASS | remote/test/browser/browser_runtime_executionContext.js | The execution context is the default one -
12:26:20 INFO - TEST-PASS | remote/test/browser/browser_runtime_executionContext.js | The execution context frame id is the same than the one returned by Page.navigate -
12:26:20 INFO - TEST-PASS | remote/test/browser/browser_runtime_executionContext.js | The destroyed id is different from the created one -
12:26:20 INFO - Navigate back to the previous document
12:26:20 INFO - Buffered messages finished
12:26:20 INFO - TEST-UNEXPECTED-FAIL | remote/test/browser/browser_runtime_executionContext.js | Test timed out -
12:26:20 INFO - GECKO(823) | MEMORY STAT | vsize 5441MB | residentFast 310MB | heapAllocated 89MB
12:26:20 INFO - TEST-OK | remote/test/browser/browser_runtime_executionContext.js | took 45065ms
12:26:20 INFO - Not taking screenshot here: see the one that was previously logged
12:26:20 INFO - TEST-UNEXPECTED-FAIL | remote/test/browser/browser_runtime_executionContext.js | Found a tab after previous test timed out: data:text/html;charset=utf-8,test-page -
12:26:20 INFO - checking window state
12:26:21 INFO - GECKO(823) | Completed ShutdownLeaks collections in process 831
12:26:21 INFO - GECKO(823) | Completed ShutdownLeaks collections in process 829
12:26:21 INFO - GECKO(823) | Completed ShutdownLeaks collections in process 832
12:26:21 INFO - GECKO(823) | Completed ShutdownLeaks collections in process 833

Regressed by: 1547961

Looks like it still happens one and off but only for debug builds on MacOS 10.14. I will have a look at it over the next days. So far I haven't been able to reproduce the problem yet.

No longer depends on: 1547961, 1585464
OS: Unspecified → macOS
Priority: P1 → P5
Hardware: Unspecified → All

Something fails at the beginning of the test:

[task 2019-10-05T13:02:56.402Z] 13:02:56     INFO - TEST-START | remote/test/browser/browser_runtime_executionContext.js
[task 2019-10-05T13:02:56.733Z] 13:02:56     INFO - GECKO(1660) | DevTools listening on ws://localhost:9222/devtools/browser/dae68fe8-a65e-304e-be2a-51be017530ac
[task 2019-10-05T13:03:41.420Z] 13:03:41     INFO - TEST-INFO | started process screencapture

So devtools started to listen on the web socket, but the test didn't get started. It's mainly debug builds, but also happens for opt builds.

I can reproduce this hang locally now. My assumption from the last comment is actually not correct. The hang happens while navigating back:

[task 2019-10-09T23:30:26.949Z] 23:30:26     INFO - TEST-PASS | remote/test/browser/browser_runtime_executionContext.js | The destroyed id is different from the created one - 
[task 2019-10-09T23:30:26.949Z] 23:30:26     INFO - Navigate back to the previous document

After the last info output nothing more happens. Having a look into that shows me that in working cases we get a pagehide event right before pageshow which I would expect here to happen. But when it fails this pagehide event is missing.

Working case:

 0:13.33 GECKO(44681) ** event: pagehide [object HTMLDocument] true
 0:13.33 GECKO(44681) [Child 44691, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80070057: file /builds/worker/workspace/build/src/dom/base/ThirdPartyUtil.cpp, line 217
 0:13.33 GECKO(44681) ** event: pageshow [object HTMLDocument] true

Failiing case:

0:17.44 GECKO(44681) ** event: pageshow [object HTMLDocument] false

And only having pageshow the persisted flag has a false value, which means we do not emit the context-created event:

https://searchfox.org/mozilla-central/rev/05a22d864814cb1e4352faa4004e1f975c7d2eb9/remote/domains/ContextObserver.jsm#86

There is a huge increase of intermittent failures recently, and this one actually turns into a perma failure on beta. It means that we should mark the test as skipped on MacOS again for now, while trying to investigate the problem.

Summary: Intermittent remote/test/browser/browser_runtime_executionContext.js | Test timed out - → Intermittent Mac remote/test/browser/browser_runtime_executionContext.js | Test timed out -
Pushed by hskupin@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/a7ca5ad33f3d
Temporarily skip remote/test/browser/browser_runtime_executionContext.js on Mac. r=remote-protocol-reviewers,maja_zf
Whiteboard: [stockwell unknown] → [stockwell disabled]

Because the new failures here were all on windows filed bug 1590930.

See Also: → 1590930

Updating summary for new location of the test.

Summary: Intermittent Mac remote/test/browser/browser_runtime_executionContext.js | Test timed out - → Intermittent Mac remote/test/browser/runtime/browser_executionContext.js | Test timed out -
You need to log in before you can comment on or make changes to this bug.