Closed Bug 1722205 Opened 3 years ago Closed 2 years ago

Output to JS console stops working

Categories

(Core :: JavaScript Engine, defect, P2)

defect

Tracking

()

RESOLVED INACTIVE

People

(Reporter: baj, Unassigned)

References

(Blocks 1 open bug)

Details

User Agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10.15; rv:90.0) Gecko/20100101 Firefox/90.0

Steps to reproduce:

I'm working on an app that uses wgpu library with wasm, and I've been testing it using Firefox Nightly since that has some webgpu support. I've noticed that debug output that's routed to the JavaScript console stops being displayed after varying amounts of time, but usually only a few seconds after the app starts. The app itself continues to work, and is still executing the routines that should be generating log entries.

I made a reproducible test case that boils down to the following:

fn start() {
    log::info!("in start()");
    loop {
        log::info!("in the loop");
    };
}

#[cfg(target_arch = "wasm32")]
fn main() {
    console_log::init().expect("could not initialize logger");
    start();
}

When I run it on Firefox Nightly (92.0a1, 2021-07-23), many times it doesn't even emit any messages at all. When it does, though, it looks like this:

in start()                    console.js:97:17
in the loop   (11924 repeats) console.js:97:17

where the value (11924) varies from run to run, but it eventually stops at some number.

Someone suggested that this might be due to the infinite loop causing a thread to overwhelm the browser, but an earlier version of start() which didn't actually spin also showed the problem:

fn start() {
    let event_loop = winit::event_loop::EventLoop::new();
    event_loop.run(move |_, _, _| {
        log::info!("in the loop");
    });
}

Moreover, I was able to reproduce this with a small JS program:

function sleep(ms) {
  return new Promise(resolve => setTimeout(resolve, ms));
}

async function loop() {
  for (let i = 0; ; i++) {
    console.warn("in loop " + i);
    if (i % 100 === 0) {
      await sleep(10);
    }
  }
}

console.warn("starting");
loop();

The first three times I ran this, it stopped after 22900, 64600, and 21800 iterations. In contrast, if I run it on a released version of Firefox (90.0.1), it ran for more than a million iterations before I manually stopped it.

Note that I don't believe this is an issue with the console being overwhelmed with messages - with my initial app, it would stop displaying after only 10-20 messages.

This is on MacOS 11.4.

Actual results:

Output to the console stops being displayed, even though it's still being generated. (see above)

Expected results:

Output to the console should continue to be displayed.

The Bugbug bot thinks this bug should belong to the 'Core::Javascript: WebAssembly' component, and is moving the bug to that component. Please revert this change in case you think the bot is wrong.

Component: Untriaged → Javascript: WebAssembly
Product: Firefox → Core

Looks like a core JS problem, not really wasm related, cf pure-JS test case in comment 0.

Component: Javascript: WebAssembly → JavaScript Engine
Severity: -- → S3
Priority: -- → P3

I'd make a bid for this being higher than S3; it essentially prevents me from getting debugging output from my wasm-based app after the first few seconds of its runtime, and I don't have good alternatives.

Also, it seems like this may be a regression, given that it doesn't seem to be a problem in FF 90.0.1.

Hey arai, do you know what could have caused this regression?

Severity: S3 → S2
Flags: needinfo?(arai.unmht)
Priority: P3 → P2
Flags: needinfo?(arai.unmht)
Flags: needinfo?(arai.unmht)
Severity: S2 → S3

Tested the "small JS" testcase, but I don't observe the difference between 88, 89, 90, 91b, 92a, with clean profile, on macOS 10.15.7.
So it would be more environment-dependent issue.

Can you use mozregression to figure out what caused the regression?
https://mozilla.github.io/mozregression/

Flags: needinfo?(arai.unmht) → needinfo?(baj)

Redirect a needinfo that is pending on an inactive user to the triage owner.
:sdetar, since the bug has high priority, could you have a look please?

For more information, please visit auto_nag documentation.

Flags: needinfo?(baj) → needinfo?(sdetar)
Status: UNCONFIRMED → RESOLVED
Closed: 2 years ago
Flags: needinfo?(sdetar)
Resolution: --- → INACTIVE
You need to log in before you can comment on or make changes to this bug.