Filed by: malexandru [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=265860196&repo=mozilla-central
Full log: https://queue.taskcluster.net/v1/task/HoujNEEvQBW4tRlt86MKqA/runs/0/artifacts/public/logs/live_backing.log

[task 2019-09-10T04:37:53.207Z] 04:37:53 INFO - GECKO(1641) | [ReplayControl 1.59] ManifestFinished #0 {"point":{"checkpoint":3,"progress":2,"position":{"kind":"OnStep","script":1,"offset":66,"frameIndex":0}},"duration":40.34012900007656,"consoleMessages":[],"scripts":[{"id":1,"sourceId":1,"startLine":5,"lineCount":5,"sourceStart":0,"sourceLength":79,"url":"http://example.com/browser/devtools/client/webreplay/mochitest/examples/doc_debugger_statements.html","format":"js"}],"debuggerStatements":[{"checkpoint":3,"progress":2,"position":{"kind":"OnStep","script":1,"offset":66,"frameIndex":0}}]}
[task 2019-09-10T04:37:53.207Z] 04:37:53 INFO - GECKO(1641) | [ReplayControl 1.59] SendManifest #0 {"kind":"debuggerRequest","request":{"type":"getSource","id":1}}
[task 2019-09-10T04:37:53.207Z] 04:37:53 INFO - GECKO(1641) | [ReplayControl 1.59] ManifestFinished #0 {"response":{"id":1,"text":"\ndebugger;\ndocument.getElementById("maindiv").innerHTML = "Foobar!";\ndebugger;\n","url":"http://example.com/browser/devtools/client/webreplay/mochitest/examples/doc_debugger_statements.html","displayURL":null,"introductionScript":0,"introductionType":"scriptElement","sourceMapURL":null},"divergedFromRecording":false}
[task 2019-09-10T04:37:53.222Z] 04:37:53 INFO - GECKO(1641) | [ReplayControl 1.59] SendManifest #0 {"kind":"resume","breakpoints":[],"pauseOnDebuggerStatement":false}
[task 2019-09-10T04:37:53.322Z] 04:37:53 INFO - GECKO(1641) | [ReplayControl 1.69] ManifestFinished #0 {"point":{"checkpoint":4,"progress":2},"duration":101.78143399994588,"consoleMessages":[],"scripts":[],"debuggerStatements":[{"checkpoint":3,"progress":2,"position":{"kind":"OnStep","script":1,"offset":197,"frameIndex":0}}]}
[task 2019-09-10T04:37:53.322Z] 04:37:53 INFO - GECKO(1641) | [ReplayControl 1.69] SendManifest #0 {"kind":"flushRecording"}
[task 2019-09-10T04:37:53.323Z] 04:37:53 INFO - GECKO(1641) | [ReplayControl 1.7] ManifestFinished #0 undefined
[task 2019-09-10T04:37:53.324Z] 04:37:53 INFO - GECKO(1641) | [ReplayControl 1.7] AddSavedCheckpoint #3 4
[task 2019-09-10T04:37:53.324Z] 04:37:53 INFO - GECKO(1641) | [ReplayControl 1.7] SendManifest #1 {"kind":"scanRecording","endpoint":{"checkpoint":4,"progress":2},"snapshotPoints":[]}
[task 2019-09-10T04:37:53.325Z] 04:37:53 INFO - GECKO(1641) | [ReplayControl 1.7] SendManifest #2 {"kind":"runToPoint","endpoint":{"checkpoint":4,"progress":2},"snapshotPoints":[]}
[task 2019-09-10T04:37:53.325Z] 04:37:53 INFO - GECKO(1641) | [ReplayControl 1.7] SendManifest #3 {"kind":"runToPoint","endpoint":{"checkpoint":4,"progress":2},"snapshotPoints":[{"checkpoint":4,"progress":2}]}
[task 2019-09-10T04:37:53.325Z] 04:37:53 INFO - GECKO(1641) | JavaScript error: resource://devtools/shared/execution-point-utils.js, line 57: TypeError: pointB is undefined
[task 2019-09-10T04:37:53.333Z] 04:37:53 INFO - GECKO(1641) | [ReplayControl 1.7] ManifestFinished #4 {"point":{"checkpoint":1,"progress":1}}
[task 2019-09-10T04:37:53.334Z] 04:37:53 INFO - GECKO(1641) | [ReplayControl 1.7] SendManifest #4 {"kind":"runToPoint","endpoint":{"checkpoint":4,"progress":2},"snapshotPoints":[]}
[task 2019-09-10T04:37:53.893Z] 04:37:53 INFO - GECKO(1641) | [ReplayControl 2.27] ManifestFinished #1 {"point":{"checkpoint":4,"progress":2},"duration":570.892286999966,"memoryUsage":{"Generic":28672,"Snapshots":23916544,"ScriptHits":16384}}
[task 2019-09-10T04:37:53.988Z] 04:37:53 INFO - GECKO(1641) | [ReplayControl 2.35] ManifestFinished #3 {"point":{"checkpoint":4,"progress":2}}
[task 2019-09-10T04:37:53.989Z] 04:37:53 INFO - GECKO(1641) | [ReplayControl 2.35] ManifestFinished #4 {"point":{"checkpoint":4,"progress":2}}
[task 2019-09-10T04:37:53.994Z] 04:37:53 INFO - GECKO(1641) | [ReplayControl 2.36] ManifestFinished #2 {"point":{"checkpoint":4,"progress":2}}
[task 2019-09-10T04:37:54.426Z] 04:37:54 INFO - GECKO(1641) | [ReplayControl 2.79] SendManifest #0 {"kind":"debuggerRequest","request":{"type":"findSources"}}
[task 2019-09-10T04:37:54.427Z] 04:37:54 INFO - GECKO(1641) | [ReplayControl 2.79] ManifestFinished #0 {"response":[{"id":1,"text":"\ndebugger;\ndocument.getElementById("maindiv").innerHTML = "Foobar!";\ndebugger;\n","url":"http://example.com/browser/devtools/client/webreplay/mochitest/examples/doc_debugger_statements.html","displayURL":null,"introductionScript":0,"introductionType":"scriptElement","sourceMapURL":null}],"divergedFromRecording":false}
[task 2019-09-10T04:37:54.427Z] 04:37:54 INFO - GECKO(1641) | [ReplayControl 2.79] SendManifest #0 {"kind":"debuggerRequest","request":{"type":"findSources"}}
[task 2019-09-10T04:37:54.427Z] 04:37:54 INFO - GECKO(1641) | [ReplayControl 2.79] ManifestFinished #0 {"response":[{"id":1,"text":"\ndebugger;\ndocument.getElementById("maindiv").innerHTML = "Foobar!";\ndebugger;\n","url":"http://example.com/browser/devtools/client/webreplay/mochitest/examples/doc_debugger_statements.html","displayURL":null,"introductionScript":0,"introductionType":"scriptElement","sourceMapURL":null}],"divergedFromRecording":false}
[task 2019-09-10T04:40:22.724Z] 04:40:22 INFO - TEST-INFO | started process screencapture
[task 2019-09-10T04:40:22.852Z] 04:40:22 INFO - TEST-INFO | screencapture: exit 0
[task 2019-09-10T04:40:22.854Z] 04:40:22 INFO - Buffered messages logged at 04:37:22
[task 2019-09-10T04:40:22.855Z] 04:40:22 INFO - Entering test bound
[task 2019-09-10T04:40:22.855Z] 04:40:22 INFO - Buffered messages logged at 04:37:51
[task 2019-09-10T04:40:22.855Z] 04:40:22 INFO - Console message: [JavaScript Error: "ReferenceError: Services is not defined" {file: "chrome://global/content/browser-child.js" line: 26}]
[task 2019-09-10T04:40:22.855Z] 04:40:22 INFO - Buffered messages logged at 04:37:53
[task 2019-09-10T04:40:22.856Z] 04:40:22 INFO - Console message: [JavaScript Error: "TypeError: pointB is undefined" {file: "resource://devtools/shared/execution-point-utils.js" line: 57}]
[task 2019-09-10T04:40:22.856Z] 04:40:22 INFO - Buffered messages logged at 04:37:54
[task 2019-09-10T04:40:22.856Z] 04:40:22 INFO - Waiting for state change: paused
[task 2019-09-10T04:40:22.856Z] 04:40:22 INFO - Buffered messages logged at 04:38:07
[task 2019-09-10T04:40:22.857Z] 04:40:22 INFO - Longer timeout required, waiting longer... Remaining timeouts: 3
[task 2019-09-10T04:40:22.857Z] 04:40:22 INFO - Buffered messages logged at 04:38:52
[task 2019-09-10T04:40:22.857Z] 04:40:22 INFO - Longer timeout required, waiting longer... Remaining timeouts: 2
[task 2019-09-10T04:40:22.857Z] 04:40:22 INFO - Buffered messages logged at 04:39:37
[task 2019-09-10T04:40:22.858Z] 04:40:22 INFO - Longer timeout required, waiting longer... Remaining timeouts: 1
[task 2019-09-10T04:40:22.858Z] 04:40:22 INFO - Buffered messages finished
[task 2019-09-10T04:40:22.858Z] 04:40:22 INFO - TEST-UNEXPECTED-FAIL | devtools/client/webreplay/mochitest/browser_dbg_rr_breakpoints-07.js | Test timed out -
[task 2019-09-10T04:40:22.858Z] 04:40:22 INFO - Removing tab.
[task 2019-09-10T04:40:22.858Z] 04:40:22 INFO - Waiting for event: 'TabClose' on [object XULElement].
[task 2019-09-10T04:40:22.866Z] 04:40:22 INFO - Got event: 'TabClose' on [object XULElement].
[task 2019-09-10T04:40:22.887Z] 04:40:22 INFO - Tab removed and finished closing
[task 2019-09-10T04:40:22.920Z] 04:40:22 INFO - GECKO(1641) | JavaScript error: resource://testing-common/PromiseTestUtils.jsm, line 112: uncaught exception: Object
[task 2019-09-10T04:40:22.921Z] 04:40:22 INFO - Console message: [JavaScript Error: "uncaught exception: Object" {file: "resource://testing-common/PromiseTestUtils.jsm" line: 112}]
[task 2019-09-10T04:40:22.921Z] 04:40:22 INFO - GECKO(1641) | MEMORY STAT | vsize 7772MB | residentFast 446MB | heapAllocated 109MB
[task 2019-09-10T04:40:22.921Z] 04:40:22 INFO - TEST-OK | devtools/client/webreplay/mochitest/browser_dbg_rr_breakpoints-07.js | took 180618ms

Brian, Jason, this is still perma failling on all trees.
(autoland example here): https://treeherder.mozilla.org/#/jobs?repo=autoland&searchStr=dt%2Cwr&fromchange=093599edfef84f61c8211b67ded2b037068d9020&tochange=d76478e79d37ec8d36f41423fc9ca401345bbba4

Failures seem to be either timeouts for "browser_dbg_rr_breakpoints-0X.js", "browser_dbg_rr_logpoint-01.js"
(log): https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=265845884&repo=autoland&lineNumber=1505

Another frequent failure is: "browser_dbg_rr_logpoint-0X.js / browser_dbg_rr_breakpoints-0X.js | a new breakpoint was created - Got X, expected Y / Paused at line X expected Y - / Eval returned x -"
(examples):
https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=265867522&repo=autoland&lineNumber=2380
https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=265860721&repo=autoland&lineNumber=3463

Depends on D45464

https://hg.mozilla.org/mozilla-central/rev/2bddf3f650f5

Brian, "browser_dbg_rr_stepping-0X" and "browser_dbg_rr_replay-0X" are also timing out, perhaps we should classify them against this bug as well.
(examples):
https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=266093681&repo=autoland&lineNumber=3648
https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=266087599&repo=autoland&lineNumber=7706

Also, I reopened this bug as it seems to be a recurring issue, feel free to close when you think it's appropriate.

https://hg.mozilla.org/mozilla-central/rev/0ba37acfca9b

(In reply to Alexandru Michis [:malexandru] from comment #7)

Brian, "browser_dbg_rr_stepping-0X" and "browser_dbg_rr_replay-0X" are also timing out, perhaps we should classify them against this bug as well.
(examples):
https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=266093681&repo=autoland&lineNumber=3648
https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=266087599&repo=autoland&lineNumber=7706

Also, I reopened this bug as it seems to be a recurring issue, feel free to close when you think it's appropriate.

These tests all seem to be failing with the same/similar crash. Unfortunately I can't reproduce this locally, but I'll see if I can figure out what's going on with some diagnostics on try.

Hi Brian. The dt-wr fails on every push on integration: https://treeherder.mozilla.org/#/jobs?repo=autoland&resultStatus=success%2Ctestfailed%2Cbusted%2Cexception&searchStr=dt-wr&fromchange=517bdcd80445ff9d6bd8b0aba7ba7bc325f91744&tochange=8eeddedeedb8fc9ef3594086d0759051b51e8db0

Could we help you out with something in order to reproduce it?

I looked in the .ini file for these tests and noticed that the test-suite has skip-if = os != "mac" || debug || !nightly_build, could that be modified to get rid of the failures? or could we disable the tests on mac?

(In reply to Andreea Pavel [:apavel] from comment #14)

I looked in the .ini file for these tests and noticed that the test-suite has skip-if = os != "mac" || debug || !nightly_build, could that be modified to get rid of the failures? or could we disable the tests on mac?

The tests only run on mac builds, because that is the only platform which web replay currently supports.

I'm making progress with using try builds to figure out what's going on, but it's a rather slow process as it takes a very long time for mac try runs to complete (the dt-wr run I triggered yesterday took 7 hours before it started running).

Okay Brian, thank you for explaining.
I just have one more question though, can we use this bug only to classify similar failures or file separate bugs?

(In reply to Andreea Pavel [:apavel] from comment #16)

Okay Brian, thank you for explaining.
I just have one more question though, can we use this bug only to classify similar failures or file separate bugs?

Sure, it's fine to classify all dt-wr failures using this bug until the problem is fixed.

Thank you very much.

The problem here is a regression from bug 1579301: after that bug different threads can be sending messages over the record/replay channel at the same time, and there is no locking which ensures those messages will be sent atomically.

https://treeherder.mozilla.org/#/jobs?repo=try&revision=ef13dffe758794b511fe10d388f5c15e209cd08c

https://hg.mozilla.org/mozilla-central/rev/a8b8823a6b72

Hi Brian. Since your patch landed this is no longer perma-failing, however there still are some occurences:

https://treeherder.mozilla.org/#/jobs?repo=autoland&resultStatus=success%2Ctestfailed%2Cbusted%2Cexception&searchStr=os%2Cx%2C10.14%2Cshippable%2Copt%2Cmochitests%2Ctest-macosx1014-64-shippable%2Fopt-mochitest-devtools-webreplay-e10s%2Cm%28dt-wr%29&fromchange=72d9ad70e1ba7d56e9e3732cfd912f53c348a9a8&tochange=c42f6c24277685fa7592a6ce596144289506bdaa

(In reply to Andreea Pavel [:apavel] from comment #25)

Hi Brian. Since your patch landed this is no longer perma-failing, however there still are some occurences:

https://treeherder.mozilla.org/#/jobs?repo=autoland&resultStatus=success%2Ctestfailed%2Cbusted%2Cexception&searchStr=os%2Cx%2C10.14%2Cshippable%2Copt%2Cmochitests%2Ctest-macosx1014-64-shippable%2Fopt-mochitest-devtools-webreplay-e10s%2Cm%28dt-wr%29&fromchange=72d9ad70e1ba7d56e9e3732cfd912f53c348a9a8&tochange=c42f6c24277685fa7592a6ce596144289506bdaa

Thanks, I just tried on tip and still can't reproduce these failures locally. I'll do more diagnosis with try builds to look into these.

(In reply to Brian Hackett (:bhackett) from comment #26)

(In reply to Andreea Pavel [:apavel] from comment #25)

Hi Brian. Since your patch landed this is no longer perma-failing, however there still are some occurences:

https://treeherder.mozilla.org/#/jobs?repo=autoland&resultStatus=success%2Ctestfailed%2Cbusted%2Cexception&searchStr=os%2Cx%2C10.14%2Cshippable%2Copt%2Cmochitests%2Ctest-macosx1014-64-shippable%2Fopt-mochitest-devtools-webreplay-e10s%2Cm%28dt-wr%29&fromchange=72d9ad70e1ba7d56e9e3732cfd912f53c348a9a8&tochange=c42f6c24277685fa7592a6ce596144289506bdaa

Thanks, I just tried on tip and still can't reproduce these failures locally. I'll do more diagnosis with try builds to look into these.

Hmm, I did a try run with about 50 runs of dt-wr and only got one failure, which I've included a fix for in bug 1581665.

https://treeherder.mozilla.org/#/jobs?repo=try&revision=07d4ecf84ea67e613343718ae75837548c0ff629

I see no other failures since the 16th of September. I think we can consider this fixed for now.

There are 65 total failures in the last 7 days on macosx1014-64-shippable opt

Recent failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=268485910&repo=autoland&lineNumber=3474

[task 2019-09-26T01:41:06.151Z] 01:41:06 INFO - checking window state
[task 2019-09-26T01:41:06.156Z] 01:41:06 INFO - TEST-START | devtools/client/webreplay/mochitest/browser_dbg_rr_breakpoints-04.js
[task 2019-09-26T01:41:06.213Z] 01:41:06 INFO - GECKO(1847) | MIDDLEMAN 1884 /var/folders/9z/_jc95mbn6rn_cmglvtrpt3cc000017/T/TempRecording.1847.4
[task 2019-09-26T01:41:06.270Z] 01:41:06 INFO - GECKO(1847) | RECORDING 1885 /var/folders/9z/_jc95mbn6rn_cmglvtrpt3cc000017/T/TempRecording.1847.4
[task 2019-09-26T01:41:06.793Z] 01:41:06 INFO - GECKO(1847) | JavaScript error: chrome://global/content/browser-child.js, line 26: ReferenceError: Services is not defined

[task 2019-09-26T01:44:06.600Z] 01:44:06 INFO - TEST-INFO | started process screencapture
[task 2019-09-26T01:44:06.734Z] 01:44:06 INFO - TEST-INFO | screencapture: exit 0
[task 2019-09-26T01:44:06.734Z] 01:44:06 INFO - Buffered messages logged at 01:41:06
[task 2019-09-26T01:44:06.734Z] 01:44:06 INFO - Entering test bound
[task 2019-09-26T01:44:06.734Z] 01:44:06 INFO - Console message: [JavaScript Error: "ReferenceError: Services is not defined" {file: "chrome://global/content/browser-child.js" line: 26}]
[task 2019-09-26T01:44:06.734Z] 01:44:06 INFO - Buffered messages logged at 01:41:08
[task 2019-09-26T01:44:06.735Z] 01:44:06 INFO - Console message: [JavaScript Error: "The character encoding of the HTML document was not declared. The document will render with garbled text in some browser configurations if the document contains characters from outside the US-ASCII range. The character encoding of the page must be declared in the document or in the transfer protocol." {file: "http://example.com/browser/devtools/client/webreplay/mochitest/examples/doc_rr_continuous.html" line: 0}]
[task 2019-09-26T01:44:06.735Z] 01:44:06 INFO - Buffered messages logged at 01:41:14
[task 2019-09-26T01:44:06.735Z] 01:44:06 INFO - Waiting for state change: paused
[task 2019-09-26T01:44:06.735Z] 01:44:06 INFO - Finished waiting for state change: paused
[task 2019-09-26T01:44:06.736Z] 01:44:06 INFO - Buffered messages logged at 01:41:15
[task 2019-09-26T01:44:06.736Z] 01:44:06 INFO - TEST-PASS | devtools/client/webreplay/mochitest/browser_dbg_rr_breakpoints-04.js | a new breakpoint was created -
[task 2019-09-26T01:44:06.736Z] 01:44:06 INFO - Waiting for state change: paused
[task 2019-09-26T01:44:06.736Z] 01:44:06 INFO - Buffered messages logged at 01:41:17
[task 2019-09-26T01:44:06.736Z] 01:44:06 INFO - Console message: [JavaScript Error: "remote browser crashed while on http://example.com/browser/devtools/client/webreplay/mochitest/examples/doc_rr_continuous.html
[task 2019-09-26T01:44:06.736Z] 01:44:06 INFO - " {file: "chrome://mochikit/content/mochitest-e10s-utils.js" line: 10}]
[task 2019-09-26T01:44:06.736Z] 01:44:06 INFO - e10s_init/<@chrome://mochikit/content/mochitest-e10s-utils.js:10:10
[task 2019-09-26T01:44:06.736Z] 01:44:06 INFO - EventListener.handleEvente10s_init@chrome://mochikit/content/mochitest-e10s-utils.js:6:10
[task 2019-09-26T01:44:06.736Z] 01:44:06 INFO - testInit@chrome://mochikit/content/browser-test.js:131:5
[task 2019-09-26T01:44:06.736Z] 01:44:06 INFO - setTimeout handler@chrome://mochikit/content/browser-test.js:41:11
[task 2019-09-26T01:44:06.737Z] 01:44:06 INFO - loadChromeScripts@jar:file:///var/folders/9z/_jc95mbn6rn_cmglvtrpt3cc000017/T/tmpnUFq30.mozrunner/extensions/mochikit@mozilla.org.xpi!/api.js:21:25
[task 2019-09-26T01:44:06.737Z] 01:44:06 INFO - loadMochitest@jar:file:///var/folders/9z/jc95mbn6rn_cmglvtrpt3cc000017/T/tmpnUFq30.mozrunner/extensions/mochikit@mozilla.org.xpi!/api.js:143:20
[task 2019-09-26T01:44:06.737Z] 01:44:06 INFO - @tests/mochitest/runtests.py:1810:5
[task 2019-09-26T01:44:06.737Z] 01:44:06 INFO - @tests/mochitest/runtests.py:1811:8
[task 2019-09-26T01:44:06.737Z] 01:44:06 INFO - evaluate.sandbox/promise<@chrome://marionette/content/evaluate.js:138:10
[task 2019-09-26T01:44:06.737Z] 01:44:06 INFO - evaluate.sandbox@chrome://marionette/content/evaluate.js:114:17
[task 2019-09-26T01:44:06.737Z] 01:44:06 INFO - GeckoDriver.prototype.execute@chrome://marionette/content/driver.js:1070:28
[task 2019-09-26T01:44:06.737Z] 01:44:06 INFO - async*GeckoDriver.prototype.executeScript@chrome://marionette/content/driver.js:945:30
[task 2019-09-26T01:44:06.737Z] 01:44:06 INFO - despatch@chrome://marionette/content/server.js:305:40
[task 2019-09-26T01:44:06.737Z] 01:44:06 INFO - execute@chrome://marionette/content/server.js:275:16
[task 2019-09-26T01:44:06.737Z] 01:44:06 INFO - onPacket/<@chrome://marionette/content/server.js:248:20
[task 2019-09-26T01:44:06.737Z] 01:44:06 INFO - onPacket@chrome://marionette/content/server.js:249:9
[task 2019-09-26T01:44:06.737Z] 01:44:06 INFO - _onJSONObjectReady/<@chrome://marionette/content/transport.js:501:20
[task 2019-09-26T01:44:06.737Z] 01:44:06 INFO -
[task 2019-09-26T01:44:06.737Z] 01:44:06 INFO - Buffered messages logged at 01:41:51
[task 2019-09-26T01:44:06.738Z] 01:44:06 INFO - Longer timeout required, waiting longer... Remaining timeouts: 3
[task 2019-09-26T01:44:06.738Z] 01:44:06 INFO - Buffered messages logged at 01:42:36
[task 2019-09-26T01:44:06.738Z] 01:44:06 INFO - Longer timeout required, waiting longer... Remaining timeouts: 2
[task 2019-09-26T01:44:06.738Z] 01:44:06 INFO - Buffered messages logged at 01:43:21
[task 2019-09-26T01:44:06.738Z] 01:44:06 INFO - Longer timeout required, waiting longer... Remaining timeouts: 1
[task 2019-09-26T01:44:06.738Z] 01:44:06 INFO - Buffered messages finished
[task 2019-09-26T01:44:06.738Z] 01:44:06 INFO - TEST-UNEXPECTED-FAIL | devtools/client/webreplay/mochitest/browser_dbg_rr_breakpoints-04.js | Test timed out -
[task 2019-09-26T01:44:06.739Z] 01:44:06 INFO - Removing tab.
[task 2019-09-26T01:44:06.739Z] 01:44:06 INFO - Waiting for event: 'TabClose' on [object XULElement].

The fix for bug 1483398 should take care of this.

https://treeherder.mozilla.org/#/jobs?repo=try&revision=46e23cc9018140d5f1ffc801a7e8a4e11e377b28&selectedJob=268500888

The failures here have toned down.

Retriggered: https://treeherder.mozilla.org/#/jobs?repo=autoland&fromchange=3850aea9c18d82aac4b388a6996fb37803a1a320&searchStr=dt-wr&tochange=a86601acb57bce3f998511f5944df2a98cd2ac24&selectedJob=270821193

Matt, can you please take a look at this? Started to perma fail. Could bug 1578624 be the culprit?

Brian, can you please take a look?

I'll look into this today.

The problem here is that if we try to load a URL in a recording tab before the recording process has initialized and set its own window global as the current one, then the URL load happens in the middleman's window global and nothing ends up happening. I've looked into ways of working around this in C++ (waiting until the recording has initialized before the load happens) but this is pretty awkward. It seems best to just delay loading URLs in recording tabs until enough initialization has occurred, which can be done from JS.

https://hg.mozilla.org/mozilla-central/rev/203e2a744ac0

No occurrences since the fix landed.

Brian, this has started perma-failing again since the changes in Bug 1594861 landed:

https://treeherder.mozilla.org/#/jobs?repo=autoland&resultStatus=testfailed%2Cbusted%2Cexception%2Csuccess%2Cusercancel%2Crunning%2Cpending%2Crunnable&fromchange=8d10108fdd91bb0b4727d8e4210fad99d8804e27&searchStr=os%2Cx%2C10.14%2Cshippable%2Copt%2Cmochitests%2Ctest-macosx1014-64-shippable%2Fopt-mochitest-devtools-webreplay-e10s%2Cm%28dt-wr%29&tochange=8c5e8ea700d908be2785b1d5c2e4feed9b31a091&selectedJob=277264619

Could you please take a look?

Gerald, could you please look into this?

https://hg.mozilla.org/mozilla-central/rev/4b138c336e87

There are 23 total failures since the 19th of January on macosx1014-64-shippable opt.

Recent failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=285751885&repo=mozilla-central&lineNumber=962

[task 2020-01-21T11:30:58.909Z] 11:30:58 INFO - TEST-START | devtools/client/webreplay/mochitest/browser_dbg_rr_breakpoints-01.js
[task 2020-01-21T11:30:59.084Z] 11:30:59 INFO - GECKO(1871) | MIDDLEMAN 1876 /var/folders/hg/2485jg4s6vq8ggdnpc4ykz_4000017/T/TempRecording.1871.1
[task 2020-01-21T11:30:59.145Z] 11:30:59 INFO - GECKO(1871) | RECORDING 1877 /var/folders/hg/2485jg4s6vq8ggdnpc4ykz_4000017/T/TempRecording.1871.1
[task 2020-01-21T11:30:59.461Z] 11:30:59 INFO - GECKO(1871) | JavaScript error: chrome://global/content/browser-child.js, line 26: ReferenceError: Services is not defined
[task 2020-01-21T11:30:59.844Z] 11:30:59 INFO - GECKO(1871) | [ReplayControl 0.42] ManifestFinished #0 {"point":{"checkpoint":1,"progress":0}}
[task 2020-01-21T11:30:59.844Z] 11:30:59 INFO - GECKO(1871) | [ReplayControl 0.42] SendManifest #0 {"kind":"flushRecording"}
[task 2020-01-21T11:30:59.844Z] 11:30:59 INFO - GECKO(1871) | [ReplayControl 0.42] WaitUntilPaused #0
[task 2020-01-21T11:30:59.844Z] 11:30:59 INFO - GECKO(1871) | [ReplayControl 0.43] ManifestFinished #0 undefined
[task 2020-01-21T11:30:59.844Z] 11:30:59 INFO - GECKO(1871) | [ReplayControl 0.43] WaitUntilPaused Done
[task 2020-01-21T11:30:59.960Z] 11:30:59 INFO - GECKO(1871) | IPDL protocol error: Handler returned error code!
[task 2020-01-21T11:30:59.960Z] 11:30:59 INFO - GECKO(1871) | ###!!! [Parent][DispatchAsyncMessage] Error: PContent::Msg_CommitBrowsingContextTransaction Processing error: message was deserialized, but the handler returned false (indicating failure)
[task 2020-01-21T11:30:59.960Z] 11:30:59 INFO - GECKO(1871) | [Parent 1871, Gecko_IOThread] WARNING: FileDescriptorSet destroyed with unconsumed descriptors: file /builds/worker/workspace/build/src/ipc/chromium/src/chrome/common/file_descriptor_set_posix.cc, line 23
[task 2020-01-21T11:31:25.568Z] 11:31:25 INFO - GECKO(1871) | 2020-01-21 11:31:25.546 firefox[1871:9880] 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)
[task 2020-01-21T11:33:59.475Z] 11:33:59 INFO - TEST-INFO | started process screencapture
[task 2020-01-21T11:33:59.643Z] 11:33:59 INFO - TEST-INFO | screencapture: exit 0
[task 2020-01-21T11:33:59.643Z] 11:33:59 INFO - Buffered messages logged at 11:30:59
[task 2020-01-21T11:33:59.643Z] 11:33:59 INFO - Entering test bound
[task 2020-01-21T11:33:59.643Z] 11:33:59 INFO - Waiting for event: 'RecordingInitialized' on [object ParentProcessMessageManager].
[task 2020-01-21T11:33:59.643Z] 11:33:59 INFO - Console message: [JavaScript Error: "ReferenceError: Services is not defined" {file: "chrome://global/content/browser-child.js" line: 26}]
[task 2020-01-21T11:33:59.643Z] 11:33:59 INFO - Console message: [JavaScript Error: "remote browser crashed while on about:blank
[task 2020-01-21T11:33:59.643Z] 11:33:59 INFO - " {file: "chrome://mochikit/content/mochitest-e10s-utils.js" line: 10}]
[task 2020-01-21T11:33:59.643Z] 11:33:59 INFO - e10s_init/<@chrome://mochikit/content/mochitest-e10s-utils.js:10:10
[task 2020-01-21T11:33:59.643Z] 11:33:59 INFO - EventListener.handleEvente10s_init@chrome://mochikit/content/mochitest-e10s-utils.js:6:10
[task 2020-01-21T11:33:59.643Z] 11:33:59 INFO - testInit@chrome://mochikit/content/browser-test.js:130:5
[task 2020-01-21T11:33:59.643Z] 11:33:59 INFO - setTimeout handler@chrome://mochikit/content/browser-test.js:40:11
[task 2020-01-21T11:33:59.643Z] 11:33:59 INFO - loadChromeScripts@jar:file:///var/folders/hg/2485jg4s6vq8ggdnpc4ykz_4000017/T/tmpfKcWxB.mozrunner/extensions/mochikit@mozilla.org.xpi!/api.js:21:25
[task 2020-01-21T11:33:59.643Z] 11:33:59 INFO - loadMochitest@jar:file:///var/folders/hg/2485jg4s6vq8ggdnpc4ykz_4000017/T/tmpfKcWxB.mozrunner/extensions/mochikit@mozilla.org.xpi!/api.js:143:20
[task 2020-01-21T11:33:59.643Z] 11:33:59 INFO - @tests/mochitest/runtests.py:1794:5
[task 2020-01-21T11:33:59.643Z] 11:33:59 INFO - @tests/mochitest/runtests.py:1795:8
[task 2020-01-21T11:33:59.643Z] 11:33:59 INFO - evaluate.sandbox/promise<@chrome://marionette/content/evaluate.js:138:10
[task 2020-01-21T11:33:59.643Z] 11:33:59 INFO - evaluate.sandbox@chrome://marionette/content/evaluate.js:114:17
[task 2020-01-21T11:33:59.643Z] 11:33:59 INFO - GeckoDriver.prototype.execute_@chrome://marionette/content/driver.js:1099:28
[task 2020-01-21T11:33:59.643Z] 11:33:59 INFO - async*GeckoDriver.prototype.executeScript@chrome://marionette/content/driver.js:974:30
[task 2020-01-21T11:33:59.643Z] 11:33:59 INFO - despatch@chrome://marionette/content/server.js:305:40
[task 2020-01-21T11:33:59.643Z] 11:33:59 INFO - execute@chrome://marionette/content/server.js:275:16
[task 2020-01-21T11:33:59.643Z] 11:33:59 INFO - onPacket/<@chrome://marionette/content/server.js:248:20
[task 2020-01-21T11:33:59.643Z] 11:33:59 INFO - onPacket@chrome://marionette/content/server.js:249:9
[task 2020-01-21T11:33:59.644Z] 11:33:59 INFO - _onJSONObjectReady/<@chrome://marionette/content/transport.js:501:20
[task 2020-01-21T11:33:59.644Z] 11:33:59 INFO -
[task 2020-01-21T11:33:59.644Z] 11:33:59 INFO - Buffered messages logged at 11:31:44
[task 2020-01-21T11:33:59.644Z] 11:33:59 INFO - Longer timeout required, waiting longer... Remaining timeouts: 3
[task 2020-01-21T11:33:59.644Z] 11:33:59 INFO - Buffered messages logged at 11:32:29
[task 2020-01-21T11:33:59.644Z] 11:33:59 INFO - Longer timeout required, waiting longer... Remaining timeouts: 2
[task 2020-01-21T11:33:59.644Z] 11:33:59 INFO - Buffered messages logged at 11:33:14
[task 2020-01-21T11:33:59.645Z] 11:33:59 INFO - Longer timeout required, waiting longer... Remaining timeouts: 1
[task 2020-01-21T11:33:59.645Z] 11:33:59 INFO - Buffered messages finished
[task 2020-01-21T11:33:59.645Z] 11:33:59 INFO - TEST-UNEXPECTED-FAIL | devtools/client/webreplay/mochitest/browser_dbg_rr_breakpoints-01.js | Test timed out -
[task 2020-01-21T11:33:59.645Z] 11:33:59 INFO - Removing tab.
[task 2020-01-21T11:33:59.646Z] 11:33:59 INFO - Waiting for event: 'TabClose' on [object XULElement].
[task 2020-01-21T11:33:59.646Z] 11:33:59 INFO - Got event: 'TabClose' on [object XULElement].
[task 2020-01-21T11:33:59.646Z] 11:33:59 INFO - Tab removed and finished closing
[task 2020-01-21T11:33:59.646Z] 11:33:59 INFO - TEST-PASS | devtools/client/webreplay/mochitest/browser_dbg_rr_breakpoints-01.js | The main process DebuggerServer has no pending connection when the test ends -
[task 2020-01-21T11:33:59.647Z] 11:33:59 INFO - TEST-PASS | devtools/client/webreplay/mochitest/browser_dbg_rr_breakpoints-01.js | The main process DebuggerServer has no pending connection when the test ends -
[task 2020-01-21T11:33:59.648Z] 11:33:59 INFO - GECKO(1871) | MEMORY STAT vsizeMaxContiguous not supported in this build configuration.
[task 2020-01-21T11:33:59.648Z] 11:33:59 INFO - GECKO(1871) | MEMORY STAT | vsize 7602MB | residentFast 346MB | heapAllocated 109MB
[task 2020-01-21T11:33:59.649Z] 11:33:59 INFO - TEST-OK | devtools/client/webreplay/mochitest/browser_dbg_rr_breakpoints-01.js | took 180490ms

Jason is this something you can take a look at?

Aryx pointed out there already is a discussion about this here: https://bugzilla.mozilla.org/show_bug.cgi?id=1583863#c13

Removing the ni for now.

Updated here: https://bugzilla.mozilla.org/show_bug.cgi?id=1583863#c16

Hi Henri I'm ni you here as I saw you wrote on bug 1583863.

This has reached the disabled recommended queue, however there are multiple tests failing.

There are 104 total failures in the last 7 days on macosx1014-64-shippable opt. Most frequent test failures start with test devtools/client/webreplay/mochitest/browser_dbg_rr_breakpoints-01.js

Recent failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=286777384&repo=autoland&lineNumber=970

[task 2020-01-28T23:18:34.329Z] 23:18:34 INFO - TEST-START | devtools/client/webreplay/mochitest/browser_dbg_rr_breakpoints-01.js
[task 2020-01-28T23:18:34.564Z] 23:18:34 INFO - GECKO(1856) | MIDDLEMAN 1861 /var/folders/zr/mh3s3lrd12341cpwh_rrx1jw000017/T/TempRecording.1856.1
[task 2020-01-28T23:18:34.598Z] 23:18:34 INFO - GECKO(1856) | RECORDING 1862 /var/folders/zr/mh3s3lrd12341cpwh_rrx1jw000017/T/TempRecording.1856.1
[task 2020-01-28T23:18:34.919Z] 23:18:34 INFO - GECKO(1856) | JavaScript error: chrome://global/content/browser-child.js, line 26: ReferenceError: Services is not defined
[task 2020-01-28T23:18:35.324Z] 23:18:35 INFO - GECKO(1856) | [ReplayControl 0.41] ManifestFinished #0 {"point":{"checkpoint":1,"progress":0}}
[task 2020-01-28T23:18:35.324Z] 23:18:35 INFO - GECKO(1856) | [ReplayControl 0.41] SendManifest #0 {"kind":"flushRecording"}
[task 2020-01-28T23:18:35.324Z] 23:18:35 INFO - GECKO(1856) | [ReplayControl 0.41] WaitUntilPaused #0
[task 2020-01-28T23:18:35.324Z] 23:18:35 INFO - GECKO(1856) | [ReplayControl 0.42] ManifestFinished #0 undefined
[task 2020-01-28T23:18:35.324Z] 23:18:35 INFO - GECKO(1856) | [ReplayControl 0.42] WaitUntilPaused Done
[task 2020-01-28T23:18:35.428Z] 23:18:35 INFO - GECKO(1856) | IPDL protocol error: Handler returned error code!
[task 2020-01-28T23:18:35.428Z] 23:18:35 INFO - GECKO(1856) | ###!!! [Parent][DispatchAsyncMessage] Error: PContent::Msg_CommitBrowsingContextTransaction Processing error: message was deserialized, but the handler returned false (indicating failure)
[task 2020-01-28T23:18:35.428Z] 23:18:35 INFO - GECKO(1856) | ###!!! [Parent][RunMessage] Error: Channel error: cannot send/recv
[task 2020-01-28T23:18:35.428Z] 23:18:35 INFO - GECKO(1856) | ###!!! [Parent][RunMessage] Error: Channel error: cannot send/recv
[task 2020-01-28T23:18:35.430Z] 23:18:35 INFO - GECKO(1856) | ###!!! [Parent][RunMessage] Error: Channel error: cannot send/recv
[task 2020-01-28T23:18:35.430Z] 23:18:35 INFO - GECKO(1856) | ###!!! [Parent][RunMessage] Error: Channel error: cannot send/recv
[task 2020-01-28T23:18:35.430Z] 23:18:35 INFO - GECKO(1856) | ###!!! [Parent][RunMessage] Error: Channel error: cannot send/recv
[task 2020-01-28T23:19:01.150Z] 23:19:01 INFO - GECKO(1856) | 2020-01-28 23:19:01.132 firefox[1856:9619] 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)
[task 2020-01-28T23:21:34.914Z] 23:21:34 INFO - TEST-INFO | started process screencapture
[task 2020-01-28T23:21:35.042Z] 23:21:35 INFO - TEST-INFO | screencapture: exit 0
[task 2020-01-28T23:21:35.042Z] 23:21:35 INFO - Buffered messages logged at 23:18:34
[task 2020-01-28T23:21:35.042Z] 23:21:35 INFO - Entering test bound
[task 2020-01-28T23:21:35.044Z] 23:21:35 INFO - Waiting for event: 'RecordingInitialized' on [object ParentProcessMessageManager].
[task 2020-01-28T23:21:35.044Z] 23:21:35 INFO - Console message: [JavaScript Error: "ReferenceError: Services is not defined" {file: "chrome://global/content/browser-child.js" line: 26}]
[task 2020-01-28T23:21:35.044Z] 23:21:35 INFO - Buffered messages logged at 23:18:35
[task 2020-01-28T23:21:35.050Z] 23:21:35 INFO - Console message: [JavaScript Error: "remote browser crashed while on about:blank
[task 2020-01-28T23:21:35.050Z] 23:21:35 INFO - " {file: "chrome://mochikit/content/mochitest-e10s-utils.js" line: 10}]
[task 2020-01-28T23:21:35.050Z] 23:21:35 INFO - e10s_init/<@chrome://mochikit/content/mochitest-e10s-utils.js:10:10
[task 2020-01-28T23:21:35.050Z] 23:21:35 INFO - EventListener.handleEvente10s_init@chrome://mochikit/content/mochitest-e10s-utils.js:6:10
[task 2020-01-28T23:21:35.050Z] 23:21:35 INFO - testInit@chrome://mochikit/content/browser-test.js:130:5
[task 2020-01-28T23:21:35.050Z] 23:21:35 INFO - setTimeout handler@chrome://mochikit/content/browser-test.js:40:11
[task 2020-01-28T23:21:35.050Z] 23:21:35 INFO - loadChromeScripts@jar:file:///var/folders/zr/mh3s3lrd12341cpwh_rrx1jw000017/T/tmpjumZ4m.mozrunner/extensions/mochikit@mozilla.org.xpi!/api.js:21:25
[task 2020-01-28T23:21:35.050Z] 23:21:35 INFO - loadMochitest@jar:file:///var/folders/zr/mh3s3lrd12341cpwh_rrx1jw000017/T/tmpjumZ4m.mozrunner/extensions/mochikit@mozilla.org.xpi!/api.js:143:20
[task 2020-01-28T23:21:35.050Z] 23:21:35 INFO - @tests/mochitest/runtests.py:1794:5
[task 2020-01-28T23:21:35.050Z] 23:21:35 INFO - @tests/mochitest/runtests.py:1795:8
[task 2020-01-28T23:21:35.051Z] 23:21:35 INFO - evaluate.sandbox/promise<@chrome://marionette/content/evaluate.js:138:10
[task 2020-01-28T23:21:35.051Z] 23:21:35 INFO - evaluate.sandbox@chrome://marionette/content/evaluate.js:114:17
[task 2020-01-28T23:21:35.051Z] 23:21:35 INFO - GeckoDriver.prototype.execute_@chrome://marionette/content/driver.js:1099:28
[task 2020-01-28T23:21:35.051Z] 23:21:35 INFO - async*GeckoDriver.prototype.executeScript@chrome://marionette/content/driver.js:974:30
[task 2020-01-28T23:21:35.051Z] 23:21:35 INFO - despatch@chrome://marionette/content/server.js:305:40
[task 2020-01-28T23:21:35.051Z] 23:21:35 INFO - execute@chrome://marionette/content/server.js:275:16
[task 2020-01-28T23:21:35.051Z] 23:21:35 INFO - onPacket/<@chrome://marionette/content/server.js:248:20
[task 2020-01-28T23:21:35.051Z] 23:21:35 INFO - onPacket@chrome://marionette/content/server.js:249:9
[task 2020-01-28T23:21:35.051Z] 23:21:35 INFO - _onJSONObjectReady/<@chrome://marionette/content/transport.js:501:20
[task 2020-01-28T23:21:35.051Z] 23:21:35 INFO -
[task 2020-01-28T23:21:35.052Z] 23:21:35 INFO - Buffered messages logged at 23:19:19
[task 2020-01-28T23:21:35.052Z] 23:21:35 INFO - Longer timeout required, waiting longer... Remaining timeouts: 3
[task 2020-01-28T23:21:35.052Z] 23:21:35 INFO - Buffered messages logged at 23:20:04
[task 2020-01-28T23:21:35.052Z] 23:21:35 INFO - Longer timeout required, waiting longer... Remaining timeouts: 2
[task 2020-01-28T23:21:35.053Z] 23:21:35 INFO - Buffered messages logged at 23:20:49
[task 2020-01-28T23:21:35.053Z] 23:21:35 INFO - Longer timeout required, waiting longer... Remaining timeouts: 1
[task 2020-01-28T23:21:35.053Z] 23:21:35 INFO - Buffered messages finished
[task 2020-01-28T23:21:35.054Z] 23:21:35 INFO - TEST-UNEXPECTED-FAIL | devtools/client/webreplay/mochitest/browser_dbg_rr_breakpoints-01.js | Test timed out -
[task 2020-01-28T23:21:35.054Z] 23:21:35 INFO - Removing tab.
[task 2020-01-28T23:21:35.054Z] 23:21:35 INFO - Waiting for event: 'TabClose' on [object XULElement].
[task 2020-01-28T23:21:35.054Z] 23:21:35 INFO - Got event: 'TabClose' on [object XULElement].
[task 2020-01-28T23:21:35.055Z] 23:21:35 INFO - Tab removed and finished closing
[task 2020-01-28T23:21:35.055Z] 23:21:35 INFO - TEST-PASS | devtools/client/webreplay/mochitest/browser_dbg_rr_breakpoints-01.js | The main process DebuggerServer has no pending connection when the test ends -
[task 2020-01-28T23:21:35.055Z] 23:21:35 INFO - TEST-PASS | devtools/client/webreplay/mochitest/browser_dbg_rr_breakpoints-01.js | The main process DebuggerServer has no pending connection when the test ends -
[task 2020-01-28T23:21:35.055Z] 23:21:35 INFO - GECKO(1856) | MEMORY STAT vsizeMaxContiguous not supported in this build configuration.
[task 2020-01-28T23:21:35.055Z] 23:21:35 INFO - GECKO(1856) | MEMORY STAT | vsize 7581MB | residentFast 310MB | heapAllocated 105MB
[task 2020-01-28T23:21:35.055Z] 23:21:35 INFO - TEST-OK | devtools/client/webreplay/mochitest/browser_dbg_rr_breakpoints-01.js | took 180628ms

Can you please take a look?

It seems to me that bug 1609815 is relevant.

Waiting on bug 1609815 to get fixed, removing disable tag.

The failures here should now disappear cause Bug 1609815 it's fixed in Gecko 75.

As earlier comments said, these tests have been removed in Bug 1609815.