1583706 - Intermittent devtools/client/webconsole/test/browser/browser_webconsole_location_logpoint_debugger_link.js | Test timed out -

Reporter

Description

•

6 years ago

treeherder

Filed by: btara [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=268281522&repo=autoland
Full log: https://queue.taskcluster.net/v1/task/P6UnIrZmQ-GATkZ4jX9khQ/runs/1/artifacts/public/logs/live_backing.log

...
[task 2019-09-25T02:47:23.014Z] 02:47:23 [task 2019-09-25T02:47:23.014Z] 02:47:23 [task 2019-09-25T02:47:23.015Z] 02:47:23 [task 2019-09-25T02:47:23.016Z] 02:47:23 [task 2019-09-25T02:47:23.016Z] 02:47:23 [task 2019-09-25T02:47:23.017Z] 02:47:23 [task 2019-09-25T02:47:23.017Z] 02:47:23 [task 2019-09-25T02:47:23.017Z] 02:47:23 [task 2019-09-25T02:47:23.018Z] 02:47:23 [task 2019-09-25T02:47:23.018Z] 02:47:23 [task 2019-09-25T02:47:23.018Z] 02:47:23 [task 2019-09-25T02:47:23.018Z] 02:47:23 [task 2019-09-25T02:47:23.019Z] 02:47:23 [task 2019-09-25T02:47:23.019Z] 02:47:23 [task 2019-09-25T02:47:23.019Z] 02:47:23 [task 2019-09-25T02:47:23.020Z] 02:47:23 [task 2019-09-25T02:47:23.021Z] 02:47:23 [task 2019-09-25T02:47:23.022Z] 02:47:23 [task 2019-09-25T02:47:23.023Z] 02:47:23 [task 2019-09-25T02:47:23.024Z] 02:47:23 [task 2019-09-25T02:47:23.024Z] 02:47:23 [task 2019-09-25T02:47:23.025Z] 02:47:23 [task 2019-09-25T02:47:23.025Z] 02:47:23 [task 2019-09-25T02:47:23.025Z] 02:47:23 [task 2019-09-25T02:47:23.027Z] 02:47:23 [task 2019-09-25T02:47:23.027Z] 02:47:23 [task 2019-09-25T02:47:23.027Z] 02:47:23 [task 2019-09-25T02:47:23.028Z] 02:47:23 [task 2019-09-25T02:47:23.028Z] 02:47:23 [task 2019-09-25T02:47:23.029Z] 02:47:23 [task 2019-09-25T02:47:23.030Z] 02:47:23 [task 2019-09-25T02:47:23.031Z] 02:47:23 [task 2019-09-25T02:47:23.031Z] 02:47:23 [task 2019-09-25T02:47:23.031Z] 02:47:23 [task 2019-09-25T02:47:24.687Z] 02:47:24 [task 2019-09-25T02:47:24.689Z] 02:47:24 [task 2019-09-25T02:47:24.737Z] 02:47:24 [task 2019-09-25T02:47:24.773Z] 02:47:24 [task 2019-09-25T02:47:26.997Z] 02:47:26 [task 2019-09-25T02:47:26.999Z] 02:47:26 [task 2019-09-25T02:47:27.039Z] 02:47:27 [task 2019-09-25T02:47:27.075Z] 02:47:27 [task 2019-09-25T02:47:27.164Z] 02:47:27 [task 2019-09-25T02:47:27.164Z] 02:47:27 INFO - TEST-PASS | devtools/client/webconsole/test/browser/browser_webconsole_location_logpoint_debugger_link.js | expected source column -
INFO - Selecting the console again
INFO - Finding message for open-in-debugger test; text is "a is 1"
INFO - TEST-PASS | devtools/client/webconsole/test/browser/browser_webconsole_location_logpoint_debugger_link.js | The message does have a location link -
INFO - checking click on node location
INFO - Waiting for event: 'source-in-debugger-opened' on [object Object].
INFO - Buffered messages logged at 02:46:04
INFO - Got event: 'source-in-debugger-opened' on [object Object].
INFO - TEST-PASS | devtools/client/webconsole/test/browser/browser_webconsole_location_logpoint_debugger_link.js | source url found ("http://example.com/browser/devtools/client/webconsole/test/browser/test-location-debugger-link-logpoint-1.js") -
INFO - TEST-PASS | devtools/client/webconsole/test/browser/browser_webconsole_location_logpoint_debugger_link.js | expected source url -
INFO - TEST-PASS | devtools/client/webconsole/test/browser/browser_webconsole_location_logpoint_debugger_link.js | source line found ("8") -
INFO - TEST-PASS | devtools/client/webconsole/test/browser/browser_webconsole_location_logpoint_debugger_link.js | expected source line -
INFO - TEST-PASS | devtools/client/webconsole/test/browser/browser_webconsole_location_logpoint_debugger_link.js | source column found ("12") -
INFO - TEST-PASS | devtools/client/webconsole/test/browser/browser_webconsole_location_logpoint_debugger_link.js | expected source column -
INFO - Leaving test bound
INFO - Entering test bound
INFO - Adding a new tab with URL: http://example.com/browser/devtools/client/webconsole/test/browser/test-location-debugger-link-logpoint.html
INFO - Tab added and finished loading
INFO - Opening the toolbox
INFO - Buffered messages logged at 02:46:07
INFO - Toolbox opened and focused
INFO - Open the Debugger panel
INFO - Buffered messages logged at 02:46:09
INFO - Add a logpoint to the first file
INFO - Buffered messages logged at 02:46:11
INFO - Waiting for state change: selected source
INFO - Finished waiting for state change: selected source
INFO - Buffered messages logged at 02:46:12
INFO - Add a logpoint to the second file
INFO - Buffered messages logged at 02:46:13
INFO - Waiting for state change: selected source
INFO - Finished waiting for state change: selected source
INFO - Buffered messages finished
INFO - TEST-UNEXPECTED-FAIL | devtools/client/webconsole/test/browser/browser_webconsole_location_logpoint_debugger_link.js | Test timed out -
INFO - Removing tab.
INFO - Waiting for event: 'TabClose' on [object XULElement].
INFO - Got event: 'TabClose' on [object XULElement].
INFO - Tab removed and finished closing
INFO - Removing tab.
INFO - Waiting for event: 'TabClose' on [object XULElement].
INFO - Got event: 'TabClose' on [object XULElement].
INFO - Tab removed and finished closing
INFO - GECKO(2476) | MEMORY STAT | vsize 20977386MB | residentFast 3765MB
INFO - TEST-OK | devtools/client/webconsole/test/browser/browser_webconsole_location_logpoint_debugger_link.js | took 94553ms

Bogdan Tara[:bogdan_tara | bogdant]

Comment 1

•

6 years ago

Intermittent based on https://treeherder.mozilla.org/#/jobs?repo=autoland&selectedJob=268281522&fromchange=9c5d1947a72e9264a5e16be2f3fa82f5edc243fe&tochange=5abd597f5d2dd52a2d2945fd95fd16d37b8ea091&searchStr=linux%2Cx64%2Casan%2Cmochitests%2Ctest-linux64-asan%2Fopt-mochitest-devtools-chrome-e10s-5%2Cm%28dt5%29

Comment hidden (Intermittent Failures Robot)

Andreea Pavel [:apavel]

Comment 5

•

6 years ago

Hi Brian, based on retriggers this seems to be a regression from bug 1583668, can you please take a look?

Flags: needinfo?(bhackett1024)

Regressed by: 1583668

Andreea Pavel [:apavel]

Updated

•

6 years ago

Whiteboard: [retriggered][stockwell needswork:owner]

Brian Hackett [Laid off!]

Comment 6

•

6 years ago

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

Hi Brian, based on retriggers this seems to be a regression from bug 1583668, can you please take a look?

Hi, a4de402e0be6 only changed a single test file which runs in a different suite from where this failure occurs (and never runs on linux, actually). I don't think there's any way that it could have legitimately caused this regression.

Flags: needinfo?(bhackett1024)

Andreea Pavel [:apavel]

Comment 7

•

6 years ago

Thanks Brian.

Nicolas is there someone you can assign to take a look at this?

Flags: needinfo?(nchevobbe)

No longer regressed by: 1583668

Comment hidden (Intermittent Failures Robot)

Nicolas Chevobbe [:nchevobbe]

Assignee

Comment 9

•

6 years ago

Sure.
Looking at the logs it looks like the test is running for a long time and enter the 30s timeout. I'll add a requestLongerTimeout in it.

Assignee: nobody → nchevobbe

Status: NEW → ASSIGNED

Flags: needinfo?(nchevobbe)

Comment hidden (Intermittent Failures Robot)

Bogdan Tara[:bogdan_tara | bogdant]

Updated

•

6 years ago

Whiteboard: [retriggered][stockwell disable-recommended] → [stockwell needswork:owner][retriggered]

Comment hidden (Intermittent Failures Robot)

Nicolas Chevobbe [:nchevobbe]

Assignee

Comment 13

•

6 years ago

chujun could you try to see what's happening here? The screenshot from the test failures looks like the logpoint input isn't displayed sometimes

Flags: needinfo?(chujunlu)

Razvan Maries

Comment 14

•

6 years ago

Attached file Bug 1583706 - Disabled browser_webconsole_location_logpoint_debugger_link.js on Linux x64 and Windows. r?#intermittent-reviewers — Details

Chujun Lu

Comment 15

•

6 years ago

(In reply to Nicolas Chevobbe [:nchevobbe] from comment #13)

chujun could you try to see what's happening here? The screenshot from the test failures looks like the logpoint input isn't displayed sometimes

Happy to.

Do you mean the very first comment from "Treeherder Bug Filer" by screenshot?

I wasn't able to reproduce it on my machine but here are some thoughts I have for now:
1.Use assertEditorLogpoint after https://searchfox.org/mozilla-central/source/devtools/client/webconsole/test/browser/browser_webconsole_location_logpoint_debugger_link.js#123
2.Use a helper waitForLog from https://searchfox.org/mozilla-central/source/devtools/client/debugger/test/mochitest/helpers.js#503 as another guard.
3.Break down this test file into two or even three files. This file looks too long for me.

What do you think?

Nicolas Chevobbe [:nchevobbe]

Assignee

Comment 16

•

6 years ago

yes, I was talking about this screenshot: https://taskcluster-artifacts.net/P6UnIrZmQ-GATkZ4jX9khQ/1/public/test_info//mozilla-test-fail-screenshot_Zrx95X.png , which is taken by treeherder when the test fails.

To try to reproduce locally, you might want to run the test with --verify. It will run the test 30 times, in various condition. Sometimes it helps when tracking down an intermittent.
Or if that doesn't work, --run-until-failure --setenv MOZ_CHAOSMODE=true, which might help (--headless is your friend in those case as you don't want to stare at firefox running those tests for a long time :D )

All your suggestions look great to me.
You can try to implement the first two, and if you don't reproduce the failure locally, you might want to push to try with ./mach try fuzzy devtools/client/webconsole/test/browser/browser_webconsole_location_logpoint_debugger_link.js

It will show a list of all the platforms you can run the test in. I usually type test-verify !android !wpt !gpu to filter the list, then do Ctrl + A and Enter. It will run the test with --verify on various platforms, so it may be easier to reproduce the failure/assert it's gone.

Thanks a lot!

Flags: needinfo?(chujunlu)

Phabricator Automation

Updated

•

6 years ago

Attachment #9098448 - Attachment description: Bug 1583706 - Disabled browser_webconsole_location_logpoint_debugger_link.js on Linux x64 and Windows 10 x64. r?#intermittent-reviewers → Bug 1583706 - Disabled browser_webconsole_location_logpoint_debugger_link.js on Linux x64 and Windows. r?#intermittent-reviewers

Razvan Maries

Comment 17

•

6 years ago

Nicolas, the disabling patch got r+. Should we land it?

Flags: needinfo?(nchevobbe)

Nicolas Chevobbe [:nchevobbe]

Assignee

Comment 18

•

6 years ago

sure, let's do that, but let's keep the bug open so we can check if Chujun idea's can fix the failures

Flags: needinfo?(nchevobbe)

Razvan Maries

Updated

•

6 years ago

Keywords: checkin-needed, leave-open

Whiteboard: [retriggered][stockwell disable-recommended] → [retriggered][stockwell disabled]

Pulsebot

Comment 19

•

6 years ago

Pushed by rmaries@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/b58865500ede
Disabled browser_webconsole_location_logpoint_debugger_link.js on Linux x64 and Windows. r=gbrown

Keywords: checkin-needed

Noemi Erli[:noemi_erli]

Comment 20

•

6 years ago

bugherder

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

Comment hidden (Intermittent Failures Robot)

Chujun Lu

Comment 22

•

6 years ago

Attached image Proposed edit to test file — Details

Hey @nchevobbe,

I wasn't aware of the variant ways to run ./mach mochitest, thanks for your detailed instruction!

With the current file:
./mach mochitest --verify : all tests passed
./mach mochitest --run-until-failure --setenv MOZ_CHAOSMODE=true: all tests passed.

With changes in the image attachment applied:
./mach mochitest --verify : all tests passed
./mach mochitest --run-until-failure --setenv MOZ_CHAOSMODE=true: all tests passed
./mach try fuzzy then test-verify !android !wpt !gpu:
https://treeherder.mozilla.org/#/jobs?repo=try&revision=e47f237565a4047894a56e78c7b5c99d5ca445b1&selectedJob=269719882

The progress has been stuck at 90% for 8+ hrs. It seems certain Window platforms could not find the requested test?

Nicolas Chevobbe [:nchevobbe]

Assignee

Comment 23

•

6 years ago

Thanks Chujun!

Sometimes the test are stuck, for some reason.
One thing we need to do is remove the skip-if annotation in the browser.ini file. Otherwise the test is ignored.

diff --git a/devtools/client/webconsole/test/browser/browser.ini b/devtools/client/webconsole/test/browser/browser.ini
--- a/devtools/client/webconsole/test/browser/browser.ini
+++ b/devtools/client/webconsole/test/browser/browser.ini
@@ -377,7 +377,6 @@ skip-if = fission
 [browser_webconsole_keyboard_accessibility.js]
 [browser_webconsole_location_debugger_link.js]
 [browser_webconsole_location_logpoint_debugger_link.js]
-skip-if = (os == 'linux' && bits == 64) || (os == 'win') # Bug 1583706
 [browser_webconsole_location_scratchpad_link.js]
 [browser_webconsole_location_styleeditor_link.js]
 [browser_webconsole_logErrorInPage.js]

Chujun Lu

Comment 24

•

6 years ago

Sorry for my negligence :/

With skip-if removed,

1.Unchanged file:
./mach mochitest --verify and ./mach mochitest --run-until-failure --setenv MOZ_CHAOSMODE=true tests passed locally.

2.Changes from the previous screenshot applied:
Failed. https://treeherder.mozilla.org/#/jobs?repo=try&revision=ab1b443cabb4e92f93ff681c6209eb073593db82

3.Changes from the previous screenshot + requestLongerTimeout(2); at the beginning of file:
Failed. https://treeherder.mozilla.org/#/jobs?repo=try&revision=e4dbe6c4d24495e2926c35931317b9726e8f410f

4.Changes from the previous screenshot +
--- a/devtools/client/webconsole/test/browser/browser_webconsole_location_logpoint_debugger_link.js
+++ b/devtools/client/webconsole/test/browser/browser_webconsole_location_logpoint_debugger_link.js
@@ -5,7 +5,6 @@
// conditional panels in the debugger.

"use strict";
-requestLongerTimeout(2);

const TEST_URI =
"http://example.com/browser/devtools/client/webconsole/" +
@@ -125,6 +124,7 @@ add_task(async function() {
await assertEditorLogpoint(dbg, 8, { hasLog: true });

info("Add a logpoint to the second file");
+ await new Promise(r => setTimeout(r, 100));
await selectSource(dbg, "test-location-debugger-link-logpoint-2.js");
await setLogPoint(dbg, 8, "c is ${c}");
await waitForLog(dbg, "c is ${c}");

Failed. https://treeherder.mozilla.org/#/jobs?repo=try&revision=a9e1eb0184abcc5434490982ee0b0e1d360b6d25
The idea came from https://docs.firefox-dev.tools/tests/debugging-intermittents.html but when I put in yield new Promise(r => setTimeout(r, 100));, there was an error saying yield is a preserved word.

Would splitting the test file into two be worth trying next? Any other direction for debugging is appreciated!

Comment hidden (Intermittent Failures Robot)

Nicolas Chevobbe [:nchevobbe]

Assignee

Comment 26

•

6 years ago

Thanks for investigating Chujun!

So yield can only be used in generator functions (See https://developer.mozilla.org/en-US/docs/Web/JavaScript/Reference/Statements/function*)

To wait in an async function, we can use await new Promise(res => setTimeout(res, 100))

So we may try that.
I'm not sure we have a timing issue here, but maybe there a bug in the debugger itself? some race condition that prevents showing the logpoint input maybe? That hard to check because you can't reproduce locally, but you might want to add a lot of console.log / dump in debugger code and pushing to TRY, and then, on failing jobs, checking the logs to see what's happening.

You can check here the logs that we have before the test fails https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=269951529&repo=try&lineNumber=2213-2264 since we log all the actions dispatched in the debugger.

Hope this helps!

Comment hidden (Intermittent Failures Robot)

Chujun Lu

Comment 28

•

6 years ago

Thanks for your feedback!

I tried await new Promise back then. There were failures. https://treeherder.mozilla.org/#/jobs?repo=try&revision=a9e1eb0184abcc5434490982ee0b0e1d360b6d25

There was a HTTP 404 error when I opened https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=269951529&repo=try&lineNumber=2213-2264. I couldn't see that log. But I was able to read the log from the very first comment, and found that action "SET_SOURCE_ACTOR_BREAKPOINT_COLUMNS" didn't get logged when Add a logpoint to the second file. This action ran when we setLogPoint in other places.

So I added some dump statements in relative files and pushed to Try. No failures. https://treeherder.mozilla.org/#/jobs?repo=try&revision=0d3abec67aa051e75a9bc7c6d1f750293b. Interestingly, its revision didn't show my removal of skip-if in browser.ini.

Moreover, I refactored the test and had dump statements. No failures: https://treeherder.mozilla.org/#/jobs?repo=try&revision=99c94301a37711f4e164ae117060e64063a8e00a

I think we can wait and see if any new failure reported by robot?

Nicolas Chevobbe [:nchevobbe]

Assignee

Comment 29

•

6 years ago

Thanks Chujun!

(In reply to Chujun Lu from comment #28)

So I added some dump statements in relative files and pushed to Try. No failures. https://treeherder.mozilla.org/#/jobs?repo=try&revision=0d3abec67aa051e75a9bc7c6d1f750293b. Interestingly, its revision didn't show my removal of skip-if in browser.ini.

I think the removal of the skip-if was done in the parent revision: https://hg.mozilla.org/try/rev/5a289914816cd2b9c07bd6f49bd2519743d4b981

Moreover, I refactored the test and had dump statements. No failures: https://treeherder.mozilla.org/#/jobs?repo=try&revision=99c94301a37711f4e164ae117060e64063a8e00a

I think we can wait and see if any new failure reported by robot?

I triggered the task a few time (on windows 10, which was where we had the most failures) to make sure the test does not fail anymore.
Maybe there was a race condition or an issue that was fixed in debugger code in the meantime.
Anyway, if the test doesn't fail, we can land a patch that simply remove the skip-if in browser.ini :)

Nicolas Chevobbe [:nchevobbe]

Assignee

Comment 30

•

6 years ago

Okay so the triggered run are all green, so I think we can remove the skip-if :)

Andreea Pavel [:apavel]

Comment 31

•

6 years ago

Attached file Bug 1583706 - remove skip-if from browser_webconsole_location_logpoint_debugger_link.js r=nchevobbe — Details

Andreea Pavel [:apavel]

Comment 32

•

6 years ago

•

Edited

(In reply to Nicolas Chevobbe [:nchevobbe] from comment #30)

Okay so the triggered run are all green, so I think we can remove the skip-if :)

I did the patch, however, failures occurred on mochitest devtools chrome jobs: https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?startday=2019-09-30&endday=2019-10-30&tree=trunk&bug=1583706

I saw the jobs were not run on that try push so I triggered now windows10-64 asan opt-mochitest-devtools-chrome-e10s jobs.

Update: All jobs (retriggers) are green.

Andreea Pavel [:apavel]

Updated

•

6 years ago

Keywords: leave-open

Whiteboard: [retriggered][stockwell disabled] → [retriggered]

Pulsebot

Comment 33

•

6 years ago

Pushed by apavel@mozilla.com: https://hg.mozilla.org/integration/autoland/rev/85aa4fa5722b remove skip-if from browser_webconsole_location_logpoint_debugger_link.js r=nchevobbe

Andreea Pavel [:apavel]

Comment 34

•

6 years ago

bugherder

https://hg.mozilla.org/mozilla-central/rev/85aa4fa5722b

Status: ASSIGNED → RESOLVED

Closed: 6 years ago

status-firefox72: --- → fixed

Resolution: --- → FIXED

Target Milestone: --- → Firefox 72

Ryan VanderMeulen [:RyanVM]

Updated

•

6 years ago

status-firefox70: --- → unaffected

status-firefox71: --- → wontfix

status-firefox-esr68: --- → unaffected

Bug 1583706 - Disabled browser_webconsole_location_logpoint_debugger_link.js on Linux x64 and Windows. r?#intermittent-reviewers 6 years ago Razvan Maries 47 bytes, text/x-phabricator-request		Details \| Review
Proposed edit to test file 6 years ago Chujun Lu 519.87 KB, image/png		Details
Bug 1583706 - remove skip-if from browser_webconsole_location_logpoint_debugger_link.js r=nchevobbe 6 years ago Andreea Pavel [:apavel] 47 bytes, text/x-phabricator-request		Details \| Review