Closed Bug 1621076 Opened 5 years ago Closed 5 years ago

Intermittent devtools/client/performance-new/test/browser/browser_devtools-record-capture.js | The component starts out in an unknown state. - Got available-to-record, expected not-yet-known

Categories

(DevTools :: Performance Tools (Profiler/Timeline), defect, P5)

Product:
DevTools
Component:
Performance Tools (Profiler/Timeline)
Type:
defect

Tracking

(firefox76 fixed)

Status:
RESOLVED FIXED
Milestone:
Firefox 76
Tracking Flags:
Tracking Status
firefox76 --- fixed

People

(Reporter: intermittent-bug-filer, Assigned: gregtatum)

References

(Regression)

Details

(Keywords: intermittent-failure, regression)

Attachments

(1 file)

Bug 1621076 - Fix intermittents caused by recording state race; r?canaltinova
47 bytes, text/x-phabricator-request
Details | Review

Filed by: nerli [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=292281364&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/QhjVojt6RwanGSlCwt8nqg/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://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/QhjVojt6RwanGSlCwt8nqg/runs/0/artifacts/public/logs/live_backing.log&only_show_unexpected=1

[task 2020-03-09T15:46:07.387Z] 15:46:07 INFO - TEST-START | devtools/client/performance-new/test/browser/browser_devtools-record-capture.js
[task 2020-03-09T15:46:07.390Z] 15:46:07 INFO - GECKO(2152) | [Parent 4404, Main Thread] WARNING: NS_ENSURE_TRUE(GetWrapper()) failed: file /builds/worker/checkouts/gecko/dom/ipc/JSWindowActor.cpp, line 66
[task 2020-03-09T15:46:07.405Z] 15:46:07 INFO - GECKO(2152) | console.error: "The preference "devtools.performance.recording.ui-base-url" was set to a URL that is not allowed. No WebChannel messages will be sent between the browser and that URL. Falling back to https://profiler.firefox.com. Only localhost and deploy previews URLs are allowed." "http://example.com/browser/devtools/client/performance-new/test/browser/fake-frontend.html"
[task 2020-03-09T15:46:07.405Z] 15:46:07 INFO - GECKO(2152) | console.error: "The preference "devtools.performance.recording.ui-base-url" was set to a URL that is not allowed. No WebChannel messages will be sent between the browser and that URL. Falling back to https://profiler.firefox.com. Only localhost and deploy previews URLs are allowed." "http://example.com/browser/devtools/client/performance-new/test/browser/fake-frontend.html"
[task 2020-03-09T15:46:07.405Z] 15:46:07 INFO - GECKO(2152) | [Child 5784: Main Thread]: I/DocShellAndDOMWindowLeak ++DOCSHELL 00AAE000 == 1 [pid = 5784] [id = {b75b7c5d-d288-47ac-a4c6-791282b80ea0}]
[task 2020-03-09T15:46:07.405Z] 15:46:07 INFO - GECKO(2152) | [Child 5784: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 6 (065BEDF0) [pid = 5784] [serial = 6] [outer = 00000000]
[task 2020-03-09T15:46:07.405Z] 15:46:07 INFO - GECKO(2152) | [Child 5784: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 7 (065C7000) [pid = 5784] [serial = 7] [outer = 065BEDF0]
[task 2020-03-09T15:46:07.428Z] 15:46:07 INFO - GECKO(2152) | [Child 5784: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 8 (065D0000) [pid = 5784] [serial = 8] [outer = 065BEDF0]
[task 2020-03-09T15:46:07.708Z] 15:46:07 INFO - GECKO(2152) | [Parent 4404: Main Thread]: I/DocShellAndDOMWindowLeak ++DOCSHELL 18C7E800 == 10 [pid = 4404] [id = {53695091-55ee-4382-8b28-c653cd16318c}]
[task 2020-03-09T15:46:07.708Z] 15:46:07 INFO - GECKO(2152) | [Parent 4404: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 22 (0C1F59B0) [pid = 4404] [serial = 24] [outer = 00000000]
[task 2020-03-09T15:46:07.727Z] 15:46:07 INFO - GECKO(2152) | [Parent 4404: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 23 (19A7D000) [pid = 4404] [serial = 25] [outer = 0C1F59B0]
[task 2020-03-09T15:46:07.826Z] 15:46:07 INFO - GECKO(2152) | [Parent 4404: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 24 (19A7BC00) [pid = 4404] [serial = 26] [outer = 0C1F59B0]
[task 2020-03-09T15:46:07.901Z] 15:46:07 INFO - GECKO(2152) | [Parent 4404, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80004005: file /builds/worker/checkouts/gecko/dom/base/nsContentUtils.cpp, line 3786
[task 2020-03-09T15:46:08.056Z] 15:46:08 INFO - GECKO(2152) | [Parent 4404: Main Thread]: I/DocShellAndDOMWindowLeak ++DOCSHELL 18C7D000 == 11 [pid = 4404] [id = {a1cdd9b9-163e-4246-b0cf-23340c689c71}]
[task 2020-03-09T15:46:08.056Z] 15:46:08 INFO - GECKO(2152) | [Parent 4404: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 25 (00806DE0) [pid = 4404] [serial = 27] [outer = 00000000]
[task 2020-03-09T15:46:08.056Z] 15:46:08 INFO - GECKO(2152) | [Parent 4404: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 26 (1D790800) [pid = 4404] [serial = 28] [outer = 00806DE0]
[task 2020-03-09T15:46:08.383Z] 15:46:08 INFO - GECKO(2152) | [Child 5784: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 7 (00AB3000) [pid = 5784] [serial = 2] [outer = 00000000] [url = about:blank]
[task 2020-03-09T15:46:08.498Z] 15:46:08 INFO - GECKO(2152) | [Child 5768: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 14 (071D4800) [pid = 5768] [serial = 4] [outer = 00000000] [url = about:blank]
[task 2020-03-09T15:46:08.498Z] 15:46:08 INFO - GECKO(2152) | [Child 5768: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 13 (071DAC00) [pid = 5768] [serial = 10] [outer = 00000000] [url = about:blank]
[task 2020-03-09T15:46:08.499Z] 15:46:08 INFO - GECKO(2152) | [Child 5768: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 12 (071D6800) [pid = 5768] [serial = 6] [outer = 00000000] [url = about:blank]
[task 2020-03-09T15:46:08.499Z] 15:46:08 INFO - GECKO(2152) | [Child 5768: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 11 (014C9400) [pid = 5768] [serial = 2] [outer = 00000000] [url = about:blank]
[task 2020-03-09T15:46:08.499Z] 15:46:08 INFO - GECKO(2152) | [Child 5768: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 10 (071D8800) [pid = 5768] [serial = 8] [outer = 00000000] [url = about:blank]
[task 2020-03-09T15:46:08.534Z] 15:46:08 INFO - GECKO(2152) | [Child 5784: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 6 (065BECE0) [pid = 5784] [serial = 4] [outer = 00000000] [url = about:blank]
[task 2020-03-09T15:46:08.534Z] 15:46:08 INFO - GECKO(2152) | [Child 5784: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 5 (00A0CAB0) [pid = 5784] [serial = 1] [outer = 00000000] [url = chrome://gfxsanity/content/sanitytest.html]
[task 2020-03-09T15:46:08.553Z] 15:46:08 INFO - TEST-INFO | started process screenshot
[task 2020-03-09T15:46:08.620Z] 15:46:08 INFO - TEST-INFO | screenshot: exit 0
[task 2020-03-09T15:46:08.621Z] 15:46:08 INFO - Buffered messages logged at 15:46:07
[task 2020-03-09T15:46:08.621Z] 15:46:08 INFO - Entering test bound test
[task 2020-03-09T15:46:08.622Z] 15:46:08 INFO - Test that DevTools can capture profiles. This function also unit tests the internal RecordingState of the client.
[task 2020-03-09T15:46:08.622Z] 15:46:08 INFO - Setting the profiler URL to the fake frontend. Note that this doesn't currently support the WebChannels, so expect a few error messages about the WebChannel URLs not being correct.
[task 2020-03-09T15:46:08.622Z] 15:46:08 INFO - Create a new about:blank tab.
[task 2020-03-09T15:46:08.623Z] 15:46:08 INFO - Begin to open the DevTools and the performance-new panel.
[task 2020-03-09T15:46:08.623Z] 15:46:08 INFO - Buffered messages logged at 15:46:08
[task 2020-03-09T15:46:08.623Z] 15:46:08 INFO - Console message: [JavaScript Error: "Content Security Policy: The page’s settings blocked the loading of a resource at inline (“default-src”)." {file: "chrome://global/content/elements/panel.js" line: 62}]
[task 2020-03-09T15:46:08.624Z] 15:46:08 INFO - The performance-new panel is now open and ready to use.
[task 2020-03-09T15:46:08.624Z] 15:46:08 INFO - Buffered messages finished
[task 2020-03-09T15:46:08.625Z] 15:46:08 INFO - TEST-UNEXPECTED-FAIL | devtools/client/performance-new/test/browser/browser_devtools-record-capture.js | The component starts out in an unknown state. - Got available-to-record, expected not-yet-known
[task 2020-03-09T15:46:08.625Z] 15:46:08 INFO - Stack trace:
[task 2020-03-09T15:46:08.625Z] 15:46:08 INFO - chrome://mochikit/content/browser-test.js:test_is:1320
[task 2020-03-09T15:46:08.625Z] 15:46:08 INFO - chrome://mochitests/content/browser/devtools/client/performance-new/test/browser/browser_devtools-record-capture.js:test/<:20
[task 2020-03-09T15:46:08.625Z] 15:46:08 INFO - chrome://mochitests/content/browser/devtools/client/performance-new/test/browser/head.js:withDevToolsPanel:372
[task 2020-03-09T15:46:08.626Z] 15:46:08 INFO - chrome://mochitests/content/browser/devtools/client/performance-new/test/browser/browser_devtools-record-capture.js:test:17
[task 2020-03-09T15:46:08.626Z] 15:46:08 INFO - chrome://mochikit/content/browser-test.js:Tester_execTest/<:1062
[task 2020-03-09T15:46:08.626Z] 15:46:08 INFO - chrome://mochikit/content/browser-test.js:Tester_execTest:1097
[task 2020-03-09T15:46:08.626Z] 15:46:08 INFO - chrome://mochikit/content/browser-test.js:nextTest/<:919
[task 2020-03-09T15:46:08.626Z] 15:46:08 INFO - chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:SimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<:918
[task 2020-03-09T15:46:08.627Z] 15:46:08 INFO - Trying to find the element with the text "Start recording".
[task 2020-03-09T15:46:08.627Z] 15:46:08 INFO - Waiting until the button is not disabled.
[task 2020-03-09T15:46:08.627Z] 15:46:08 INFO - TEST-PASS | devtools/client/performance-new/test/browser/browser_devtools-record-capture.js | After talking to the actor, we're ready to record. -
[task 2020-03-09T15:46:08.627Z] 15:46:08 INFO - Click the button to start recording
[task 2020-03-09T15:46:08.627Z] 15:46:08 INFO - TEST-PASS | devtools/client/performance-new/test/browser/browser_devtools-record-capture.js | Clicking the start recording button sends in a request to start recording. -
[task 2020-03-09T15:46:08.627Z] 15:46:08 INFO - Trying to find the element with the text "Capture recording".
[task 2020-03-09T15:46:08.628Z] 15:46:08 INFO - Waiting until the button is not disabled.
[task 2020-03-09T15:46:08.628Z] 15:46:08 INFO - GECKO(2152) | [Child 5768: Main Thread]: I/DocShellAndDOMWindowLeak --DOCSHELL 014CA000 == 4 [pid = 5768] [id = {1167a9da-7b0e-4bec-9fa0-3cb02c5a3575}] [url = moz-extension://95a8e183-b40b-447b-92b2-c3adb6ac87e0/_generated_background_page.html]
[task 2020-03-09T15:46:08.628Z] 15:46:08 INFO - GECKO(2152) | [Child 5768: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 9 (0140B350) [pid = 5768] [serial = 3] [outer = 00000000] [url = moz-extension://95a8e183-b40b-447b-92b2-c3adb6ac87e0/_generated_background_page.html]
[task 2020-03-09T15:46:08.783Z] 15:46:08 INFO - TEST-PASS | devtools/client/performance-new/test/browser/browser_devtools-record-capture.js | Once the Capture recording button is available, the actor has started its recording -
[task 2020-03-09T15:46:08.784Z] 15:46:08 INFO - Click the button to capture the recording.
[task 2020-03-09T15:46:08.784Z] 15:46:08 INFO - TEST-PASS | devtools/client/performance-new/test/browser/browser_devtools-record-capture.js | We have requested to stop the profiler. -
[task 2020-03-09T15:46:08.784Z] 15:46:08 INFO - Trying to find the element with the text "Start recording".
[task 2020-03-09T15:46:09.114Z] 15:46:09 INFO - Waiting until the button is not disabled.
[task 2020-03-09T15:46:09.114Z] 15:46:09 INFO - TEST-PASS | devtools/client/performance-new/test/browser/browser_devtools-record-capture.js | The profiler is available to record again. -
[task 2020-03-09T15:46:09.115Z] 15:46:09 INFO - If the DevTools successfully injects a profile into the page, then the fake frontend will rename the title of the page.
[task 2020-03-09T15:46:09.115Z] 15:46:09 INFO - Attempting to see if the selected tab can receive a profile.
[task 2020-03-09T15:46:09.115Z] 15:46:09 INFO - > Waiting for the fake frontend tab to be loaded.
[task 2020-03-09T15:46:09.142Z] 15:46:09 INFO - GECKO(2152) | [Child 5812: Main Thread]: I/DocShellAndDOMWindowLeak ++DOCSHELL 008AFC00 == 1 [pid = 5812] [id = {d03cea06-f16e-434a-9681-cf8767d3c7ca}]
[task 2020-03-09T15:46:09.142Z] 15:46:09 INFO - GECKO(2152) | [Child 5812: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 4 (09D4E240) [pid = 5812] [serial = 4] [outer = 00000000]
[task 2020-03-09T15:46:09.142Z] 15:46:09 INFO - GECKO(2152) | [Child 5812: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 5 (008B5C00) [pid = 5812] [serial = 5] [outer = 09D4E240]
[task 2020-03-09T15:46:09.369Z] 15:46:09 INFO - GECKO(2152) | [Child 5812: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 6 (069DA000) [pid = 5812] [serial = 6] [outer = 09D4E240]
[task 2020-03-09T15:46:09.436Z] 15:46:09 INFO - > Waiting for the profile to be received.
[task 2020-03-09T15:46:09.476Z] 15:46:09 INFO - TEST-PASS | devtools/client/performance-new/test/browser/browser_devtools-record-capture.js | The profile was successfully injected to the page -
[task 2020-03-09T15:46:09.503Z] 15:46:09 INFO - About to remove the about:blank tab
[task 2020-03-09T15:46:09.542Z] 15:46:09 INFO - GECKO(2152) | [Child 3552: Main Thread]: I/DocShellAndDOMWindowLeak --DOCSHELL 00DB5400 == 0 [pid = 3552] [id = {e2cd9fdd-3879-40f5-b5a6-6b61bf8e1af8}] [url = http://example.com/browser/devtools/client/performance-new/test/browser/fake-frontend.html]
[task 2020-03-09T15:46:10.441Z] 15:46:10 INFO - GECKO(2152) | [Parent 4404: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 25 (248AD000) [pid = 4404] [serial = 20] [outer = 00000000] [url = about:blank]
[task 2020-03-09T15:46:10.508Z] 15:46:10 INFO - GECKO(2152) | [Parent 4404, Main Thread] WARNING: '!inner', file /builds/worker/checkouts/gecko/dom/ipc/JSWindowActorService.cpp, line 182
[task 2020-03-09T15:46:10.508Z] 15:46:10 INFO - GECKO(2152) | [Parent 4404, Main Thread] WARNING: '!inner', file /builds/worker/checkouts/gecko/dom/ipc/JSWindowActorService.cpp, line 182
[task 2020-03-09T15:46:10.508Z] 15:46:10 INFO - The about:blank tab is now removed.
[task 2020-03-09T15:46:11.009Z] 15:46:11 INFO - Leaving test bound test
[task 2020-03-09T15:46:11.036Z] 15:46:11 INFO - GECKO(2152) | MEMORY STAT | vsize 845MB | vsizeMaxContiguous 559MB | residentFast 298MB | heapAllocated 133MB

Regressed by: 1620323
Has Regression Range: --- → yes
Keywords: regression
Summary: Intermittent TV devtools/client/performance-new/test/browser/browser_devtools-record-capture.js | The component starts out in an unknown state. - Got available-to-record, expected not-yet-known → Intermittent devtools/client/performance-new/test/browser/browser_devtools-record-capture.js | The component starts out in an unknown state. - Got available-to-record, expected not-yet-known

I originally wrote the tests to check for the "not-yet-known" recording state. This
check is a race that did not fail locally, but does when run on the try servers.
This patch makes the tests a bit more permissive. It still includes the check for
"not-yet-known", but also allows for the recording state to already be known
at the beginning of the test.

Assignee: nobody → gtatum
Status: NEW → ASSIGNED
Pushed by gtatum@mozilla.com: https://hg.mozilla.org/integration/autoland/rev/51cd675065e6 Fix intermittents caused by recording state race; r=canaltinova

https://hg.mozilla.org/mozilla-central/rev/51cd675065e6

Status: ASSIGNED → RESOLVED
Closed: 5 years ago
status-firefox76: --- → fixed
Resolution: --- → FIXED
Target Milestone: --- → Firefox 76
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: