1777948 - Messages logged from web worker do not show

Status: NEW

(WebExtensions :: Developer Tools, defect, P3)

Description

[Teal Dulcet [:tdulcet] (TB Council)]

Attachment: image.png

Messages logged to the console from web workers created from a web extension background page do not show most of the time. When they do show, any arrays have only "empty slots" and console.time* messages show up as undefined: NaNms. Clicking to the "Debugger" tab and then back to the "Console" tab does seem improve the odds of the messages showing. Sometimes they only appear after a long delay. If you reload the about:devtools-toolbox page, they will disappear again. There also can be some difficulty getting messages from a web extension popup to show, but it is much less severe.

I am not sure if it is related to bug 1215120 or bug 1674342, but this only seems to affect workers created from a web extension. I tested in Firefox 91 ESR, Firefox 102 and Nightly 104. In 91 ESR, I was unable to get them to show at all.

Comment 1

[Luca Greco [:rpl] [:luca] [:lgreco]]

Hi Nicholas,
so you have some idea about what may trigger the issue as described in comment 0?

Comment 2

[Nicolas Chevobbe [:nchevobbe]]

tdlucet, could you give some code example of what kind of object you are trying to log?
It would be even better if you could share a small webextension highlighting the issue so we can have a proper look

At the moment, we are doing our best to clone messages from the worker thread to the main thread, and we might not succeed for specific type of data. The console.time one might have a dedicated bug so we can investigate and fix it.

tdlucet, can you try to go to about:config and set dom.worker.console.dispatch_events_to_main_thread to false (you might reload DevTools and the page then) ? In such case, we won't do the cloning anymore and you should see the messages. If that's not the case, let me know.

Comment 3

[Teal Dulcet [:tdulcet] (TB Council)]

Attachment: image.png

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

tdlucet, could you give some code example of what kind of object you are trying to log?

Thanks for the quick response. Here is some example/test code:

const label = "test";
console.time(label);

console.log(undefined);
console.log(null);
console.log(true, false);
console.log(1234);
console.log(Number.MIN_SAFE_INTEGER, Number.MAX_SAFE_INTEGER);
console.log(-Infinity, +Infinity, NaN);
console.log(1234n);
console.log("abc");
console.log(/abc/);
console.log({a: 1, b: 2, c: 3});
console.log([1, 2, 3]);
console.log(new Date());
console.log(new Set([1, 2, 3]));
console.log(new Map(Object.entries({a: 1, b: 2, c: 3})));

console.timeEnd(label);

Running this is a web worker created from a background script results in the output in the attached screenshot. As you can see, the array and console.time* messages do not work. I can provide an example extension if needed. However, the main issue is that the messages just do not show most of the time, which combined with several other DevTools bugs makes debugging web extensions very difficult.

tdlucet, can you try to go to about:config and set dom.worker.console.dispatch_events_to_main_thread to false (you might reload DevTools and the page then) ? In such case, we won't do the cloning anymore and you should see the messages. If that's not the case, let me know.

Yes, with this change the messages do now seem to show all of the time. However, the array and console.time* messages still do not work.

Comment 4

[Alex Cornestean]

Hello,

I’m from Webextensions QA and I’m attempting to reproduce the issue in order to confirm it, but I would require the example extension you mentioned in Comment 3 in order to do so, if it’s not much of a hassle.

Thank you !

Comment 5

[Teal Dulcet [:tdulcet] (TB Council)]

Attachment: worker.zip

Here is a minimal example extension to reproduce the issue.

Comment 6

[Alex Cornestean]

Thank you for the example extension !

I tried to reproduce the issue on the latest Nightly (104.0a1/20220705212856), Beta (103.0b4/20220703190044) and Release (102.0/20220623063721) under Windows 10 x64 and Ubuntu 16.04 LTS, but at least on my end, all console output logged by the extension is properly displayed and shows all the time.

I’ve added/removed and reloaded both the packed .xpi and the manifest.json file several times and there were no issues. Note that I did not change any prefs and used new profiles.

For more details, see the attached screenshot. The screenshot depicts the console output from Nightly, but the same results were obtained across all tested browsers.

Comment 7

[Alex Cornestean]

Attachment: Nightly output.png

Comment 8

[Teal Dulcet [:tdulcet] (TB Council)]

(In reply to Alex Cornestean from comment #6)

I tried to reproduce the issue on the latest Nightly (104.0a1/20220705212856), Beta (103.0b4/20220703190044) and Release (102.0/20220623063721) under Windows 10 x64 and Ubuntu 16.04 LTS, but at least on my end, all console output logged by the extension is properly displayed and shows all the time.

Hmm, I just tested it again and was able to reproduce both issues with my example extension in the latest Firefox 102 and Nightly 104. I did not modify any preferences either.

Note that my screenshot was from the Extension console, not the Browser console, so you would need to click that "Inspect" button on the about:debugging page where you loaded the extension. I never see any output from the worker in the Browser console (just a lot of errors).

Comment 9

[Alex Cornestean]

Indeed I can confirm that the issue occurs when viewing the output in the extension console. The output is also displayed with varying degrees of delay.
Tested on the latest Nightly (104.0a1/20220705212856), Beta (103.0b4/20220703190044) and Release (102.0/20220623063721).

See the attached screenshot.

Comment 10

[Alex Cornestean]

Attachment: 2022-07-06_14h41_47.png

Comment 11

[BugBot [:suhaib / :marco/ :calixte]]

The severity field is not set for this bug.
:mixedpuppy, could you have a look please?

For more information, please visit auto_nag documentation.

Comment 12

[Luca Greco [:rpl] [:luca] [:lgreco]]

HI Nicolas,
are the details provided by the reporter in comment 3 useful to get a better picture of what would be the underlying issue and next steps for this bug?

Comment 13

[Nicolas Chevobbe [:nchevobbe]]

Yes, this is useful.
Hopefully I'll have some time to work on Bug 1674342 during this summer.

Comment 14

[Luca Greco [:rpl] [:luca] [:lgreco]]

Setting as P3 / S4 for now, also linked as a see also to Bug 1573659 (as a reminder that if we are about to enable background service workers we may consider bumping the priority of this bug, if still open).