545365 - "this should not be happening! arrgggggh!" repeatedly to console because gloda streaming a message that does not support the JS Mime Emitter

Status: RESOLVED FIXED

(MailNews Core :: Database, defect)

Description

[ISHIKAWA, Chiaki]

User-Agent:       Mozilla/5.0 (X11; U; Linux i686; ja; rv:1.9.1.7) Gecko/20091221 Firefox/3.5.7
Build Identifier: Mozilla/5.0 (X11; U; Linux i686; ja; rv:1.9.1.7) Gecko/20100111 Thunderbird/3.0.1

To be frank, I have no idea what triggers this outputs.

But seeing
this should not be happening! arrgggggh!
this should not be happening! arrgggggh!
this should not be happening! arrgggggh!
       ...

is not quite comfortable.

I would like to help debugging if possible.


Reproducible: Sometimes

Steps to Reproduce:
1. Sorry, no idea.
2.
3.



I am using TB 3.0.1 under Debian 
Linux debian-vbox-ci 2.6.26-2-686 #1 SMP Sat Dec 26 09:01:51 UTC 2009 i686 GNU/Linux

inside VirtualBox emulation environment.
But emulation probably doesn't have anything to do with this since I noticed
a similar report from a reporter in
http://forums.mozillazine.org/viewtopic.php?f=29&t=1549095

That report doesn't mention virtual environment and I don't see
any reason virtual/real environment has anything to do with this strange
output.

It is hard to say if anything is seriously broken, but who knows?
At least, the coder expected something fishy is happening when the control
reaches the part where this message is printed, and this message gets printed
multiple times. So something IS fishy.

Maybe printing a short stack trace where this message is printed would be helpful (with more additional information such as values of relevant variables, etc.)

TIA

Comment 1

[Nathan Tuggy (:tuggyne)]

A poke around MXR turns up one result, in Gloda, which appears to be a warning only that unexpected things are happening. Specifically, http://mxr.mozilla.org/comm-central/source/mailnews/db/gloda/modules/mimemsg.js#142 ff indicates that this message appears when CallbackStreamListener.prototype.onDataAvailable implementation is being called, which it shouldn't be. (This was noted also, in less detail, in the MozillaZine thread.)

asuth, this might well interest you. Filing in Database, where the other Gloda bugs seem to live. Severity needs checking.

Comment 2

[Andrew Sutherland [:asuth] (he/him)]

The most likely explanation is that code is trying to use the JS Mime Emitter to stream a message that does not support the JS Mime Emitter.  As far as I know, this only is the case for news messages.

It is unlikely that the gloda indexing mechanism is doing this as it has several layers of defense against trying to index news messages.

The message summarization stuff for collapsed threads uses the JS Mime Emitter, but it is supposed to stay away from news messages.  Its logic may not be sufficiently robust.  Extensions may also have cottoned onto the API and not know to avoid news messages.

Practically speaking, the message is harmless.  I agree that it does not sound harmless.  And a stack trace wouldn't be bad but there will be no interesting JS stack at the point this happens.

Comment 3

[ISHIKAWA, Chiaki]

Hi, 
mention of "news messages" sounds interesting because indeed
I have accessed mozilla newsgroups to figure out how to debug javascript usage
in TB3. I was reading a few articles and "uncolappsed" several threads 
in doing so. (This effort is related to the Bug 429827 )

Maybe, next time, I will look at the invoking console when I read the news articles to see if uncollapsing thread would trigger the repeated messages.

TIA

Comment 4

[ISHIKAWA, Chiaki]

(In reply to comment #3)

> Maybe, next time, I will look at the invoking console when I read the news
> articles to see if uncollapsing thread would trigger the repeated messages.
> 
> TIA

Right, using TB3, uncollapsing the news message thread, and then visiting the message(s) in
the thread produced "this should not be happening! arrggggh!".

But reproducing this may not be easy.

At least, today, I found a reproducible thread and messages.
Some threads cause this message printed while others don't.

If I visit mozilla.dev.platform newsgroup hosted at news.mozilla.org
and visit a thread, "Loading components for chrome Mochitests - help wanted",
circa August 18th, 2009,
and uncollapse it, and then
in the tree-like headers, visit the
second entry there, namely a post by "Ehsan akhgari", then
at that timing, "this should not be happening! arrgggggh!" is printed
on the invoking tty console emulator.

Visting the third article also triggers this output.

Someone who is interested in debugging can use this test case.

I have extensions 
 - Javascript Debugger 0.9.87.4 
 - NoScript 1.9.9.47
 - SQLite Optimizer 0.7.5
 - Xmarks 3.4.10
 - Text link 3.1.2009110201 (actually the name of the add-on is
   in Japanese transcription of TextLink or some such.)

but not sure if these extensions may interfere with the said behavior
of mime emitter, etc.

TIA

Comment 5

[Wayne Mery (:wsmwk)]

(In reply to comment #2)
> The most likely explanation is that code is trying to use the JS Mime Emitter
> to stream a message that does not support the JS Mime Emitter.  As far as I
> know, this only is the case for news messages.

would this happen also for news messages that have been copied to imap or local?

Comment 6

[Andrew Sutherland [:asuth] (he/him)]

(In reply to comment #5)
> would this happen also for news messages that have been copied to imap or
> local?

No, the problem with streaming is in the news folder/server/uri implementation, not the IMAP/local ones.

Comment 7

[Lucien]

Mozilla/5.0 (Macintosh; U; Intel Mac OS X 10.6; en-US; rv:1.9.2.13) Gecko/20101207 Mnenhy/0.8.3 Thunderbird/3.1.7

The newsgroup threads that trigger the message seem to be unrelated, but it looks like it has something to do with the message threading... both expanding and collapsing (though not viewing any different messages).

Comment 8

[Wayne Mery (:wsmwk)]

(In reply to Andrew Sutherland (:asuth) from comment #6)
> (In reply to comment #5)
> > would this happen also for news messages that have been copied to imap or
> > local?
> 
> No, the problem with streaming is in the news folder/server/uri
> implementation, not the IMAP/local ones.

so we can get this off UNCO and mark this NEW?

Comment 9

[Andrew Sutherland [:asuth] (he/him)]

(In reply to Wayne Mery (:wsmwk) from comment #8)
> so we can get this off UNCO and mark this NEW?

Not unless we have explicit STR; I think we have had various fixes to minor glitches in streaming for the multi-message summary logic that might have fixed this.  It's also possible we're just looking at corrupt message/folder flags tricking us into thinking something is a mail message when it's not.

We still have the most excellent error message though, so probably we should keep this bug around for now, though...

Comment 10

[Jim Porter (:squib)]

Would it help to write a patch to print a stack trace when we hit this? Then in the future, we could hopefully diagnose this a bit better.

Comment 11

[Shane]

I'm getting this on 64 bit Thunderbird 7.0.1 running on both Centos 5.5 and Scientific Linux 6.1.  We get this output each time a Newsgroup message is viewed, regardless of whether its selected via keyboard or mouse, or if the message has already been read or not.

Process or elimination for me I've found something in Enigmail plugin (1.3.2) is causing Stale NFS handles (strace output below) ... not sure if this will be the same for others but hopefully it's useful in tracking further:

19127 poll([{fd=5, events=POLLIN}, {fd=4, events=POLLIN}, {fd=9, events=POLLIN|POLLPRI}, {fd=25, events=POLLIN|POLLPRI}, {fd=26, events=POLLIN|POLLPRI}, {fd=27, events=POLLIN|POLLPRI}, {fd=12, events=POLLIN|POLLPRI}, {fd=24, events=POLLIN}, {fd=21, events=POLLIN}], 9, 0) = 0 (Timeout)
19127 read(4, 0x7fb0e4558074, 4096)     = -1 EAGAIN (Resource temporarily unavailable)
19127 poll([{fd=5, events=POLLIN}, {fd=4, events=POLLIN}, {fd=9, events=POLLIN|POLLPRI}, {fd=25, events=POLLIN|POLLPRI}, {fd=26, events=POLLIN|POLLPRI}, {fd=27, events=POLLIN|POLLPRI}, {fd=12, events=POLLIN|POLLPRI}, {fd=24, events=POLLIN}, {fd=21, events=POLLIN}], 9, 0) = 0 (Timeout)
19127 write(2, "this should not be happening! ar"..., 41) = -1 ESTALE (Stale NFS file handle)

Comment 13

[Patrick Brunschwig]

Confirming. Streaming news messages doesn't work with MsgHdrToMimeMessage (which causes a problem for Enigmail).

Comment 14

[Jonathan Protzenko [:protz]]

(In reply to Patrick Brunschwig from comment #13)
> Confirming. Streaming news messages doesn't work with MsgHdrToMimeMessage
> (which causes a problem for Enigmail).

bug 478167

Comment 15

[max]

I do not know if this should or should not be happening, but it causes problems in web extensions during attempt to get e.g. more message headers for an nntp message, see Bug #1644027. The code even unable to properly reject a promise if some error happens. There are several places in the code where functions are not ready to actual argument with no message and exception is not caught, so the promise just is not resolved. The extension has no chance to be notified about the error.

Comment 16

[Magnus Melin [:mkmelin]]

Attachment: Bug 545365 - Make NNTP streaming of messages work. r=leftmostcat

Comment 17

[Magnus Melin [:mkmelin]]

Attachment: Bug 545365 - Remove add-ons workaround for streaming nntp messages. r=john.bieling

Depends on D179933

Comment 18

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/comm-central/rev/d8c1f3ba2b40
Make NNTP streaming of messages work. r=leftmostcat
https://hg.mozilla.org/comm-central/rev/c357a7917dc6
Remove add-ons workaround for streaming nntp messages. r=john.bieling

Comment 19

[Magnus Melin [:mkmelin]]

Comment on attachment 9337656 [details]
Bug 545365 - Remove add-ons workaround for streaming nntp messages. r=john.bieling

[Approval Request Comment]
Regression caused by (bug #): never worked
User impact if declined: summary wouldn't work for news, so we'd have to add workarounds (like bug 1824422)
Testing completed (on c-c, etc.): c-c
Risk to taking this patch (and alternatives if risky): fairly low risk

Comment 20

[Magnus Melin [:mkmelin]]

(Both patches)

Comment 21

[Wayne Mery (:wsmwk)]

Comment on attachment 9337656 [details]
Bug 545365 - Remove add-ons workaround for streaming nntp messages. r=john.bieling

[Triage Comment]
Approved for beta

Comment 22

[Wayne Mery (:wsmwk)]

Comment on attachment 9337435 [details]
Bug 545365 - Make NNTP streaming of messages work. r=leftmostcat

[Triage Comment]
Approved for beta

Comment 23

[Daniel Darnell [:dandarnell]]

Thunderbird 115.0b3:
https://hg.mozilla.org/releases/comm-beta/rev/767a05078a9e
https://hg.mozilla.org/releases/comm-beta/rev/240d9833cbab