Open Bug 1594897 Opened 11 months ago Updated 22 days ago

Intermittent devtools/client/webconsole/test/browser/browser_webconsole_location_logpoint_debugger_link.js | The textarea of logpoint panel is focused - Got BODY, expected TEXTAREA

Categories

(DevTools :: Console, defect, P5)

defect

Tracking

(Not tracked)

REOPENED

People

(Reporter: aiakab, Assigned: apavel)

References

Details

(Keywords: intermittent-failure, leave-open, Whiteboard: [stockwell disabled])

Attachments

(2 files, 1 obsolete file)

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

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


[task 2019-10-30T23:52:12.299Z] 23:52:12 INFO - TEST-START | devtools/client/webconsole/test/browser/browser_webconsole_location_logpoint_debugger_link.js
[task 2019-10-30T23:52:12.356Z] 23:52:12 INFO - GECKO(1740) | ++DOCSHELL 0x105e49000 == 2 [pid = 1743] [id = {86ac10f5-3254-0243-a3af-be5369305196}]
[task 2019-10-30T23:52:12.356Z] 23:52:12 INFO - GECKO(1740) | ++DOMWINDOW == 4 (0x11e7513e0) [pid = 1743] [serial = 454] [outer = 0x0]
[task 2019-10-30T23:52:12.357Z] 23:52:12 INFO - GECKO(1740) | ++DOMWINDOW == 5 (0x105f34000) [pid = 1743] [serial = 455] [outer = 0x11e7513e0]
[task 2019-10-30T23:52:12.485Z] 23:52:12 INFO - GECKO(1740) | ++DOMWINDOW == 6 (0x11694cc00) [pid = 1743] [serial = 456] [outer = 0x11e7513e0]
[task 2019-10-30T23:52:12.551Z] 23:52:12 INFO - GECKO(1740) | --DOCSHELL 0x158e53800 == 7 [pid = 1740] [id = {2bd7ebec-1822-0e43-885e-12f8eee9f662}] [url = chrome://devtools/content/debugger/index.html]
[task 2019-10-30T23:52:12.709Z] 23:52:12 INFO - GECKO(1740) | ++DOCSHELL 0x125975000 == 8 [pid = 1740] [id = {d639d203-1ba2-1040-a066-d05ec749f4eb}]
[task 2019-10-30T23:52:12.710Z] 23:52:12 INFO - GECKO(1740) | ++DOMWINDOW == 21 (0x111963020) [pid = 1740] [serial = 1320] [outer = 0x0]
[task 2019-10-30T23:52:12.710Z] 23:52:12 INFO - GECKO(1740) | ++DOMWINDOW == 22 (0x111012800) [pid = 1740] [serial = 1321] [outer = 0x111963020]
[task 2019-10-30T23:52:12.710Z] 23:52:12 INFO - GECKO(1740) | ++DOMWINDOW == 23 (0x11c5b2c00) [pid = 1740] [serial = 1322] [outer = 0x111963020]
[task 2019-10-30T23:52:12.755Z] 23:52:12 INFO - GECKO(1740) | ++DOMWINDOW == 24 (0x12436c400) [pid = 1740] [serial = 1323] [outer = 0x111963020]
[task 2019-10-30T23:52:12.851Z] 23:52:12 INFO - GECKO(1740) | [Parent 1740, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80004005: file /builds/worker/workspace/build/src/dom/base/nsContentUtils.cpp, line 3697

[task 2019-10-30T23:52:22.458Z] 23:52:22 INFO - Got event: 'source-in-debugger-opened' on [object Object].
[task 2019-10-30T23:52:22.458Z] 23:52:22 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") -
[task 2019-10-30T23:52:22.458Z] 23:52:22 INFO - TEST-PASS | devtools/client/webconsole/test/browser/browser_webconsole_location_logpoint_debugger_link.js | expected source url -
[task 2019-10-30T23:52:22.458Z] 23:52:22 INFO - Buffered messages finished
[task 2019-10-30T23:52:22.458Z] 23:52:22 INFO - TEST-UNEXPECTED-FAIL | devtools/client/webconsole/test/browser/browser_webconsole_location_logpoint_debugger_link.js | The textarea of logpoint panel is focused - Got BODY, expected TEXTAREA
[task 2019-10-30T23:52:22.458Z] 23:52:22 INFO - Stack trace:
[task 2019-10-30T23:52:22.458Z] 23:52:22 INFO - chrome://mochikit/content/browser-test.js:test_is:1314
[task 2019-10-30T23:52:22.458Z] 23:52:22 INFO - chrome://mochitests/content/browser/devtools/client/webconsole/test/browser/head.js:checkClickOnNode:531
[task 2019-10-30T23:52:22.458Z] 23:52:22 INFO - chrome://mochitests/content/browser/devtools/client/webconsole/test/browser/head.js:testOpenInDebugger:455
[task 2019-10-30T23:52:22.458Z] 23:52:22 INFO - chrome://mochitests/content/browser/devtools/client/webconsole/test/browser/browser_webconsole_location_logpoint_debugger_link.js:null:65
[task 2019-10-30T23:52:22.459Z] 23:52:22 INFO - chrome://mochikit/content/browser-test.js:Tester_execTest/<:1069
[task 2019-10-30T23:52:22.459Z] 23:52:22 INFO - chrome://mochikit/content/browser-test.js:Tester_execTest:1104
[task 2019-10-30T23:52:22.459Z] 23:52:22 INFO - chrome://mochikit/content/browser-test.js:nextTest/<:932
[task 2019-10-30T23:52:22.459Z] 23:52:22 INFO - chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:SimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<:805
[task 2019-10-30T23:52:22.459Z] 23:52:22 INFO - Not taking screenshot here: see the one that was previously logged
[task 2019-10-30T23:52:22.459Z] 23:52:22 INFO - TEST-UNEXPECTED-FAIL | devtools/client/webconsole/test/browser/browser_webconsole_location_logpoint_debugger_link.js | Uncaught exception - at chrome://mochitests/content/browser/devtools/client/webconsole/test/browser/head.js:537 - TypeError: inputEl.parentElement.parentElement is null
[task 2019-10-30T23:52:22.459Z] 23:52:22 INFO - Stack trace:
[task 2019-10-30T23:52:22.459Z] 23:52:22 INFO - checkClickOnNode@chrome://mochitests/content/browser/devtools/client/webconsole/test/browser/head.js:537:24
[task 2019-10-30T23:52:22.459Z] 23:52:22 INFO - asynctestOpenInDebugger@chrome://mochitests/content/browser/devtools/client/webconsole/test/browser/head.js:455:9
[task 2019-10-30T23:52:22.459Z] 23:52:22 INFO - async
@chrome://mochitests/content/browser/devtools/client/webconsole/test/browser/browser_webconsole_location_logpoint_debugger_link.js:65:9
[task 2019-10-30T23:52:22.459Z] 23:52:22 INFO - Async*Tester_execTest/<@chrome://mochikit/content/browser-test.js:1069:34
[task 2019-10-30T23:52:22.459Z] 23:52:22 INFO - Tester_execTest@chrome://mochikit/content/browser-test.js:1104:11
[task 2019-10-30T23:52:22.459Z] 23:52:22 INFO - nextTest/<@chrome://mochikit/content/browser-test.js:932:14
[task 2019-10-30T23:52:22.459Z] 23:52:22 INFO - SimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:805:67
[task 2019-10-30T23:52:22.459Z] 23:52:22 INFO - Leaving test bound
[task 2019-10-30T23:52:22.460Z] 23:52:22 INFO - Entering test bound
[task 2019-10-30T23:52:22.460Z] 23:52:22 INFO - Adding a new tab with URL: http://example.com/browser/devtools/client/webconsole/test/browser/test-location-debugger-link-logpoint.html

Similar to Bug 1592854 except it is failing on Windows.

Brian can you please check if it is the same issue?

URL: 1592854
Flags: needinfo?(bhackett1024)
URL: 1592854
No longer depends on: 1592854
See Also: → 1592854
Whiteboard: [retriggered][stockwell fixed:patch] → [stockwell needswork:owner]
Flags: needinfo?(bhackett1024)

Brian please take a look.

Flags: needinfo?(bhackett1024)

This is almost certainly the same issue as bug 1592854, though I don't have a windows machine to confirm locally. The fix in bug 1592854 is only a workaround, inserting a delay into the patch. Increasing the delay might fix this intermittent, though the underlying issue still needs to be addressed.

Flags: needinfo?(bhackett1024)

Nicholas can you assign someone to take a look at this?

Flags: needinfo?(nchevobbe)

Chujun, would you know how this could be fixed?
Brian did some investigation in https://bugzilla.mozilla.org/show_bug.cgi?id=1592854#c5

Flags: needinfo?(nchevobbe) → needinfo?(chujunlu)
Whiteboard: [stockwell unknown] → [stockwell needswork:owner]

Joel any suggestions here?

Flags: needinfo?(jmaher)

:apavel, it looks like the ccov failures are close to perma failing, can we just disable this on ccov and see where that leaves us?

Flags: needinfo?(jmaher)
Pushed by apavel@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/8f2e33e24cb2
disable browser_webconsole_location_logpoint_debugger_link.js on ccov r=jmaher
Attached video conditionalPanel.mp4

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

This is almost certainly the same issue as bug 1592854, though I don't have a windows machine to confirm locally. The fix in bug 1592854 is only a workaround, inserting a delay into the patch. Increasing the delay might fix this intermittent, though the underlying issue still needs to be addressed.

Hi Brain, I reproduced the error when I removed await waitForTime(1000); and ran ./mach mochitest --verify --headless. When it fails, the test is clicking a message in console to navigate to debugger => OPEN_CONDITIONAL_PANEL action dispatches => a bunch of SET_BREAKPOINT actions dispatch. In other cases that pass, there aren't SET_BREAKPOINT actions after OPEN_CONDITIONAL_PANEL. I put some console.trace statements and pushed to Try. Here's an Example.

In a running debugger, if I leave conditional panel open and try to add a breakpoint, things will be messed up. See attached Video.

Based on the logged actions, I guess the problem is that we open conditional panel immediately, while source is adding breakpoints (which shouldn't be?); conditional panel loses focus and never gets back focus. I tried adding waitForDispatch(dbg, "SET_BREAKPOINT", bpCount); or waitFor(() => dbg._selectors.getBreakpointCount(dbg._getState()) === bpCount) after clicking console message in test. Didn't work.

I'm not sure why newQueuedSources is called. I'm wondering is there an event like waitUntilBreakpointSync I can check before dispatching the OPEN_CONDITIONAL_PANEL action in debugger or in the test? Any pointer would be appreciated!

Status: NEW → RESOLVED
Closed: 10 months ago
Resolution: --- → FIXED
Target Milestone: --- → Firefox 72
Assignee: nobody → apavel
Status: RESOLVED → REOPENED
Keywords: leave-open
Resolution: FIXED → ---
Whiteboard: [stockwell needswork:owner] → [stockwell disabled]
Target Milestone: Firefox 72 → ---

(In reply to Chujun Lu from comment #12)

Created attachment 9110177 [details]
conditionalPanel.mp4

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

This is almost certainly the same issue as bug 1592854, though I don't have a windows machine to confirm locally. The fix in bug 1592854 is only a workaround, inserting a delay into the patch. Increasing the delay might fix this intermittent, though the underlying issue still needs to be addressed.

Hi Brain, I reproduced the error when I removed await waitForTime(1000); and ran ./mach mochitest --verify --headless. When it fails, the test is clicking a message in console to navigate to debugger => OPEN_CONDITIONAL_PANEL action dispatches => a bunch of SET_BREAKPOINT actions dispatch. In other cases that pass, there aren't SET_BREAKPOINT actions after OPEN_CONDITIONAL_PANEL. I put some console.trace statements and pushed to Try. Here's an Example.

In a running debugger, if I leave conditional panel open and try to add a breakpoint, things will be messed up. See attached Video.

Based on the logged actions, I guess the problem is that we open conditional panel immediately, while source is adding breakpoints (which shouldn't be?); conditional panel loses focus and never gets back focus. I tried adding waitForDispatch(dbg, "SET_BREAKPOINT", bpCount); or waitFor(() => dbg._selectors.getBreakpointCount(dbg._getState()) === bpCount) after clicking console message in test. Didn't work.

I'm not sure why newQueuedSources is called. I'm wondering is there an event like waitUntilBreakpointSync I can check before dispatching the OPEN_CONDITIONAL_PANEL action in debugger or in the test? Any pointer would be appreciated!

newQueuedSources() will execute in response to new sources coming in from the server, which can happen at pretty much anytime. The main issue that would be nice to fix here is not so much getting the test to pass reliably as it is to get the code editor UI to not be broken when setting breakpoints with the conditional panel open. If that is fixed, the test should work without needing any artificial delays or other checks. This is where I got stuck though, as I don't know much about the code mirror source or how it interacts with the debugger's reducer state.

There are 21 total failures in the last 7 days on linux64 debug

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

[task 2019-12-23T21:32:17.523Z] 21:32:17 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") -
[task 2019-12-23T21:32:17.523Z] 21:32:17 INFO - TEST-PASS | devtools/client/webconsole/test/browser/browser_webconsole_location_logpoint_debugger_link.js | expected source url -
[task 2019-12-23T21:32:17.525Z] 21:32:17 INFO - Buffered messages finished
[task 2019-12-23T21:32:17.526Z] 21:32:17 INFO - TEST-UNEXPECTED-FAIL | devtools/client/webconsole/test/browser/browser_webconsole_location_logpoint_debugger_link.js | The textarea of logpoint panel is focused - Got BODY, expected TEXTAREA
[task 2019-12-23T21:32:17.526Z] 21:32:17 INFO - Stack trace:
[task 2019-12-23T21:32:17.527Z] 21:32:17 INFO - chrome://mochikit/content/browser-test.js:test_is:1320
[task 2019-12-23T21:32:17.528Z] 21:32:17 INFO - chrome://mochitests/content/browser/devtools/client/webconsole/test/browser/head.js:checkClickOnNode:544
[task 2019-12-23T21:32:17.529Z] 21:32:17 INFO - chrome://mochitests/content/browser/devtools/client/webconsole/test/browser/head.js:testOpenInDebugger:463
[task 2019-12-23T21:32:17.529Z] 21:32:17 INFO - chrome://mochitests/content/browser/devtools/client/webconsole/test/browser/browser_webconsole_location_logpoint_debugger_link.js:null:53
[task 2019-12-23T21:32:17.530Z] 21:32:17 INFO - chrome://mochikit/content/browser-test.js:Tester_execTest/<:1062
[task 2019-12-23T21:32:17.530Z] 21:32:17 INFO - chrome://mochikit/content/browser-test.js:Tester_execTest:1097
[task 2019-12-23T21:32:17.530Z] 21:32:17 INFO - chrome://mochikit/content/browser-test.js:nextTest/<:925
[task 2019-12-23T21:32:17.531Z] 21:32:17 INFO - chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:SimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<:808
[task 2019-12-23T21:32:17.531Z] 21:32:17 INFO - Not taking screenshot here: see the one that was previously logged
[task 2019-12-23T21:32:17.532Z] 21:32:17 INFO - TEST-UNEXPECTED-FAIL | devtools/client/webconsole/test/browser/browser_webconsole_location_logpoint_debugger_link.js | Uncaught exception - at chrome://mochitests/content/browser/devtools/client/webconsole/test/browser/head.js:550 - TypeError: inputEl.parentElement.parentElement is null
[task 2019-12-23T21:32:17.532Z] 21:32:17 INFO - Stack trace:
[task 2019-12-23T21:32:17.533Z] 21:32:17 INFO - checkClickOnNode@chrome://mochitests/content/browser/devtools/client/webconsole/test/browser/head.js:550:24
[task 2019-12-23T21:32:17.533Z] 21:32:17 INFO - asynctestOpenInDebugger@chrome://mochitests/content/browser/devtools/client/webconsole/test/browser/head.js:463:9
[task 2019-12-23T21:32:17.534Z] 21:32:17 INFO - async
@chrome://mochitests/content/browser/devtools/client/webconsole/test/browser/browser_webconsole_location_logpoint_debugger_link.js:53:9
[task 2019-12-23T21:32:17.534Z] 21:32:17 INFO - Async*Tester_execTest/<@chrome://mochikit/content/browser-test.js:1062:34
[task 2019-12-23T21:32:17.535Z] 21:32:17 INFO - Tester_execTest@chrome://mochikit/content/browser-test.js:1097:11
[task 2019-12-23T21:32:17.535Z] 21:32:17 INFO - nextTest/<@chrome://mochikit/content/browser-test.js:925:14
[task 2019-12-23T21:32:17.536Z] 21:32:17 INFO - SimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:808:67
[task 2019-12-23T21:32:17.536Z] 21:32:17 INFO - Leaving test bound
[task 2019-12-23T21:32:17.537Z] 21:32:17 INFO - Entering test bound
[task 2019-12-23T21:32:17.537Z] 21:32:17 INFO - GECKO(1120) | [ACTION] SET_BREAKPOINT [done] - {"type":"SET_BREAKPOINT","cx":{"navigateCounter":0},"breakpoint":{"id":"sourceURL-http://example.com/browser/devtools/client/webconsole/test/browser/test-location-debugger-link-logpoint-1.js:7:12","disabled":false,"options":{"logValue":"undefinedVariable"},"location":{"line":7,"column":12,"sourceId":"sourceURL-http://example.com/browser/devtools/client/webconsole/test/browser/test-location-debugger-link-logpoint-1.js","sourceUrl":"http://example.com/browser/devtools/client/webconsole/test/browser/test-location-debugger-link-logpoint-1.js"},"astLocation":{"name":"add","offset":{"line":1},"index":0},"generatedLocation":{"line":7,"column":12,"sourceId":"sourceURL-http://example.com/browser/devtools/client/webconsole/test/browser/test-location-debugger-link-logpoint-1.js","sourceUrl":"http://example.com/browser/devtools/client/webconsole/test/browser/test-location-debugger-link-logpoint-1.js"},"text":"1;","originalText":"1;"},"seqId":"9","status":"done","value":[null]}
[task 2019-12-23T21:32:17.538Z] 21:32:17 INFO - Adding a new tab with URL: http://example.com/browser/devtools/client/webconsole/test/browser/test-location-debugger-link-logpoint.html
[task 2019-12-23T21:32:17.538Z] 21:32:17 INFO - GECKO(1120) | [Child 1320: Main Thread]: I/DocShellAndDOMWindowLeak ++DOCSHELL 0x7fa418bba800 == 1 [pid = 1320] [id = {f77b43bb-838d-4090-959a-f891275a3f94}]
[task 2019-12-23T21:32:17.539Z] 21:32:17 INFO - GECKO(1120) | [Child 1320: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 1 (0x7fa41eb9b200) [pid = 1320] [serial = 297] [outer = (nil)]
[task 2019-12-23T21:32:17.539Z] 21:32:17 INFO - GECKO(1120) | [Child 1320: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 2 (0x7fa418b4a400) [pid = 1320] [serial = 298] [outer = 0x7fa41eb9b200]
[task 2019-12-23T21:32:17.548Z] 21:32:17 INFO - GECKO(1120) | [ACTION] SET_BREAKPOINT [done] - {"type":"SET_BREAKPOINT","cx":{"navigateCounter":0},"breakpoint":{"id":"sourceURL-http://example.com/browser/devtools/client/webconsole/test/browser/test-location-debugger-link-logpoint-1.js:8:12","disabled":false,"options":{"logValue":"`a is ${a}`"},"location":{"line":8,"column":12,"sourceId":"sourceURL-http://example.com/browser/devtools/client/webconsole/test/browser/test-location-debugger-link-logpoint-1.js","sourceUrl":"http://example.com/browser/devtools/client/webconsole/test/browser/test-location-debugger-link-logpoint-1.js"},"astLocation":{"name":"add","offset":{"line":2},"index":0},"generatedLocation":{"line":8,"column":12,"sourceId":"sourceURL-http://example.com/browser/devtools/client/webconsole/test/browser/test-location-debugger-link-logpoint-1.js","sourceUrl":"http://example.com/browser/devtools/client/webconsole/test/browser/test-location-debugger-link-logpoint-1.js"},"text":"2;","originalText":"2;"},"seqId":"10","status":"done","value":[null]}
[task 2019-12-23T21:32:17.710Z] 21:32:17 INFO - GECKO(1120) | [Parent 1120, Main Thread] WARNING: we only accept nsIURI interface type, patch welcome: file /builds/worker/workspace/build/src/dom/ipc/PropertyBagUtils.cpp, line 112
[task 2019-12-23T21:32:17.711Z] 21:32:17 INFO - GECKO(1120) | [Child 1320, Main Thread] WARNING: Trying to request nsIHttpChannel from DocumentChannelChild, this is likely broken: file /builds/worker/workspace/build/src/netwerk/ipc/DocumentChannelChild.cpp, line 63
[task 2019-12-23T21:32:17.734Z] 21:32:17 INFO - GECKO(1120) | [Child 1320: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 3 (0x7fa418b51400) [pid = 1320] [serial = 299] [outer = 0x7fa41eb9b200]
[task 2019-12-23T21:32:18.035Z] 21:32:18 INFO - Tab added and finished loading
[task 2019-12-23T21:32:18.035Z] 21:32:18 INFO - Opening the toolbox

There seems to be a spike here starting December 19th: https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?startday=2019-11-23&endday=2019-12-23&tree=trunk&bug=1594897

Hey Jason, I've been struggling with an intermitter failure. This mochitest is about clicking a location message in the console jumps to the debugger and opens the conditional panel. The problem is that after an OPEN_CONDITIONAL_PANEL action dispatches, there're SET_BREAKPOINT actions coming in, then the test times out.

Logan pointed to me that componentWillUpdate in src/components/Editor/ConditionalPanel.js looks wired. It calls clearConditionalPanel but then in componentDidUpdate, keepFocusOnInput will be called. I think it's weird to clear the panel then keep panel's input in focus since we won't have the input area once we close the panel. Removing componentDidUpdate seems doesn't have any effect on UI, and makes the test pass. Hence I commented it out and pushed to Try to see if it breaks anything.

There were refactors in the pass of this part. I'm not quite sure if componentDidUpdate is needed or what it's for, so a bit of guidance would be helpful.

Attachment #9118805 - Attachment is obsolete: true

It seems the issue doesn't occur for a while. I'll keep an eye if it reappears.

Flags: needinfo?(chujunlu)

(In reply to Chujun Lu from comment #28)

It seems the issue doesn't occur for a while. I'll keep an eye if it reappears.

Oh, I found it's because the test was disabled on ccov. Sorry! Hmmm, I wasn't able to make much progress.

You need to log in before you can comment on or make changes to this bug.