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.

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?

(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.

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

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

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?

(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.

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.

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

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

(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?

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.

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

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!