484195 - Thunderbird IMAP cache parses first received wrongly.

Status: RESOLVED WORKSFORME

(MailNews Core :: Networking: IMAP, defect)

Description

[palo misik]

User-Agent:       Mozilla/5.0 (Windows; U; Windows NT 5.1; en-US; rv:1.9.0.7) Gecko/2009021910 Firefox/3.0.7 (.NET CLR 3.5.30729) XPCOMViewer/1.0a1
Build Identifier: Mozilla/5.0 (Windows; U; Windows NT 5.1; en-US; rv:1.9.1b3pre) Gecko/20090223 Thunderbird/3.0b2

0.	Create a new empty gmail account.
1.      Start "thunderbird.exe -P" and create new profile
2.	Configure IMAP access and enable inbox for offline usage.
3.	Send message in attachment _1.eml by sendemail to account on gmail. 
4.	After message is received display message source or save message to file.

You will see that message starts with this pattern

Mar 19 11:09:52 2009
X-Mozilla-Status: 0001
X-Mozilla-Status2: 00000000

If you take a look into offline storage you will see that message is received correctly
And you will see 
From - Thu Mar 19 11:09:52 2009
X-Mozilla-Status: 0001
X-Mozilla-Status2: 00000000

“From - Thu” disappeared.

Then send the same message again to this account.
After message is received second message display message source of second message. Message is received correctly.
Go back to first message and you will see “From - Thu” at the end of first message.

I reproduced it with Thunderbird 2.0.0.19 and 3.b2.

When I used nsIMsgMessageService::StreamMessage to stream message to file.

I got totally damaged message in this form:
Beginning of message body 
Message line 1 
Message line 2 
Message line 3 


Delivered-To: [e-mail] 
Received: by 10.100.209.19 with SMTP id h19cs286759ang; 
        Tue, 17 Mar 2009 07:12:13 -0700 (PDT) 
Received: by 10.86.51.10 with SMTP id y10mr128741fgy.9.1237299132269; 
        Tue, 17 Mar 2009 07:12:12 -0700 (PDT) 
Return-Path: <[e-mail]> 
Received: by xxxxxxxxxxxx.sk (Postfix, from userid 5001) 
    id 5381BB30DC6D; Tue, 17 Mar 2009 15:12:11 +0100 (CET) 
From: srctest <[e-mail]> 
User-Agent: Thunderbird 2.0.0.16 (Windows/20080708) 
MIME-Version: 1.0 
To: [e-mail] 
Subject: Test message 
Content-Type: text/plain; charset=ISO-8859-1; format=flowed 
Content-Transfer-Encoding: 7bit 
Message-Id: <[e-mail]> 

Beginning of message body 
Message line 1 
Message line 2 
Message line 3 
Message line 5 
End of message body





Reproducible: Always

Actual Results:  
Wrongly parsed email.

Expected Results:  
Correctly parsed email.

Take a look at mozilla.dev.apps.thunderbird
Subject: StreamMessage and GMail


If anyone rely on correct information he can lose or damage other data. 
I'm not sure it can happened on other messages with clean Thunderbird. 

I got damaged messages not just first one. But i can't simply reproduce it without my extension.

Comment 1

[palo misik]

Attachment: Testing email

Comment 2

[Ludovic Hirlimann [:Usul]]

(In reply to comment #0)

> Take a look at mozilla.dev.apps.thunderbird
> Subject: StreamMessage and GMail

Can you provide a link to it as they are available through groups.google.com

Comment 3

[palo misik]

http://groups.google.com/group/mozilla.dev.apps.thunderbird/browse_thread/thread/593b91360cbf084e#

By the way. Isn't simpler to configure news (nntp - ServerName news.mozilla.org) in Thunderbird and check news I specified?

Comment 4

[palo misik]

Well if you are using just web browser this can be helpful.
At the end of that post is link to post in mozilla.dev.platform thread with
subject "Read blocking nsInputStream without blocking" mozilla.dev.
link is here:

http://groups.google.com/group/mozilla.dev.platform/browse_thread/thread/88d31625d071f5b0

Comment 5

[David :Bienvenu]

so we would need your extension to reproduce this, is that right? If so, can we get a copy of it?

Comment 6

[palo misik]

If you follow steps I described exactly you can reproduce it for first received message without my extension.
It is important go through all steps.

I' going to try to reduce it to smallest code. 
It is written in c++ because of dependency on OS and another services and application.
Basically i do this. 

My extension react after I get notification from nsIMsgFolderNotificationService that new message was received. 

In my MsgFolderListener::ItemAdded(nsISupports *aItem)
I immediately open message and try to stream it by nsIMsgMessageService::StreamMessage.

If first chunk of data I read from StreamListener::OnDataAvailable I have damaged email.

Comment 7

[palo misik]

I'm not sure but it can help.
I got this assertion form IMAP thread.
nsStreamListenerTee not thread-safe

Here is call stack of thread where it happened.

>kb
 Index  Function
--------------------------------------------------------------------------------
 1      ntdll.dll!_DbgBreakPoint@0() 
*2      xpcom_core.dll!nsDebugImpl::Break(const char * aFile=0x02cec4d0, int aLine=0x0000002b) 
 3      xpcom_core.dll!nsDebugImpl::Assertion(const char * aStr=0x02cec550, const char * aExpr=0x02cec51c, const char * aFile=0x02cec4d0, int aLine=0x0000002b) 
 4      xpcom_core.dll!NSGlue_Assertion(const char * aStr=0x02cec550, const char * aExpr=0x02cec51c, const char * aFile=0x02cec4d0, int aLine=0x0000002b) 
 5      necko.dll!nsStreamListenerTee::Release() 
 6      necko.dll!nsCOMPtr<nsIRequestObserver>::~nsCOMPtr<nsIRequestObserver>() 
 7      necko.dll!nsAsyncStreamObserver::~nsAsyncStreamObserver() 
 8      necko.dll!nsAsyncStreamListener::~nsAsyncStreamListener() 
 9      necko.dll!nsAsyncStreamListener::`scalar deleting destructor'() 
 10     necko.dll!nsAsyncStreamObserver::Release() 
 11     necko.dll!nsAsyncStreamListener::Release() 
 12     mail.dll!nsCOMPtr<nsIStreamListener>::assign_assuming_AddRef(nsIStreamListener * newPtr=0x00000000) 
 13     mail.dll!nsCOMPtr<nsIStreamListener>::assign_with_AddRef(nsISupports * rawPtr=0x00000000) 
 14     mail.dll!nsCOMPtr<nsIStreamListener>::operator=(nsIStreamListener * rhs=0x00000000) 
 15     mail.dll!nsImapProtocol::CloseStreams() 
 16     mail.dll!nsImapProtocol::TellThreadToDie(int isSafeToClose=0x00000000) 
 17     mail.dll!nsImapProtocol::CreateNewLineFromSocket() 
 18     mail.dll!nsImapServerResponseParser::GetNextLineForParser(char * * nextLine=0x0532b1c4) 
 19     mail.dll!nsIMAPGenericParser::AdvanceToNextLine() 
 20     mail.dll!nsIMAPGenericParser::AdvanceToNextToken() 
 21     mail.dll!nsImapServerResponseParser::ParseIMAPServerResponse(const char * currentCommand=0x061bfb98, int aIgnoreBadAndNOResponses=0x00000000) 
 22     mail.dll!nsImapProtocol::ParseIMAPandCheckForNewMail(const char * commandString=0x061bfb98, int aIgnoreBadAndNOResponses=0x00000000) 
 23     mail.dll!nsImapProtocol::FetchMessage(const char * messageIds=0x062094c0, nsIMAPeFetchFields whatToFetch=kEveryThingRFC822Peek, int idIsUid=0x00000001, unsigned int startByte=0x00000000, unsigned int endByte=0x00000000, char * part=0x00000000) 
 24     mail.dll!nsImapProtocol::FetchTryChunking(const char * messageIds=0x062094c0, nsIMAPeFetchFields whatToFetch=kEveryThingRFC822Peek, int idIsUid=0x00000001, char * part=0x00000000, unsigned int downloadSize=0x000007a8, int tryChunking=0x00000001) 
 25     mail.dll!nsImapProtocol::ProcessSelectedStateURL() 
 26     mail.dll!nsImapProtocol::ProcessCurrentURL() 
 27     mail.dll!nsImapProtocol::ImapThreadMainLoop() 
 28     mail.dll!nsImapProtocol::Run() 
 29     xpcom_core.dll!nsThread::Main(void * arg=0x0534c068) 
 30     nspr4.dll!_PR_NativeRunThread(void * arg=0x0534c160) 
 31     nspr4.dll!pr_root(void * arg=0x0534c160) 
 32     msvcr80d.dll!__beginthreadex() 
 33     msvcr80d.dll!__beginthreadex() 
 34     kernel32.dll!_BaseThreadStart@8()

Comment 8

[WADA:World Anti-bad-Duping Agency]

I could observe phenomenon with Tb trunk 2009/3/07 build, using Gmail IMAP, on MS Win-XP SP3.
  1. Enable "offline use" of a folder(say FOLDER-1), shutdown down Tb
  2. Delete file of FOLDER-1 & FOLDER-1.msf
  3. Restart Tb, check FOLDER-1 content
  4. View messege source of mail of smallest UID
     (mail of smallest value in "Order Received" column) 
But I couldn't observe the phenomenon with Tb trunk 2009/3/21 build any more.
(Note: Bug 381472 has been FIXED at 2009-03-17 07:14:19 PDT)

To palo misik(bug opener):
Can you reproduce problem with latest-trunk nightly?

Comment 9

[palo misik]

To WADA:
I installed latest build from here:
ftp://ftp.mozilla.org/pub/thunderbird/nightly/2009/03/2009-03-22-03-comm-central-trunk/thunderbird-3.1a1pre.en-US.win32.installer.exe

I have to confirm that parsing of first message in offline storage is in that build ok.

I'm happy to see that beginning of the message doesn't contains:
From - Mon Mar 23 07:42:39 2009
X-Mozilla-Status: 0001
X-Mozilla-Status2: 00000000

And message start from point which was received.

But I can receive message which looks like this:
Date: Thu, 21 Aug 2008 13:35:33 +0200
From: srctest <[e-mail]>
User-Agent: Thunderbird 2.0.0.16 (Windows/20080708)
MIME-Version: 1.0
From - Mon Mar 23 07:42:39 2009
X-Mozilla-Status: 0001
X-Mozilla-Status2: 00000000
To: [e-mail]
Subject: Test message
Content-Type: text/plain; charset=ISO-8859-1; format=flowed
Content-Transfer-Encoding: 7bit
Return-Path: [e-mail]

Beginning of message body
Message line 1
Message line 2
Message line 3
Message line 5
Message line 6
Message line 7
Message line 8
Message line 9
End of message body

This kind of message is received and not correctly parsed
Parser just add enter before From - to finish message header.

Comment 10

[palo misik]

Hi,

I tried to rewrite my extension from c++ to javascript and deliver you to reproduce my problem with damaged messages from 
NS_IMETHOD 
nsIMsgMessageService::StreamMessage(const char *aMessageURI, nsISupports *aConsumer, nsIMsgWindow *aMsgWindow, nsIUrlListener *aUrlListener, PRBool aConvertData, const char *aAdditionalHeader, nsIURI **_retval) = 0;

In javascript it seems that it works fine. Then I started to investigate what difference is between c++ and javascript.

I thought that nsIMsgMessageService::StreamMessage isn’t documented because nsIMsgMessageService.h has no comments about parameters. Therefore I searched Thunderbirds code to see how YOU are using it (I searched all code of Thunderbird 2.0.0.19). In all places where you call this method is passed last parameter (_retval) as NULL. Therefore I expected that I have to call it with NULL. When it was called from javascript there was passed correct pointer.

Meanwhile I read thread on mozilla.dev.planning about xulplannet. Someone mentioned there that any idl files are commented with wrong style.
Therefore I took a look into nsIMsgMessageService.idl. What I saw? Documentation of parameters I was looking for.

I realized the StreamMessage starts asynchronous reading without blocking. If I don’t addref _retval then it is finished prematurely. If operation was fast and was completed inside StreamMessage I read correct data from stream if not I get corrupted data. If I release _retval after I get notification in aUrlListener ::OnStopRunningUrl everything is fine.

Am I right?
Is my analysis correct?
Can I release _retval after I get notification in aUrlListener ::OnStopRunningUrl without worry i get damaged data?

If I’m right you should review code on all occurrences of StreamMessage with null.

Of course you should fix idl comments style in mentioned nsIMsgMessageService.idl.

Comment 11

[palo misik]

I was wrong. There is still some difference between call from js and c++.
When I tested in c++ i forgot to disable my js extension.

Comment 12

[palo misik]

Attachment: Native binnary extnsion

use 7-zip to unpack

Comment 13

[palo misik]

Attachment: javascript extension

javascript version works fine

Comment 14

[palo misik]

Finally I extracted a part of my code which is responsible to save message to file. I created new minimal native extension with which you can reproduce problem. 

It is important to start with empty folder (create new profile or delete inbox and inbox.msf) and then starts thunderbird.


Extension I shipped must be installed manually. 
In file “imapBugNative\Bin\[e-mail]” modify your real path where you extracted a package and then copy to *extension* subfolder of your testing account.
Extension is built for Tb 2.0.0.19 debug configuration. 
If you want to try it with another version then replace stuff in subfolder Mozilla and rebuild it in Visual C++. 

Prerequisites:
Before you start create on drive c: folder c:\Tb\.

How it works.
After extension gets notification from MsgFolderNotificationService, it extract a messageUri and adds it to ScanQueue. 
ScanQueue is watched by scan thread.
Scan thread create a proxy object which start storing message to file. It utilizes nsiMsgMessageService::StreamMessage. Messages are stored in c:\Tb\<number>.eml.

In subfolder TestStuff is file ISent.eml which I send to IMAP Gmail account.
In IRead.eml is what I get from Thunderbird.
Files inbox.* is my inbox after extension finished reading message. I sent one message. Message is stored twice. First is correct and second is a message I got from Thunderbird. I got damaged storage just by reading. 

I thing there is some kind of race condition. I think that proxy interferes with IMAP but I don’t know how. 

I have rewritten this extension to javascript and it works fine.

Attachments description:
imapbug.7z – extension written in javascript
imapBugNative.7z – extension written in c++

PS: 
This is really maximally simplified version of my extension. I really have serious reason why I can’t use JavaScript version. Therefore do not try to persuade me to use JavaScript. I think it is bug in Thunderbird in some special condition. 

Please any help is welcome.

Comment 15

[David :Bienvenu]

palo, does your extension have this problem with a trunk 3.0 build? If so, I would need a version of your extension built against that in order to fix the bug in 3.0

Comment 16

[palo misik]

Attachment: Version for tb3

Comment 17

[palo misik]

A Tb3 behavior is different. I sent one message to my testing IMAP account on GMail. I read message correctly but I get two notifications about new message. Message is stored in offline storage twice and correctly. I tested it with Tb3b2 debug configuration. Therefore I can’t confirm what happened in release configuration with optimizations. Sorry I don’t have Tb3.0 trunk. It take long time to check out me trunk.

Have you any idea or advise some workaround to solve it in Tb2?

imapBugNativeV3.7z contains my extension for Tb3. It contains source code too.
If you want to compile from source code you need to update project settings (AdditionalIncludeDirectories and AdditionalDependencies) or copy Mozilla includes to headers to imapBugNativeV3\Mozilla\include. The same do with lib files.
For trunk I think you would need to update Bin\install.rdf.

Comment 18

[Wayne Mery (:wsmwk)]

from PM 9/24/2009 "I resolved this issue by different way.
I don't try to force thunderbird to download message from imap server
when folder is for offline and message don't has flag MSG_FLAG_OFFLINE.
This causes that my extension don't work correctly till messages aren't
downloaded from server to offline cache (it skips messages that are not
offline) but more important is that my extension don't damage offline
storage.
I haven't tried it with Tb3b4 yet whether there is still issue with
doubling messages."

Comment 19

[palo misik]

I tested it with Tb3b4 and it seems it works correctly now.
I get only one notification about new message.

Once Thunderbird hit following assertion:
nsDocLoader.cpp :ln 515
      NS_ASSERTION((loadFlags & nsIChannel::LOAD_REPLACE) ||
                   !(mDocumentRequest.get()),
                   "Overwriting an existing document channel!");

With following stack:

ntdll.dll!_DbgBreakPoint@0() 	
xpcom_core.dll!Break(const char * aMsg=0x0012f254)  Line 491	C++
xpcom_core.dll!NS_DebugBreak_P(unsigned int aSeverity=0x00000001, const char * aStr=0x03a6d5d4, const char * aExpr=0x03a6d590, const char * aFile=0x03a6d54c, int aLine=0x00000205)  Line 364 + 0xc bytes	C++
docshell.dll!nsDocLoader::OnStartRequest(nsIRequest * request=0x0653fd28, nsISupports * aCtxt=0x00000000)  Line 517 + 0x36 bytes	C++
necko.dll!nsLoadGroup::AddRequest(nsIRequest * request=0x0653fd28, nsISupports * ctxt=0x00000000)  Line 603 + 0x21 bytes	C++
msgimap.dll!nsImapCacheStreamListener::OnStartRequest(nsIRequest * request=0x065800a0, nsISupports * aCtxt=0x00000000)  Line 8316	C++
necko.dll!nsInputStreamPump::OnStateStart()  Line 439 + 0x2c bytes	C++
necko.dll!nsInputStreamPump::OnInputStreamReady(nsIAsyncInputStream * stream=0x05fb23d8)  Line 395 + 0xb bytes	C++
xpcom_core.dll!nsInputStreamReadyEvent::Run()  Line 112	C++
xpcom_core.dll!nsThread::ProcessNextEvent(int mayWait=0x00000001, int * result=0x0012f848)  Line 522	C++
xpcom_core.dll!NS_ProcessNextEvent_P(nsIThread * thread=0x00d970b0, int mayWait=0x00000001)  Line 227 + 0x16 bytes	C++
gkwidget.dll!nsBaseAppShell::Run()  Line 170 + 0xc bytes	C++
tkitcmps.dll!nsAppStartup::Run()  Line 193 + 0x1c bytes	C++
xul.dll!XRE_main(int argc=0x00000001, char * * argv=0x003bd218, const nsXREAppData * aAppData=0x003bd748)  Line 3321 + 0x25 bytes	C++
thunderbird.exe!NS_internal_main(int argc=0x00000001, char * * argv=0x003bd218)  Line 103 + 0x12 bytes	C++
thunderbird.exe!wmain(int argc=0x00000001, wchar_t * * argv=0x003bd1b0)  Line 110 + 0xd bytes	C++
thunderbird.exe!__tmainCRTStartup()  Line 594 + 0x19 bytes	C
thunderbird.exe!wmainCRTStartup()  Line 414	C
kernel32.dll!_BaseProcessStart@4()  + 0x23 bytes	


I tried hard to reproduce it again but without success. It looked like Thunderbird was downloading one message again and again.

Comment 20

[Wayne Mery (:wsmwk)]

WFM per reporter