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

[task 2022-04-14T02:19:50.658Z] 02:19:50     INFO - TEST-START | devtools/client/webconsole/test/browser/browser_console_microtask.js
[task 2022-04-14T02:19:50.895Z] 02:19:50     INFO - GECKO(3940) | [Parent 3940: Main Thread]: I/DocShellAndDOMWindowLeak ++DOCSHELL 7efcf5452800 == 11 [pid = 3940] [id = 10]
[task 2022-04-14T02:19:50.897Z] 02:19:50     INFO - GECKO(3940) | [Parent 3940: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 21 (7efcff4426f0) [pid = 3940] [serial = 23] [outer = 0]
[task 2022-04-14T02:19:50.899Z] 02:19:50     INFO - GECKO(3940) | [Parent 3940: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 22 (7efcf89a3000) [pid = 3940] [serial = 24] [outer = 7efcff4426f0]
[task 2022-04-14T02:19:50.924Z] 02:19:50     INFO - GECKO(3940) | [Parent 3940, Main Thread] WARNING: NS_ENSURE_TRUE(rootFrame) failed: file /builds/worker/checkouts/gecko/dom/base/nsGlobalWindowOuter.cpp:4147
[task 2022-04-14T02:19:50.938Z] 02:19:50     INFO - GECKO(3940) | [Parent 3940, Main Thread] WARNING: Failed to retarget HTML data delivery to the parser thread.: file /builds/worker/checkouts/gecko/parser/html/nsHtml5StreamParser.cpp:1198
[task 2022-04-14T02:19:51.133Z] 02:19:51     INFO - GECKO(3940) | [GLX] window 22000bf has VisualID 0x41
[task 2022-04-14T02:19:51.141Z] 02:19:51     INFO - GECKO(3940) | [Parent 3940, Renderer] WARNING: robust_buffer_access_behavior marked as unsupported: file /builds/worker/checkouts/gecko/gfx/gl/GLContextFeatures.cpp:632
[task 2022-04-14T02:19:51.141Z] 02:19:51     INFO - GECKO(3940) | [Parent 3940, Renderer] WARNING: Robustness supported, strategy is not LOSE_CONTEXT_ON_RESET!: file /builds/worker/checkouts/gecko/gfx/gl/GLContext.cpp:999
[task 2022-04-14T02:19:51.142Z] 02:19:51     INFO - GECKO(3940) | [Parent 3940, Renderer] WARNING: robustness marked as unsupported: file /builds/worker/checkouts/gecko/gfx/gl/GLContextFeatures.cpp:632
[task 2022-04-14T02:19:51.144Z] 02:19:51     INFO - GECKO(3940) | [2022-04-14T02:19:51Z WARN  webrender::device::gl] Missing optimized shader source for gpu_cache_update
[task 2022-04-14T02:19:51.483Z] 02:19:51     INFO - GECKO(3940) | [Parent 3940: Main Thread]: I/DocShellAndDOMWindowLeak --DOCSHELL 7efcff335800 == 10 [pid = 3940] [id = 5] [url = chrome://devtools/content/webconsole/index.html]
[task 2022-04-14T02:19:51.485Z] 02:19:51     INFO - GECKO(3940) | [Parent 3940: Main Thread]: I/DocShellAndDOMWindowLeak --DOCSHELL 7efcf5448c00 == 9 [pid = 3940] [id = 7] [url = chrome://devtools/content/webconsole/index.html]
[task 2022-04-14T02:19:51.487Z] 02:19:51     INFO - GECKO(3940) | [Parent 3940: Main Thread]: I/DocShellAndDOMWindowLeak --DOCSHELL 7efcf5447800 == 8 [pid = 3940] [id = 6] [url = chrome://devtools/content/webconsole/index.html]
[task 2022-04-14T02:19:51.507Z] 02:19:51     INFO - GECKO(3940) | [Parent 3940: Main Thread]: I/DocShellAndDOMWindowLeak --DOCSHELL 7efcf544f800 == 7 [pid = 3940] [id = 8] [url = chrome://devtools/content/webconsole/index.html]
[task 2022-04-14T02:19:51.629Z] 02:19:51     INFO - GECKO(3940) | [2022-04-14T02:19:51Z WARN  webrender::device::gl] Cropping texture upload Box2D((0, 0), (0, 1)) to None
[task 2022-04-14T02:19:51.630Z] 02:19:51     INFO - GECKO(3940) | [2022-04-14T02:19:51Z WARN  webrender::device::gl] Cropping texture upload Box2D((0, 0), (0, 1)) to None
[task 2022-04-14T02:19:51.816Z] 02:19:51     INFO - GECKO(3940) | [2022-04-14T02:19:51Z WARN  webrender::device::gl] Attribute VertexAttribute { name: "aUvRect1", count: 4, kind: F32 } is not found in the shader composite. Expected at 6, found at -1
[task 2022-04-14T02:19:51.817Z] 02:19:51     INFO - GECKO(3940) | [2022-04-14T02:19:51Z WARN  webrender::device::gl] Attribute VertexAttribute { name: "aUvRect2", count: 4, kind: F32 } is not found in the shader composite. Expected at 7, found at -1
[task 2022-04-14T02:19:51.831Z] 02:19:51     INFO - GECKO(3940) | [2022-04-14T02:19:51Z WARN  webrender::device::gl] Attribute VertexAttribute { name: "aColor", count: 4, kind: F32 } is not found in the shader composite. Expected at 3, found at -1
[task 2022-04-14T02:19:51.833Z] 02:19:51     INFO - GECKO(3940) | [2022-04-14T02:19:51Z WARN  webrender::device::gl] Attribute VertexAttribute { name: "aUvRect1", count: 4, kind: F32 } is not found in the shader composite. Expected at 6, found at -1
[task 2022-04-14T02:19:51.834Z] 02:19:51     INFO - GECKO(3940) | [2022-04-14T02:19:51Z WARN  webrender::device::gl] Attribute VertexAttribute { name: "aUvRect2", count: 4, kind: F32 } is not found in the shader composite. Expected at 7, found at -1
[task 2022-04-14T02:19:52.095Z] 02:19:52     INFO - GECKO(3940) | [2022-04-14T02:19:52Z WARN  webrender::device::gl] Cropping texture upload Box2D((0, 0), (0, 1)) to None
[task 2022-04-14T02:19:52.097Z] 02:19:52     INFO - GECKO(3940) | [2022-04-14T02:19:52Z WARN  webrender::device::gl] Cropping texture upload Box2D((0, 0), (0, 1)) to None
[task 2022-04-14T02:19:52.098Z] 02:19:52     INFO - GECKO(3940) | [2022-04-14T02:19:52Z WARN  webrender::device::gl] Cropping texture upload Box2D((0, 0), (0, 1)) to None
[task 2022-04-14T02:19:52.364Z] 02:19:52     INFO - GECKO(3940) | console.error: "Error when attaching target:" (new Error("closed from: server6.conn0.workerDescriptor25", "resource://devtools/shared/protocol/Front.js", 365))
[task 2022-04-14T02:19:52.904Z] 02:19:52     INFO - GECKO(3940) | [2022-04-14T02:19:52Z WARN  webrender::device::gl] Attribute VertexAttribute { name: "aClipRect_TL", count: 4, kind: F32 } is not found in the shader cs_clip_rectangle. Expected at 8, found at -1
[task 2022-04-14T02:19:52.904Z] 02:19:52     INFO - GECKO(3940) | [2022-04-14T02:19:52Z WARN  webrender::device::gl] Attribute VertexAttribute { name: "aClipRect_TR", count: 4, kind: F32 } is not found in the shader cs_clip_rectangle. Expected at 10, found at -1
[task 2022-04-14T02:19:52.906Z] 02:19:52     INFO - GECKO(3940) | [2022-04-14T02:19:52Z WARN  webrender::device::gl] Attribute VertexAttribute { name: "aClipRadii_TR", count: 4, kind: F32 } is not found in the shader cs_clip_rectangle. Expected at 11, found at -1
[task 2022-04-14T02:19:52.907Z] 02:19:52     INFO - GECKO(3940) | [2022-04-14T02:19:52Z WARN  webrender::device::gl] Attribute VertexAttribute { name: "aClipRect_BL", count: 4, kind: F32 } is not found in the shader cs_clip_rectangle. Expected at 12, found at -1
[task 2022-04-14T02:19:52.908Z] 02:19:52     INFO - GECKO(3940) | [2022-04-14T02:19:52Z WARN  webrender::device::gl] Attribute VertexAttribute { name: "aClipRadii_BL", count: 4, kind: F32 } is not found in the shader cs_clip_rectangle. Expected at 13, found at -1
[task 2022-04-14T02:19:52.909Z] 02:19:52     INFO - GECKO(3940) | [2022-04-14T02:19:52Z WARN  webrender::device::gl] Attribute VertexAttribute { name: "aClipRect_BR", count: 4, kind: F32 } is not found in the shader cs_clip_rectangle. Expected at 14, found at -1
[task 2022-04-14T02:19:52.910Z] 02:19:52     INFO - GECKO(3940) | [2022-04-14T02:19:52Z WARN  webrender::device::gl] Attribute VertexAttribute { name: "aClipRadii_BR", count: 4, kind: F32 } is not found in the shader cs_clip_rectangle. Expected at 15, found at -1
[task 2022-04-14T02:19:53.722Z] 02:19:53     INFO - GECKO(3940) | [Child 4109: Main Thread]: I/DocShellAndDOMWindowLeak --DOCSHELL 7fcac247e000 == 0 [pid = 4109] [id = 2] [url = about:blank]
[task 2022-04-14T02:19:54.215Z] 02:19:54     INFO - GECKO(3940) | [Child 4029: Main Thread]: I/DocShellAndDOMWindowLeak --DOCSHELL 7f851600f400 == 1 [pid = 4029] [id = 2] [url = about:blank]
[task 2022-04-14T02:19:54.249Z] 02:19:54     INFO - GECKO(3940) | console.log: #0: before createXULElement
[task 2022-04-14T02:19:54.265Z] 02:19:54     INFO - GECKO(3940) | console.log: #1: after createXULElement
[task 2022-04-14T02:19:54.271Z] 02:19:54     INFO - GECKO(3940) | console.log: #2: in microtask
[task 2022-04-14T02:19:54.310Z] 02:19:54     INFO - GECKO(3940) | [Child 4109: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 2 (7fcac247c400) [pid = 4109] [serial = 4] [outer = 0] [url = about:blank]
[task 2022-04-14T02:19:54.312Z] 02:19:54     INFO - GECKO(3940) | [Child 4109: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 1 (7fcad8196300) [pid = 4109] [serial = 5] [outer = 0] [url = about:blank]
[task 2022-04-14T02:19:54.654Z] 02:19:54     INFO - GECKO(3940) | [Child 4029: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 5 (7f8530f95bc0) [pid = 4029] [serial = 5] [outer = 0] [url = about:blank]
[task 2022-04-14T02:19:54.655Z] 02:19:54     INFO - GECKO(3940) | [Child 4029: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 4 (7f8530f96300) [pid = 4029] [serial = 7] [outer = 0] [url = about:blank]
[task 2022-04-14T02:19:55.607Z] 02:19:55     INFO - TEST-INFO | started process screentopng
[task 2022-04-14T02:19:55.824Z] 02:19:55     INFO - TEST-INFO | screentopng: exit 0
[task 2022-04-14T02:19:55.825Z] 02:19:55     INFO - Buffered messages logged at 02:19:50
[task 2022-04-14T02:19:55.825Z] 02:19:55     INFO - Entering test bound 
[task 2022-04-14T02:19:55.826Z] 02:19:55     INFO - Buffered messages logged at 02:19:52
[task 2022-04-14T02:19:55.826Z] 02:19:55     INFO - Console message: [JavaScript Warning: "The Web Console logging API (console.log, console.info, console.warn, console.error) has been disabled by a script on this page."]
[task 2022-04-14T02:19:55.827Z] 02:19:55     INFO - Buffered messages logged at 02:19:55
[task 2022-04-14T02:19:55.828Z] 02:19:55     INFO - TEST-PASS | devtools/client/webconsole/test/browser/browser_console_microtask.js | before createXULElement log is displayed first - 
[task 2022-04-14T02:19:55.829Z] 02:19:55     INFO - TEST-PASS | devtools/client/webconsole/test/browser/browser_console_microtask.js | after createXULElement log is displayed second - 
[task 2022-04-14T02:19:55.830Z] 02:19:55     INFO - Buffered messages finished
[task 2022-04-14T02:19:55.832Z] 02:19:55     INFO - TEST-UNEXPECTED-FAIL | devtools/client/webconsole/test/browser/browser_console_microtask.js | Uncaught exception in test - at chrome://mochitests/content/browser/devtools/client/webconsole/test/browser/browser_console_microtask.js:49 - TypeError: can't access property 1, text.match(...) is null
[task 2022-04-14T02:19:55.832Z] 02:19:55     INFO - Stack trace:
[task 2022-04-14T02:19:55.832Z] 02:19:55     INFO - getMessageIndex@chrome://mochitests/content/browser/devtools/client/webconsole/test/browser/browser_console_microtask.js:49:17
[task 2022-04-14T02:19:55.833Z] 02:19:55     INFO - @chrome://mochitests/content/browser/devtools/client/webconsole/test/browser/browser_console_microtask.js:62:6
[task 2022-04-14T02:19:55.833Z] 02:19:55     INFO - Async*handleTask@chrome://mochikit/content/browser-test.js:989:26
[task 2022-04-14T02:19:55.834Z] 02:19:55     INFO - _runTaskBasedTest@chrome://mochikit/content/browser-test.js:1061:18
[task 2022-04-14T02:19:55.834Z] 02:19:55     INFO - Tester_execTest@chrome://mochikit/content/browser-test.js:1189:14
[task 2022-04-14T02:19:55.835Z] 02:19:55     INFO - nextTest/<@chrome://mochikit/content/browser-test.js:972:14
[task 2022-04-14T02:19:55.836Z] 02:19:55     INFO - SimpleTest.waitForFocus/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:1041:13
[task 2022-04-14T02:19:55.837Z] 02:19:55     INFO - Leaving test bound 
[task 2022-04-14T02:19:55.838Z] 02:19:55     INFO - Clear the browser console output
[task 2022-04-14T02:19:55.839Z] 02:19:55     INFO - Browser console cleared
[task 2022-04-14T02:19:55.841Z] 02:19:55     INFO - Wait for all Browser Console targets to be attached
[task 2022-04-14T02:19:55.842Z] 02:19:55     INFO - Waiting 1 seconds.
[task 2022-04-14T02:19:55.842Z] 02:19:55     INFO - Close the Browser Console
[task 2022-04-14T02:19:55.843Z] 02:19:55     INFO - GECKO(3940) | console.warn: "IGNORED REDUX ACTION:" "MESSAGES_ADD"
[task 2022-04-14T02:19:55.876Z] 02:19:55     INFO - GECKO(3940) | JavaScript error: , line 0: NotFoundError: No such JSWindowActor 'DevToolsFrame'
[task 2022-04-14T02:19:55.878Z] 02:19:55     INFO - GECKO(3940) | JavaScript error: , line 0: NotFoundError: No such JSWindowActor 'DevToolsFrame'
[task 2022-04-14T02:19:55.880Z] 02:19:55     INFO - GECKO(3940) | JavaScript error: , line 0: NotFoundError: No such JSWindowActor 'DevToolsFrame'
[task 2022-04-14T02:19:55.887Z] 02:19:55     INFO - GECKO(3940) | JavaScript error: , line 0: NotFoundError: No such JSWindowActor 'DevToolsFrame'
[task 2022-04-14T02:19:55.889Z] 02:19:55     INFO - GECKO(3940) | JavaScript error: , line 0: NotFoundError: No such JSWindowActor 'DevToolsFrame'
[task 2022-04-14T02:19:55.890Z] 02:19:55     INFO - GECKO(3940) | JavaScript error: , line 0: NotFoundError: No such JSWindowActor 'DevToolsFrame'
[task 2022-04-14T02:19:55.919Z] 02:19:55     INFO - Browser Console closed
[task 2022-04-14T02:19:55.921Z] 02:19:55     INFO - Console message: [JavaScript Error: "NotFoundError: No such JSWindowActor 'DevToolsFrame'"]
[task 2022-04-14T02:19:55.923Z] 02:19:55     INFO - Console message: [JavaScript Error: "NotFoundError: No such JSWindowActor 'DevToolsFrame'"]
[task 2022-04-14T02:19:55.923Z] 02:19:55     INFO - Console message: [JavaScript Error: "NotFoundError: No such JSWindowActor 'DevToolsFrame'"]
[task 2022-04-14T02:19:55.925Z] 02:19:55     INFO - Console message: [JavaScript Error: "NotFoundError: No such JSWindowActor 'DevToolsFrame'"]
[task 2022-04-14T02:19:55.926Z] 02:19:55     INFO - Console message: [JavaScript Error: "NotFoundError: No such JSWindowActor 'DevToolsFrame'"]
[task 2022-04-14T02:19:55.927Z] 02:19:55     INFO - Console message: [JavaScript Error: "NotFoundError: No such JSWindowActor 'DevToolsFrame'"]
[task 2022-04-14T02:19:55.930Z] 02:19:55     INFO - GECKO(3940) | console.warn: "IGNORED REDUX ACTION:" "AUTOCOMPLETE_CLEAR"
[task 2022-04-14T02:19:55.948Z] 02:19:55     INFO - GECKO(3940) | [Parent 3940, Compositor] WARNING: Possibly dropping task posted to updater thread: file /builds/worker/checkouts/gecko/gfx/layers/apz/src/APZUpdater.cpp:365
[task 2022-04-14T02:19:55.963Z] 02:19:55     INFO - TEST-PASS | devtools/client/webconsole/test/browser/browser_console_microtask.js | The main process DevToolsServer has no pending connection when the test ends - 

Could you please have a look arai?

So far it doesn't reproduce locally in verify mode, on macOS.
I will continue investigating.

The log shows the following:

[task 2022-04-14T06:11:39.214Z] 06:11:39     INFO - GECKO(3957) | console.log: #0: before createXULElement
[task 2022-04-14T06:11:39.224Z] 06:11:39     INFO - GECKO(3957) | console.log: #1: after createXULElement
[task 2022-04-14T06:11:39.229Z] 06:11:39     INFO - GECKO(3957) | console.log: #2: in microtask

So, as long as inMicroTask holds the DOM node for the 3rd log, and the node is unchanged, the code should work.

The error can happen if the text content of the message node is changed from "#2: in microtask" to something else.

Perhaps the content of the node can be removed/modified in some case?
for example when the message goes outside of visible area, or some other event?

:nchevobbe, can I have your opinion?
can https://groups.google.com/g/firefox-dev/c/4xw3LgoROzk affect it?

(In reply to Tooru Fujisawa [:arai] from comment #3)

Perhaps the content of the node can be removed/modified in some case?
for example when the message goes outside of visible area, or some other event?
:nchevobbe, can I have your opinion?
can https://groups.google.com/g/firefox-dev/c/4xw3LgoROzk affect it?

The node can be removed indeed because of virtualization, but in the test, you would still have the node reference (but the node wouldn't be connected anymore).
The findMessage helper should take care of managing the virtualization.

I wonder if we don't retrieve the evaluation message instead of the log, which would explain text.match(...) is null , as we don't have #2 in it.

Could you try passing ".message.log" as findMessage 3rd parameter ?

passing the parameter didn't solve.
https://treeherder.mozilla.org/jobs?repo=try&selectedTaskRun=bYSE3kFCTPiHHOi8GPYl4A.0&revision=4f422b033bbeb3faee94a231898e798d95738999

But yeah, findMessage returns the console input instead of the console.log output.
https://treeherder.mozilla.org/logviewer?job_id=374467832&repo=try&lineNumber=2804

the textContent returns the input value, that also contains the console log message inside it.

(In reply to Tooru Fujisawa [:arai] from comment #5)

passing the parameter didn't solve.
https://treeherder.mozilla.org/jobs?repo=try&selectedTaskRun=bYSE3kFCTPiHHOi8GPYl4A.0&revision=4f422b033bbeb3faee94a231898e798d95738999

But yeah, findMessage returns the console input instead of the console.log output.
https://treeherder.mozilla.org/logviewer?job_id=374467832&repo=try&lineNumber=2804

the textContent returns the input value, that also contains the console log message inside it.

ah shoot, the evaluation message has the log class. I guess .message.log:not(.command) might be better?

Yeah, I've confirmed that filtering by command works.
Then, while auditing other findMessage consumer, I found the following example:

https://searchfox.org/mozilla-central/rev/d34f9713ae128a3138c2b70d8041a535f1049d19/devtools/client/aboutdebugging/test/browser/browser_aboutdebugging_addons_debug_console.js#237

    return findMessages(hud, "message after reload", ".console-api").length > 0;

That looks more specific for console.log output.

Set release status flags based on info from the regressing bug 1761590

https://hg.mozilla.org/mozilla-central/rev/63b7ec0edfae