Closed Bug 1767724 Opened 3 years ago Closed 6 months ago

Intermittent devtools/client/webconsole/test/browser/browser_webconsole_console_logging_workers_api.js | single tracking bug

Categories

(DevTools :: Console, defect, P3)

Product:
DevTools
Component:
Console
Type:
defect

Tracking

(firefox139 fixed)

Status:
RESOLVED FIXED
Milestone:
139 Branch
Tracking Flags:
Tracking Status
firefox139 --- fixed

People

(Reporter: jmaher, Assigned: nchevobbe)

References

Details

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

Attachments

(2 files)

Bug 1767724 - Disable browser_webconsole_console_logging_workers_api.js on linux and apple_catalina debug for frequent failures. r=#intermittent-reviewers
48 bytes, text/x-phabricator-request
Details | Review
Bug 1767724 - [devtools Fix browser_webconsole_console_logging_workers_api.js intermittent. r=#devtools.
48 bytes, text/x-phabricator-request
Details | Review
No description provided.

Filter on devtools-intermittent-singletrackingbug-triage

Severity: -- → S4

Update

There have been 31 failures within the last 7 days:

  • 12 failures on Linux 18.04 x64 WebRender debug
  • 13 failures on OS X 10.15 WebRender debug/opt
  • 6 failures on OS X 10.15 WebRender Shippable opt

Recent failure log: https://treeherder.mozilla.org/logviewer?job_id=419888318&repo=autoland&lineNumber=4765

[task 2023-06-19T20:43:35.016Z] 20:43:35     INFO - TEST-PASS | devtools/client/webconsole/test/browser/browser_webconsole_console_logging_workers_api.js | Symbol logged from worker is visible in the console - 
[task 2023-06-19T20:43:35.016Z] 20:43:35     INFO - Click on the clear button and wait for messages to be removed
[task 2023-06-19T20:43:35.017Z] 20:43:35     INFO - Buffered messages finished
[task 2023-06-19T20:43:35.019Z] 20:43:35     INFO - TEST-UNEXPECTED-FAIL | devtools/client/webconsole/test/browser/browser_webconsole_console_logging_workers_api.js | Uncaught exception in test bound  - at chrome://mochitests/content/browser/devtools/client/shared/test/shared-head.js:1055 - Error: Failed waitFor():  
[task 2023-06-19T20:43:35.019Z] 20:43:35     INFO - Failed condition: () =>
[task 2023-06-19T20:43:35.019Z] 20:43:35     INFO -       !findConsoleAPIMessage(hud, "initial-message-from-worker") &&
[task 2023-06-19T20:43:35.019Z] 20:43:35     INFO -       !findConsoleAPIMessage(hud, "log-from-worker") 
[task 2023-06-19T20:43:35.019Z] 20:43:35     INFO - Exception Message:  - timed out after 500 tries.
[task 2023-06-19T20:43:35.019Z] 20:43:35     INFO - Stack trace:
[task 2023-06-19T20:43:35.020Z] 20:43:35     INFO - waitFor@chrome://mochitests/content/browser/devtools/client/shared/test/shared-head.js:1055:11
[task 2023-06-19T20:43:35.020Z] 20:43:35     INFO - async*testWorkerMessage@chrome://mochitests/content/browser/devtools/client/webconsole/test/browser/browser_webconsole_console_logging_workers_api.js:97:9
[task 2023-06-19T20:43:35.020Z] 20:43:35     INFO - async*@chrome://mochitests/content/browser/devtools/client/webconsole/test/browser/browser_webconsole_console_logging_workers_api.js:19:9
[task 2023-06-19T20:43:35.020Z] 20:43:35     INFO - async*handleTask@chrome://mochikit/content/browser-test.js:1131:26
[task 2023-06-19T20:43:35.020Z] 20:43:35     INFO - _runTaskBasedTest@chrome://mochikit/content/browser-test.js:1203:18
[task 2023-06-19T20:43:35.020Z] 20:43:35     INFO - Tester_execTest@chrome://mochikit/content/browser-test.js:1345:14
[task 2023-06-19T20:43:35.020Z] 20:43:35     INFO - nextTest/<@chrome://mochikit/content/browser-test.js:1120:14
[task 2023-06-19T20:43:35.021Z] 20:43:35     INFO - SimpleTest.waitForFocus/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:1056:13
[task 2023-06-19T20:43:35.021Z] 20:43:35     INFO - Leaving test bound

Nicolas, can you help us assign this to someone?
Thank you.

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

Update

There have been 31 failures within the last 7 days:

  • 25 failures on Linux 18.04 x64 WebRender opt/debug
  • 3 failures on Linux 18.04 x64 WebRender Shippable opt
  • 3 failures on OS X 10.15 WebRender debug

Recent failure log: https://treeherder.mozilla.org/logviewer?job_id=436252452&repo=autoland&lineNumber=6062

Whiteboard: [stockwell unknown] → [stockwell needswork:owner]

There have been 55 total failures in the last 7 days.
There are:

  • 41 failures on Linux 18.04 x64 WebRender debug
  • 12 failures on Linux 18.04 x64 WebRender opt
  • 2 failures on OS X 10.15 WebRender debug

Recent failure log.

[task 2023-11-21T05:50:56.270Z] 05:50:56     INFO - TEST-PASS | devtools/client/webconsole/test/browser/browser_webconsole_console_logging_workers_api.js | undefined assertion name - 
[task 2023-11-21T05:50:56.271Z] 05:50:56     INFO - Click on the clear button and wait for messages to be removed
[task 2023-11-21T05:50:56.271Z] 05:50:56     INFO - Buffered messages finished
[task 2023-11-21T05:50:56.273Z] 05:50:56     INFO - TEST-UNEXPECTED-FAIL | devtools/client/webconsole/test/browser/browser_webconsole_console_logging_workers_api.js | Uncaught exception in test bound  - at chrome://mochitests/content/browser/devtools/client/shared/test/shared-head.js:1055 - Error: Failed waitFor():  
[task 2023-11-21T05:50:56.273Z] 05:50:56     INFO - Failed condition: () =>
[task 2023-11-21T05:50:56.273Z] 05:50:56     INFO -       !findConsoleAPIMessage(hud, "initial-message-from-worker") &&
[task 2023-11-21T05:50:56.273Z] 05:50:56     INFO -       !findConsoleAPIMessage(hud, "log-from-worker") 
[task 2023-11-21T05:50:56.273Z] 05:50:56     INFO - Exception Message:  - timed out after 500 tries.
[task 2023-11-21T05:50:56.273Z] 05:50:56     INFO - Stack trace:
[task 2023-11-21T05:50:56.273Z] 05:50:56     INFO - waitFor@chrome://mochitests/content/browser/devtools/client/shared/test/shared-head.js:1055:11
[task 2023-11-21T05:50:56.273Z] 05:50:56     INFO - async*testWorkerMessage@chrome://mochitests/content/browser/devtools/client/webconsole/test/browser/browser_webconsole_console_logging_workers_api.js:108:9
[task 2023-11-21T05:50:56.273Z] 05:50:56     INFO - async*@chrome://mochitests/content/browser/devtools/client/webconsole/test/browser/browser_webconsole_console_logging_workers_api.js:25:9
[task 2023-11-21T05:50:56.273Z] 05:50:56     INFO - async*handleTask@chrome://mochikit/content/browser-test.js:1138:26
[task 2023-11-21T05:50:56.273Z] 05:50:56     INFO - _runTaskBasedTest@chrome://mochikit/content/browser-test.js:1210:18
[task 2023-11-21T05:50:56.273Z] 05:50:56     INFO - Tester_execTest@chrome://mochikit/content/browser-test.js:1352:14
[task 2023-11-21T05:50:56.273Z] 05:50:56     INFO - nextTest/<@chrome://mochikit/content/browser-test.js:1127:14
[task 2023-11-21T05:50:56.273Z] 05:50:56     INFO - SimpleTest.waitForFocus/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:1058:13
[task 2023-11-21T05:50:56.274Z] 05:50:56     INFO - Leaving test bound 
[task 2023-11-21T05:50:56.274Z] 05:50:56     INFO - GECKO(5805) | [Parent 5805, Main Thread] WARNING: NS_ENSURE_TRUE(mPresShell) failed: file /builds/worker/checkouts/gecko/layout/generic/nsFrameSelection.cpp:1710
[task 2023-11-21T05:50:57.043Z] 05:50:57     INFO - Removing tab.
[task 2023-11-21T05:50:57.043Z] 05:50:57     INFO - Waiting for event: 'TabClose' on [object XULElement].
[task 2023-11-21T05:50:57.064Z] 05:50:57     INFO - Got event: 'TabClose' on [object XULElement].
[task 2023-11-21T05:50:57.068Z] 05:50:57     INFO - GECKO(5805) | console.warn: "IGNORED REDUX ACTION:" "AUTOCOMPLETE_CLEAR"
[task 2023-11-21T05:50:57.078Z] 05:50:57     INFO - GECKO(5805) | [Parent 5805, Main Thread] WARNING: '!inner', file /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSWindowActorProtocol.cpp:163
[task 2023-11-21T05:50:57.079Z] 05:50:57     INFO - GECKO(5805) | [Parent 5805, Main Thread] WARNING: '!inner', file /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSWindowActorProtocol.cpp:163
[task 2023-11-21T05:50:57.084Z] 05:50:57     INFO - Tab removed and finished closing
[task 2023-11-21T05:50:57.099Z] 05:50:57     INFO - GECKO(5805) | JavaScript error: , line 0: NotFoundError: No such JSWindowActor 'DevToolsFrame'
[task 2023-11-21T05:50:57.112Z] 05:50:57     INFO - Console message: [JavaScript Error: "NotFoundError: No such JSWindowActor 'DevToolsFrame'"]
[task 2023-11-21T05:50:57.116Z] 05:50:57     INFO - TEST-PASS | devtools/client/webconsole/test/browser/browser_webconsole_console_logging_workers_api.js | The main process DevToolsServer has no pending connection when the test ends -
Flags: needinfo?(nchevobbe)
Flags: needinfo?(nchevobbe)
Pushed by csabou@mozilla.com: https://hg.mozilla.org/integration/autoland/rev/c92f964f2792 Disable browser_webconsole_console_logging_workers_api.js on linux and apple_catalina debug for frequent failures. r=jmaher
Whiteboard: [stockwell disable-recommended] → [stockwell disabled]

Test was disabled

Flags: needinfo?(nchevobbe)

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit BugBot documentation.

Status: NEW → RESOLVED
Closed: 1 year ago
Resolution: --- → INCOMPLETE

New failure instance: https://treeherder.mozilla.org/logviewer?job_id=481158230&repo=mozilla-esr115

Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit BugBot documentation.

Status: REOPENED → RESOLVED
Closed: 1 year ago → 10 months ago
Resolution: --- → INCOMPLETE

New failure instance: https://treeherder.mozilla.org/logviewer?job_id=489654197&repo=mozilla-esr115

Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit BugBot documentation.

Status: REOPENED → RESOLVED
Closed: 10 months ago → 7 months ago
Resolution: --- → INCOMPLETE

New failure instance: https://treeherder.mozilla.org/logviewer?job_id=501170793&repo=mozilla-esr115

Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---

Nicolas, it seems that in this test nothing happens when we click on the "clear" button here https://searchfox.org/mozilla-central/rev/08b2a1a770688df19a5a43fd89fb63b34bb2d6a6/devtools/client/webconsole/test/browser/browser_webconsole_console_logging_workers_api.js#131-140

info("Click on the clear button and wait for messages to be removed");
const onMessagesCacheCleared = hud.ui.once("messages-cache-cleared");
hud.ui.window.document.querySelector(".devtools-clear-icon").click();
await waitFor(
  () =>
    !findConsoleAPIMessage(hud, "initial-message-from-worker") &&
    !findConsoleAPIMessage(hud, "log-from-worker")
);
await onMessagesCacheCleared;
ok(true, "Messages were removed");

In the failure screenshot, all messages are still displayed.

I did a naive change to wait 1s to wait before clicking on the clear button and it seems to fix the issue on Linux debug:

Any idea of some event we might have to wait for before clicking?

Flags: needinfo?(nchevobbe)

(In reply to Julian Descottes [:jdescottes] from comment #136)

Nicolas, it seems that in this test nothing happens when we click on the "clear" button here https://searchfox.org/mozilla-central/rev/08b2a1a770688df19a5a43fd89fb63b34bb2d6a6/devtools/client/webconsole/test/browser/browser_webconsole_console_logging_workers_api.js#131-140

info("Click on the clear button and wait for messages to be removed");
const onMessagesCacheCleared = hud.ui.once("messages-cache-cleared");
hud.ui.window.document.querySelector(".devtools-clear-icon").click();
await waitFor(
  () =>
    !findConsoleAPIMessage(hud, "initial-message-from-worker") &&
    !findConsoleAPIMessage(hud, "log-from-worker")
);
await onMessagesCacheCleared;
ok(true, "Messages were removed");

In the failure screenshot, all messages are still displayed.

I did a naive change to wait 1s to wait before clicking on the clear button and it seems to fix the issue on Linux debug:

Any idea of some event we might have to wait for before clicking?

not really, I'm not sure what's happening here.
there are also other failures (e.g. https://treeherder.mozilla.org/logviewer?job_id=504244412&repo=try&lineNumber=10077) , where it seems like the console is cleared, but the cache isn't as we can see those messages when restarting the toolbox.

The logs don't really show any error or warnings that would explain that, so I'm a bit clueless, I'll look into this

Flags: needinfo?(nchevobbe)

findConsoleAPIMessage is based on findMessagesByType, which looks for the matching string in the whole message, which includes the location https://searchfox.org/mozilla-central/rev/8867630d67bfe76f6065df08d60381d45d73c439/devtools/client/webconsole/test/browser/shared-head.js#397,405-411

function findMessagesByType(hud, text, typeSelector) {
...
  const selector = ".message" + typeSelector;
  const messages = hud.ui.outputNode.querySelectorAll(selector);
  const elements = Array.from(messages).filter(el =>
    el.textContent.includes(text)
  );
  return elements;
}

the test uses a data url worker https://searchfox.org/mozilla-central/rev/8867630d67bfe76f6065df08d60381d45d73c439/devtools/client/webconsole/test/browser/test-console-workers.html#14-15

const worker = new Worker(`data:application/javascript,
  console.log("initial-message-from-worker", {foo: "bar"}, globalThis);

which means the initial-message-from-worker will be included in the location, which can break some assumptions in the test

I moved the data url worker to a proper file to avoid such thing; I'm still waiting for more TV results, but it seems promising so far: https://treeherder.mozilla.org/jobs?repo=try&revision=943a3e23ff2d0bcf601669185f121adeac81696b

EDIT: the test is still failing, so this isn't enough https://treeherder.mozilla.org/jobs?repo=try&revision=943a3e23ff2d0bcf601669185f121adeac81696b&selectedTaskRun=E_rfsz-wRuqycondSt1sHg.0

Because the test was using a data url worker, in the test we were matching some
assertions not on the message body, but on the message location, which means we
weren't properly checking what we wanted, and possibly were triggering some actions
to early/late.

This patch migrates the worker content to an existing worker file that we then
use in the support file, so we don't match on the message location anymore.

Assignee: nobody → nchevobbe
Pushed by nchevobbe@mozilla.com: https://hg.mozilla.org/integration/autoland/rev/48f40502dd07 [devtools Fix browser_webconsole_console_logging_workers_api.js intermittent. r=devtools-reviewers,bomsy.

https://hg.mozilla.org/mozilla-central/rev/48f40502dd07

Status: REOPENED → RESOLVED
Closed: 7 months ago → 6 months ago
status-firefox139: --- → fixed
Resolution: --- → FIXED
Target Milestone: --- → 139 Branch
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: