726967 - Deadlock of Firefox when using console.log and multiple threads (started with v1.4.2 of Add-on SDK)

Status: VERIFIED FIXED

(Add-on SDK Graveyard :: General, defect)

Description

[Henrik Skupin [:whimboo][⌚️UTC+1]]

So this bug is a combined regression from two fixes involved. I have found it today while trying to run our MemChaser extension build with the SDK v1.5.rc1. But this is also happening with v1.4.2.

The causing bug in the SDK is the fix for bug 718230:
https://github.com/mozilla/addon-sdk/pull/333/files

It changes the way how we log messages to the console. And in my situation we end-up in a deadlock situation. Here a short excerpt of the error output in the console:

error: An exception occurred.
Traceback (most recent call last):
  File "resource://memchaser-at-quality-dot-mozilla-dot-org/memchaser/lib/garbage-collector.js", line 87, in null
    this._emit('data', data);
  File "resource://memchaser-at-quality-dot-mozilla-dot-org/api-utils/lib/events.js", line 153, in _emit
    return this._emitOnObject.apply(this, args);
  File "resource://memchaser-at-quality-dot-mozilla-dot-org/api-utils/lib/events.js", line 185, in _emitOnObject
    this._emit('error', e);
  File "resource://memchaser-at-quality-dot-mozilla-dot-org/api-utils/lib/events.js", line 153, in _emit
    return this._emitOnObject.apply(this, args);
  File "resource://memchaser-at-quality-dot-mozilla-dot-org/api-utils/lib/events.js", line 185, in _emitOnObject
    this._emit('error', e);
[..]
[Exception... "Component returned failure code: 0x80004005 (NS_ERROR_FAILURE) [nsIConsoleService.logMessage]"  nsresult: "0x80004005 (NS_ERROR_FAILURE)"  location: "JS frame :: resource://memchaser-at-quality-dot-mozilla-dot-org/api-utils/lib/cuddlefish.js -> resource://memchaser-at-quality-dot-mozilla-dot-org/api-utils/lib/globals!.js :: forsakenConsoleDump :: line 99"  data: no]

This problem only occurs in Aurora and Nightly builds due to the changes made on bug 675221, which removes the XPCOM proxies.

So to reproduce this bug do the following:
1. git clone https://github.com/whimboo/memchaser/
2. git init && git update
3. cd addon-sdk
4. git checkout 1.4.2
5. source bin/activate
6. cd ../extension
7. cfx run
8. Enable logging by clicking the red button in the add-on bar

After step 8 Firefox will freeze within seconds and has to be killed via the process manager.

Comment 1

[Benjamin Smedberg]

163     if (NS_IsMainThread() && mDeliveringMessage) {
164         NS_WARNING("Some console listener threw an error while inside itself. Discarding this message");
165         return NS_ERROR_FAILURE;
166     }

So if you are currently in a nsIConsoleListener.observe notification and you have a script error (or explicitly send another message to the console service), we refuse to submit the message to avoid an infinite loop. Code for this existed in the prior version of consoleservice but was broken so that it only worked in race conditions and didn't work regularly.

Could you explain what "deadlock" means in your bug report? Does Firefox stop responding? If so, does it do so with 0% CPU or 100% CPU?

Comment 2

[Henrik Skupin [:whimboo][⌚️UTC+1]]

(In reply to Benjamin Smedberg  [:bsmedberg] from comment #1)
> So if you are currently in a nsIConsoleListener.observe notification and you
> have a script error (or explicitly send another message to the console
> service), we refuse to submit the message to avoid an infinite loop. Code
> for this existed in the prior version of consoleservice but was broken so
> that it only worked in race conditions and didn't work regularly.

So that would make sense here. In my extension I observe console messages. And when trying to emit the data to the main thread there is happening a failure. This will cause forsakenConsoleDump to be executed, which itself submits a console message. That message will be in the same thread as my observe callback and the code above will throw an NS_ERROR_FAILURE.

Here the link to the patch:
https://github.com/ochameau/addon-sdk/blob/5d34ca07a733ee4121105e1778d3dbf4402f11e1/packages/api-utils/lib/globals!.js#L91

Should we simply ignore such a failure by wrapping the logMessage/logStringMessage into a try/catch clause? Or would it be better to check if we are in the main thread and only submit a message in such a condition?

> Could you explain what "deadlock" means in your bug report? Does Firefox
> stop responding? If so, does it do so with 0% CPU or 100% CPU?

It completely stops responding and the CPU goes straight up to 100%. I have to force a kill via the activity console.

Comment 3

[Henrik Skupin [:whimboo][⌚️UTC+1]]

Commenting out the following line would hide this problem but still report to stdout:

https://github.com/whimboo/memchaser/blob/master/extension/lib/garbage-collector.js#L24

Comment 4

[Henrik Skupin [:whimboo][⌚️UTC+1]]

Attachment: minimized testcase

Minimized version of the MemChaser extension. To reproduce the problem simply install it in Firefox 12 or 13.

Comment 5

[Benjamin Smedberg]

When you say "emit the data to the main thread" what do you mean? Note that since console listeners only ever run on the main thread, you're always on the main thread when this runs. So checking what thread you are on seems a bit pointless.

What is this extension actually trying to accomplish?

Comment 6

[Henrik Skupin [:whimboo][⌚️UTC+1]]

(In reply to Benjamin Smedberg  [:bsmedberg] from comment #5)
> When you say "emit the data to the main thread" what do you mean? Note that
> since console listeners only ever run on the main thread, you're always on
> the main thread when this runs. So checking what thread you are on seems a
> bit pointless.

Ah ok, that would explain the output of nsIThreadManager.isMainThread. Thanks for the clarification. In the observer callback I use the EventEmitter from the Add-on SDK to send data to the main module. I'm sure Alex can explain how that code works in detail. I have just started using it 2 weeks back.

> What is this extension actually trying to accomplish?

See my blog post: http://www.hskupin.info/2012/02/10/memchaser-an-extension-to-track-firefoxs-memory-activities/

So for GC/CC activities we have to scrape the console service for messages. This is only necessary until bug 531396 has been fixed.

Sorry that I can't give more details but I'm fairly new in using it.

Comment 7

[Alexandre Poirot [:ochameau]]

Attachment: Pull request 345

Henrik, the main issue is related to what Benjamin said in comment 1.
You shouldn't dispatch any console message from `observe` method call.

You are dispatching a new console message from:
    --> garbage-collector.js:observe:
    this._emit('data', data);
    --> main.js:
    logger.log(gData.current);
    --> logger.js:
    console.debug("Logging: '" + message + "'");

It ends up looping as `_emit` method tries to log errors when the listener throws an error:
https://github.com/mozilla/addon-sdk/blob/master/packages/api-utils/lib/events.js#L147-153

You should fix your code, by doing this (there may be nicer solutions!):
    let self = this;
    require("timer").setTimeout(function () {
      self._emit('data', data);
    });

And we should prevent such infinite loop, by landing patch similar to this pull request.

Comment 8

[[github robot]]

Commits pushed to master at https://github.com/mozilla/addon-sdk

https://github.com/mozilla/addon-sdk/commit/34a9d6bcf8c92107f39c5f1f332a1e940ba5c5c5
Bug 726967: Fix infinite loop when `error` event listener throws.

https://github.com/mozilla/addon-sdk/commit/45c79c70c5126731c282c12eaebdf9e271a84041
Merge pull request #345 from ochameau/bug-726967-infinite-loop

fix Bug 726967: Fix infinite loop when `error` event listener throws. r=@gozala

Comment 9

[Henrik Skupin [:whimboo][⌚️UTC+1]]

This fixes the issue I was facing. Thanks for the patch. I will now update our MemChaser extension.

Comment 10

[Henrik Skupin [:whimboo][⌚️UTC+1]]

(In reply to Alexandre Poirot (:ochameau) from comment #7)
> You should fix your code, by doing this (there may be nicer solutions!):
>     let self = this;
>     require("timer").setTimeout(function () {
>       self._emit('data', data);
>     });

Benjamin, could you imagine a better fix or is this one I could safely use?

Comment 11

[Benjamin Smedberg]

I still don't understand what is actually being accomplished here. It appears as if you are watching for console messages and then dispatching the same console message again. I don't understand why you want to be doing this, so I cannot comment on the technical aspects of the patch.

In general you should not ever be dispatching a new console message while you're handling an existing console message. The timeout appears to just be intentionally defeating the anti-looping mechanism.

Comment 12

[Henrik Skupin [:whimboo][⌚️UTC+1]]

Alex, is there a way to only output a message to stdout instead? For debugging purposes it would be enough for us.

Comment 13

[Alexandre Poirot [:ochameau]]

Sure, you may use `dump` directly. Having said that there is some funky behavior with `dump`. From what I remember one `dump` goes to stderr and the other one goes to stdout. (`dump` in html/xul documents is different than the JSM/XPCOM one). There may even be more than 2 kind of dump!