1526558 - Intermittent devtools/client/webreplay/mochitest/browser_dbg_rr_breakpoints-02.js | Uncaught exception - [object Object] | After evToolsUtils.assert threw an exception: Error: Assertion failure: Must pass Error objects to reportError

Status: RESOLVED FIXED

(Core Graveyard :: Web Replay, defect, P5)

Description

[Treeherder Bug Filer]

#[markdown(off)]
Filed by: nbeleuzu [at] mozilla.com

https://treeherder.mozilla.org/logviewer.html#?job_id=227294911&repo=mozilla-central

https://queue.taskcluster.net/v1/task/cTJP2Ni5TPq6BoRKlY3Bew/runs/0/artifacts/public/logs/live_backing.log

15:23:46 INFO - Got event: 'RecordingFinished' on [object ParentProcessMessageManager].
15:23:46 INFO - Buffered messages logged at 15:23:45
15:23:46 INFO - Console message: [JavaScript Warning: "Removed unsafe attribute. Element: svg. Attribute: xlink." {file: "resource://devtools/client/shared/vendor/react-dom.js" line: 5811}]
15:23:46 INFO - Console message: [JavaScript Warning: "Removed unsafe attribute. Element: svg. Attribute: xlink." {file: "resource://devtools/client/shared/vendor/react-dom.js" line: 5811}]
15:23:46 INFO - Console message: [JavaScript Warning: "Removed unsafe attribute. Element: svg. Attribute: xmlns." {file: "resource://devtools/client/shared/vendor/react-dom.js" line: 5811}]
15:23:46 INFO - Console message: [JavaScript Warning: "Removed unsafe attribute. Element: svg. Attribute: xlink." {file: "resource://devtools/client/shared/vendor/react-dom.js" line: 5811}]
15:23:46 INFO - Console message: [JavaScript Warning: "Removed unsafe attribute. Element: svg. Attribute: xmlns." {file: "resource://devtools/client/shared/vendor/react-dom.js" line: 5811}]
15:23:46 INFO - Console message: [JavaScript Warning: "Removed unsafe attribute. Element: svg. Attribute: version." {file: "resource://devtools/client/shared/vendor/react-dom.js" line: 5811}]
15:23:46 INFO - Buffered messages finished
15:23:46 INFO - TEST-UNEXPECTED-FAIL | devtools/client/webreplay/mochitest/browser_dbg_rr_breakpoints-02.js | Uncaught exception - [object Object]
15:23:46 INFO - Leaving test bound
15:23:46 INFO - Console message: [JavaScript Error: "error occurred while processing 'interrupt: Error: Assertion failure: Must pass Error objects to reportError
15:23:46 INFO - Stack: reallyAssert@resource://devtools/shared/DevToolsUtils.js:468:17
15:23:46 INFO - this.reportError@resource://devtools/server/actors/thread.js:2083:3
15:23:46 INFO - onInterrupt@resource://devtools/server/actors/thread.js:1318:7
15:23:46 INFO - onPacket@resource://devtools/server/main.js:1279:15
15:23:46 INFO - receiveMessage@resource://devtools/shared/transport/child-transport.js:66:5
15:23:46 INFO - MessageListener.receiveMessage*_addListener@resource://devtools/shared/transport/child-transport.js:40:5
15:23:46 INFO - ready@resource://devtools/shared/transport/child-transport.js:57:5
15:23:46 INFO - _onConnection@resource://devtools/server/main.js:868:5
15:23:46 INFO - connectToParent@resource://devtools/server/main.js:289:12
15:23:46 INFO - onConnect<@resource://devtools/server/startup/frame.js:59:20
15:23:46 INFO - exports.makeInfallible/<@resource://devtools/shared/ThreadSafeDevToolsUtils.js:109:14
15:23:46 INFO - MessageListener.receiveMessage*@resource://devtools/server/startup/frame.js:80:5
15:23:46 INFO - @resource://devtools/server/startup/frame.js:20:" {file: "resource://devtools/server/main.js" line: 1148}]
15:23:46 INFO - _unknownError@resource://devtools/server/main.js:1148:5
15:23:46 INFO - onPacket@resource://devtools/server/main.js:1282:29
15:23:46 INFO - receiveMessage@resource://devtools/shared/transport/child-transport.js:66:5
15:23:46 INFO - MessageListener.receiveMessage*_addListener@resource://devtools/shared/transport/child-transport.js:40:5
15:23:46 INFO - ready@resource://devtools/shared/transport/child-transport.js:57:5
15:23:46 INFO - _onConnection@resource://devtools/server/main.js:868:5
15:23:46 INFO - connectToParent@resource://devtools/server/main.js:289:12
15:23:46 INFO - onConnect<@resource://devtools/server/startup/frame.js:59:20
15:23:46 INFO - exports.makeInfallible/<@resource://devtools/shared/ThreadSafeDevToolsUtils.js:109:14
15:23:46 INFO - MessageListener.receiveMessage*@resource://devtools/server/startup/frame.js:80:5
15:23:46 INFO - @resource://devtools/server/startup/frame.js:20:4
15:23:46 INFO -
15:23:46 INFO - Removing tab.
15:23:46 INFO - Waiting for event: 'TabClose' on [object XULElement].
15:23:46 INFO - Got event: 'TabClose' on [object XULElement].
15:23:46 INFO - Tab removed and finished closing
15:23:46 INFO - GECKO(804) | MEMORY STAT | vsize 4491MB | residentFast 424MB | heapAllocated 142MB
15:23:46 INFO - TEST-OK | devtools/client/webreplay/mochitest/browser_dbg_rr_breakpoints-02.js | took 6395ms

Comment 1

[Narcis Beleuzu [:NarcisB]]

1st part of the log:

15:23:40 INFO - TEST-START | devtools/client/webreplay/mochitest/browser_dbg_rr_breakpoints-02.js
15:23:40 INFO - GECKO(804) | MIDDLEMAN 818 /var/folders/_t/yt59_r453lq8r521j3r5kkvh00000x/T/TempRecording.804.2
15:23:40 INFO - GECKO(804) | RECORDING 819 /var/folders/_t/yt59_r453lq8r521j3r5kkvh00000x/T/TempRecording.804.2
15:23:42 INFO - GECKO(804) | REPLAYING 821 /var/folders/_t/yt59_r453lq8r521j3r5kkvh00000x/T/TempRecording.804.2
15:23:42 INFO - GECKO(804) | REPLAYING 822 /var/folders/_t/yt59_r453lq8r521j3r5kkvh00000x/T/TempRecording.804.2
15:23:44 INFO - GECKO(804) | Spew[822]: WARNING: Repeated accesses to the same dirty address 0x118b042a0
15:23:45 INFO - GECKO(804) | [ACTION] ADD_SOURCES - {"type":"ADD_SOURCES","sources":[{"id":"sourceURL-http://example.com/browser/devtools/client/webreplay/mochitest/examples/doc_rr_basic.html","url":"http://example.com/browser/devtools/client/webreplay/mochitest/examples/doc_rr_basic.html","relativeUrl":"http://example.com/browser/devtools/client/webreplay/mochitest/examples/doc_rr_basic.html","isPrettyPrinted":false,"sourceMapURL":null,"introductionUrl":null,"isBlackBoxed":false,"loadedState":"unloaded","isWasm":false}],"sourceActors":[{"actor":"server1.conn1.child1/source24","source":"sourceURL-http://example.com/browser/devtools/client/webreplay/mochitest/examples/doc_rr_basic.html","thread":"server1.conn1.child1/context22"}]}
15:23:45 INFO - GECKO(804) | [ACTION] SET_SELECTED_LOCATION - {"type":"SET_SELECTED_LOCATION","source":{"id":"sourceURL-http://example.com/browser/devtools/client/webreplay/mochitest/examples/doc_rr_basic.html","url":"http://example.com/browser/devtools/client/webreplay/mochitest/examples/doc_rr_basic.html","sourceMapURL":null,"isBlackBoxed":false,"isPrettyPrinted":false,"isWasm":false,"isExtension":false,"contentType":"","loadedState":"unloaded","relativeUrl":"http://example.com/browser/devtools/client/webreplay/mochitest/examples/doc_rr_basic.html","introductionUrl":null},"location":{"sourceId":"sourceURL-http://example.com/browser/devtools/client/webreplay/mochitest/examples/doc_rr_basic.html","line":21,"column":2}}
15:23:45 INFO - GECKO(804) | [ACTION] LOAD_SOURCE_TEXT [start] - {"type":"LOAD_SOURCE_TEXT","sourceId":"sourceURL-http://example.com/browser/devtools/client/webreplay/mochitest/examples/doc_rr_basic.html","seqId":"1","status":"start"}
15:23:45 INFO - GECKO(804) | [ACTION] SET_WORKERS - {"type":"SET_WORKERS","workers":[],"mainThread":"server1.conn1.child1/context22"}
15:23:45 INFO - GECKO(804) | [ACTION] CONNECT - {"type":"CONNECT","mainThread":{"url":"about:blank","actor":"server1.conn1.child1/context22","type":-1},"canRewind":true}
15:23:45 INFO - GECKO(804) | [ACTION] PAUSE_ON_EXCEPTIONS [start] - {"type":"PAUSE_ON_EXCEPTIONS","thread":"server1.conn1.child1/context22","shouldPauseOnExceptions":false,"shouldPauseOnCaughtExceptions":true,"seqId":"2","status":"start"}
15:23:45 INFO - GECKO(804) | [ACTION] LOAD_SOURCE_TEXT [done] - {"type":"LOAD_SOURCE_TEXT","sourceId":"sourceURL-http://example.com/browser/devtools/client/webreplay/mochitest/examples/doc_rr_basic.html","seqId":"1","status":"done","value":{"id":"sourceURL-http://example.com/browser/devtools/client/webreplay/mochitest/examples/doc_rr_basic.html","text":"","contentType":"text/html"}}
15:23:45 INFO - GECKO(804) | [ACTION] PAUSE_ON_EXCEPTIONS [done] - {"type":"PAUSE_ON_EXCEPTIONS","thread":"server1.conn1.child1/context22","shouldPauseOnExceptions":false,"shouldPauseOnCaughtExceptions":true,"seqId":"2","status":"done","value":{"from":"server1.conn1.child1/context22","type":"paused","actor":"server1.conn1.child1/pause25","executionPoint":{"checkpoint":11,"progress":47},"recordingEndpoint":{"checkpoint":11,"progress":47},"poppedFrames":[],"why":{"type":"interrupted","onNext":true}}}
15:23:45 INFO - GECKO(804) | [ACTION] SET_EXPANDED_STATE - {"type":"SET_EXPANDED_STATE","thread":"server1.conn1.child1/context22","expanded":{}}
15:23:45 INFO - GECKO(804) | [ACTION] SET_ORIENTATION - {"type":"SET_ORIENTATION","orientation":"horizontal"}
15:23:45 INFO - GECKO(804) | [ACTION] SET_SYMBOLS [start] - {}
15:23:45 INFO - GECKO(804) | [ACTION] OUT_OF_SCOPE_LOCATIONS - {}
15:23:45 INFO - GECKO(804) | [ACTION] IN_SCOPE_LINES - {}
15:23:45 INFO - GECKO(804) | [ACTION] SET_SYMBOLS [done] - {}
15:23:45 INFO - GECKO(804) | [ACTION] PAUSED - {"type":"PAUSED","thread":"server1.conn1.child1/context22","why":{"type":"interrupted","onNext":true},"frames":[],"loadedObjects":[],"pauseInfo":{"why":{"type":"interrupted","onNext":true}},"scopes":[]}
15:23:45 INFO - GECKO(804) | [ACTION] MAP_FRAMES - {}
15:23:45 INFO - GECKO(804) | [ACTION] EVALUATE_EXPRESSIONS - {"type":"EVALUATE_EXPRESSIONS","inputs":[],"results":[]}
15:23:45 INFO - GECKO(804) | [ACTION] RESUME - {"type":"RESUME","thread":"server1.conn1.child1/context22","wasStepping":false}
15:23:45 INFO - GECKO(804) | [ACTION] EVALUATE_EXPRESSIONS - {"type":"EVALUATE_EXPRESSIONS","inputs":[],"results":[]}
15:23:45 INFO - GECKO(804) | ReplayControl Server Error: Assertion Failed! Stack: ThrowError@resource://devtools/server/actors/replay/control.js:1114:17
15:23:45 INFO - GECKO(804) | assert@resource://devtools/server/actors/replay/control.js:1108:5
15:23:45 INFO - GECKO(804) | waitUntilPaused@resource://devtools/server/actors/replay/control.js:128:5
15:23:45 INFO - GECKO(804) | waitUntilPaused@resource://devtools/server/actors/replay/control.js:1004:7
15:23:45 INFO - GECKO(804) | _ensurePaused@resource://devtools/server/actors/replay/debugger.js:225:7
15:23:45 INFO - GECKO(804) | replayPause@resource://devtools/server/actors/replay/debugger.js:217:5
15:23:45 INFO - GECKO(804) | onInterrupt@resource://devtools/server/actors/thread.js:1292:9
15:23:45 INFO - GECKO(804) | onPacket@resource://devtools/server/main.js:1279:15
15:23:45 INFO - GECKO(804) | receiveMessage@resource://devtools/shared/transport/child-transport.js:66:5
15:23:45 INFO - GECKO(804) | MessageListener.receiveMessage*_addListener@resource://devtools/shared/transport/child-transport.js:40:5
15:23:45 INFO - GECKO(804) | ready@resource://devtools/shared/transport/child-transport.js:57:5
15:23:45 INFO - GECKO(804) | _onConnection@resource://devtools/server/main.js:868:5
15:23:45 INFO - GECKO(804) | connectToParent@resource://devtools/server/main.js:289:12
15:23:45 INFO - GECKO(804) | onConnect<@resource://devtools/server/startup/frame.js:59:20
15:23:45 INFO - GECKO(804) | exports.makeInfallible/<@resource://devtools/shared/ThreadSafeDevToolsUtils.js:109:14
15:23:45 INFO - GECKO(804) | MessageListener.receiveMessage*@resource://devtools/server/startup/frame.js:80:5

Comment 2

[Brian Hackett [Laid off!]]

Attachment: patch

This failure happens when we are waiting for a child process to pause, but once it does so it resumes immediately before the calling code has a chance to operate on it. The attached patch avoids this problem (and similar ones we have been seeing when using retroactive console logging) by resuming execution in the child asynchronously, and tidies up previous workarounds for this problem in the process.

Comment 3

[Brian Hackett [Laid off!]]

Try push with fix:

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

Comment 4

[Andreea Pavel [:apavel]]

Brian there are other similar failures bug 1526124, bug 1526101, bug 1522988

Does your patch fix all of them or just this particular test?

Comment 5

[Brian Hackett [Laid off!]]

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

Brian there are other similar failures bug 1526124, bug 1526101, bug 1522988

Does your patch fix all of them or just this particular test?

Bug 1526124 and bug 1526101 should both be fixed by this patch, this problem can affect all the web replay tests. Bug 1522988 is a different issue, it looks like a replaying process crashed. Failures like that are pretty rare from what I've seen; the fix here should take care of most of the intermittent failures that have been showing up, e.g. all the intermittent failures in the diagnostic try push below are associated with this bug.

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

Comment 8

[Andreea Pavel [:apavel]]

Thanks for clarifying Brian. Closing the other two bugs as duplicates of this one. Will look more into bug 1522988.

Comment 9

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/mozilla-inbound/rev/b3bfc680b6c6
Poke background children asynchronously, r=jlast.

Comment 10

[Noemi Erli[:noemi_erli]]

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

Comment 11

[Intermittent Failures Robot]

1 failures in 2658 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-central: 1

Platform breakdown:

• macosx64-nightly: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1526558&startday=2019-02-04&endday=2019-02-10&tree=all