Closed Bug 582918 Opened 14 years ago Closed 13 years ago

Body of message(and message headers too) is missing when move to sub-folder of "Local Folders" by filter and mailnews.downloadToTempFile=true

Categories

(MailNews Core :: Filters, defect)

x86
Windows 7
defect
Not set
critical

Tracking

(Not tracked)

VERIFIED FIXED
Thunderbird 5.0b1

People

(Reporter: Aureliano, Assigned: rkent)

References

(Blocks 1 open bug, )

Details

(Keywords: dataloss, regression, Whiteboard: [Workround: comment 14] [ressession of bug 387361])

Attachments

(11 files, 2 obsolete files)

540 bytes, text/plain
Details
25.36 KB, application/octet-stream
Details
25.71 KB, application/octet-stream
Details
8.20 KB, patch
Details | Diff | Splinter Review
4.61 KB, text/plain
Details
8.48 KB, text/plain
Details
165.18 KB, text/plain
Details
210.52 KB, text/plain
Details
7.55 KB, patch
Details | Diff | Splinter Review
10.19 KB, patch
Bienvenu
: review+
Details | Diff | Splinter Review
11.42 KB, patch
Details | Diff | Splinter Review
From long time I have created one subfolder of my Local Folders when I move my bugzilla traffic using a generic filter.
When I use TB 3.2.x I have dataloss!

STR:
1. create a filter (for example a filter that move in one subfolder of local folders messages that have subject = "ciao");
2. send your self a messagge with subject = "ciao" and body = "abc";
3. when message arrive TB move him to subfolder but the body of message is empty (source code too).

If I disable the filter from this account I haven't dataloss.

Behaves the same also in safe-mode!

With TB 3.1.x I haven't problems (regressions?).

Mozilla/5.0 (Windows; Windows NT 6.1; rv:2.0b3pre) Gecko/20100728 Shredder/3.2a1pre ID:20100728032601
Attached file protocol log (in -safe-mode) (obsolete) —
Summary: Messages filtered on one subfolder of Local Folders are blank → Body of message is missing when move to sub-folder of "Local Folders" by filter
Attachment #461499 - Attachment is obsolete: true
rkent what do you need to understand what's going on ?
Component: General → Filters
Product: Thunderbird → MailNews Core
QA Contact: general → filters
Verified with Shredder. Using message filter causes blank message and blank message source

Mozilla/5.0 (Windows; Windows NT 5.1; rv:2.0b3pre) Gecko/20100729 Shredder/3.2a1pre

This error message occurs with or without message filter with View>Message Source.

Error: [Exception... "Component returned failure code: 0x80004001 (NS_ERROR_NOT_IMPLEMENTED) [nsIRequest.name]"  nsresult: "0x80004001 (NS_ERROR_NOT_IMPLEMENTED)"  location: "JS frame :: file:///C:/Program%20Files/Mozilla%20Thunderbird/components/nsLoginManager.js :: anonymous :: line 286"  data: no]
Source File: file:///C:/Program%20Files/Mozilla%20Thunderbird/components/nsLoginManager.js
Line: 286
Verified with Shredder. Using message filter causes blank message and blank message source

Mozilla/5.0 (Windows; Windows NT 5.1; rv:2.0b3pre) Gecko/20100729 Shredder/3.2a1pre

This error message occurs with or without message filter with View>Message Source.

Error: [Exception... "Component returned failure code: 0x80004001 (NS_ERROR_NOT_IMPLEMENTED) [nsIRequest.name]"  nsresult: "0x80004001 (NS_ERROR_NOT_IMPLEMENTED)"  location: "JS frame :: file:///C:/Program%20Files/Mozilla%20Thunderbird/components/nsLoginManager.js :: anonymous :: line 286"  data: no]
Source File: file:///C:/Program%20Files/Mozilla%20Thunderbird/components/nsLoginManager.js
Line: 286
Sorry for the double comment.
"This error message occurs ..." : Looking at that briefly, it is hard to see how that could result in a failure of local folders filter unless the callback failure is causing a move to give up.

"what do you need to understand what's going on?"

1. Is this 100% reproducible? (I'm not using shredder routinely myself).

2. Is there a regression window?

If reproducible it should be straightforward to trace out what is occurring, but a lazy man (like myself) would prefer a regression bug number.
(In reply to comment #9)
> 1. Is this 100% reproducible? (I'm not using shredder routinely myself).
Yes it is!
Confirmed from comment #6 too (Thanks Bozz)
Status: UNCONFIRMED → NEW
Ever confirmed: true
regression range 2010-06-08 (work) - 2010-06-12 (fails)

pushlog

http://hg.mozilla.org/comm-central/pushloghtml?startdate=2010-06-08&enddate=2010-06-12
Whiteboard: [regression range 2010-06-08 (work) - 2010-06-12 (fails)]
Definitively:

regression range 2010-06-08 (work) - 2010-06-09 (fails)

pushlog:

http://hg.mozilla.org/comm-central/pushloghtml?startdate=2010-06-08&enddate=2010-06-09

candidate change for regression is bug #387361
Whiteboard: [regression range 2010-06-08 (work) - 2010-06-12 (fails)] → [regression range 2010-06-08 (work) - 2010-06-09 (fails)]
Depends on: 387361
This issue as noted also in bug #387361 comment #45 from Matthias Bockelkamp

(In reply to bug #387361 comment #47)
> With mailnews.downloadToTempFile=true the bug does not depend on whether my
> antivirus program is enabled or disabled. With
> mailnews.downloadToTempFile=false the bug disappears.
xref bug #324467
I can't seem to demonstrate filters working for incoming POP3 mail at all when mailnews.downloadToTempFile=true in either TB 3.0.4 or TB 3.1.1 (which is confirmed by bug 324467 comment 44). OP is cross-referencing bugs that are associated with mailnews.downloadToTempFile=true. Is this current bug supposed to be dependent on mailnews.downloadToTempFile=true?
xref to Bug 571693 per regression window for ease of tracking.
Depends on: 571693
(In reply to comment #16)
> Is this current bug supposed
> to be dependent on mailnews.downloadToTempFile=true?

Yes, it is! It happens on Trunk only when mailnews.downloadToTempFile=true with STR in comment #0
Summary: Body of message is missing when move to sub-folder of "Local Folders" by filter → Body of message is missing when move to sub-folder of "Local Folders" by filter and mailnews.downloadToTempFile=true
This unit test, which does a filter of POP3 mail with quarantine enabled, seems to work for me. I need to know what has to be done to make this fail before I can fix this bug.

Many of these classes of unit tests are failing on Linux, but the reporters seem to be on windows.
(In reply to comment #19)
> Created attachment 467462 [details] [diff] [review]
> unit test that worksforme
> I need to know what has to be done to make this fail before I
> can fix this bug.

How I can help you?
(In reply to comment #16)
> I can't seem to demonstrate filters working for incoming POP3 mail at all when
> mailnews.downloadToTempFile=true in either TB 3.0.4 or TB 3.1.1 (snip)

Patch of bug 387361 by you is not landed on Tb 3.1. "Null body" of copied/moved mail is also observed in test of bug 589092 (check of "Copy to IMAP + Move to IMAP in single filter rule" case, after your patch is landed, with mailnews.downloadToTempFile=true, using Trunk build).
(In reply to comment #21)
> (In reply to comment #16)
> > I can't seem to demonstrate filters working for incoming POP3 mail at all when
> > mailnews.downloadToTempFile=true in either TB 3.0.4 or TB 3.1.1 (snip)
> 
> Patch of bug 387361 by you is not landed on Tb 3.1. "Null body" of copied/moved
> mail is also observed in test of bug 589092 (check of "Copy to IMAP + Move to
> IMAP in single filter rule" case, after your patch is landed, with
> mailnews.downloadToTempFile=true, using Trunk build).

Yes as I write in comment #0 this issue affects only Trunk (3.2.x) builds
Blocks: 387361
No longer depends on: 387361
"How I can help you?"

Does this issue occur with you anti-virus program disabled?

Cases where a bug cannot be reproduced are sometimes resolved when several people chime in with different setups, and we can see who sees the bug and who does not. It would be helpful if other people tried your STR and reported their results.
(In reply to comment #23)
> "How I can help you?"
> 
> Does this issue occur with you anti-virus program disabled?

Yes, it happens also with my AV (Kaspersky 6.0) disabled if I have set mailnews.downloadToTempFile=true.
(In reply to comment #23)
> Cases where a bug cannot be reproduced are sometimes resolved when several
> people chime in with different setups, and we can see who sees the bug and who
> does not. It would be helpful if other people tried your STR and reported their results.

Kent James, bug 589092 is my answer to your repeated such question. My bug 589092 is similar to my answer of bug 387361 comment #13 to your question of bug 387361 comment #12. Should we report each phenomenon with each slightly diferrent condision with slightly different STR, providing detailed data such as log or trace for each slightly different test cases?
"bug 589092 is my answer to your repeated such question"

WADA, I don't doubt that there are existing issues of incorrect filter copies. Bug 387361 was an attempt to solve one such issue, but others remain. The bug that you mention is an IMAP bug, while this bug is a POP3 bug, so although the issues may be related they are probably not the same.

But at this point in time, I am primarily interested in making sure that the patch to bug 387361 made things better, not worse. As you can see, it is quite difficult to mess with this code without causing unforeseen effects - particularly when you add anti virus software to the mix. Fixing these bugs is not my highest priority at this point in time, but I will followup any issues from patches that I landed, including those of bug 387361.

The option always exists to back out bug 387361, but that would result in a clearly reproducible problem recurring. Because I did the patch to bug 387361, I am willing to work on any side effects of that bug that I can reproduce. Aureliano with his comment 0 and comment 13 seems to have such a case - but I cannot reproduce it. If we can figure out why he sees it and I don't, and then ideally figure out what I have to do to see it, then I could work on it. Otherwise, the only choice available is to either leave the existing patch, or back it out.
(In reply to comment #26)
> But at this point in time, I am primarily interested in making sure that the
> patch to bug 387361 made things better, not worse. (snip)

You are absolutely right. Your patch for bug 387361 improved very well. Unless your patch is applied, we can't produce phenomenon of "Null mail body", this bug and bug 589092, because far worse problem of bug 387361 occurs :-)
Followup of your patch for bug 387361 is required to resolved whole problem of bug 387361.
"Null mail body" I wrote in bug 589092 was wrong. As "Fetch Header Only" was checked when I tested, no mail body lines was uploaded to IMAP folder. Sorry for my mistake.

Checked with 6/08 build, 6/09 build, 8/16 build, 9/06 build (Tb3.2a1pre), on MS Win-XP SP3.
(A) Exception upon View/Message Source
    Observed with all builds. Irrelevant to this bug.
(B) Problem when "Copy to local and Move to local" in single filter rule.
    6/08 build : Nothing was processed by filering upon download.
                 No filter log was written.
    6/09, 8/16, 9/06 build : No problem.
                Copy to local, Move to local was executed as expected.
(C) Simple "Move to local" only (Pure "Move to local" without "Copy")
    6/08 build : No problem.
    6/09, 8/16, 9/06 build : Problem was reproduced.

[Steps to reproduce]
(0) mailnews.downloadToTempFile=true (POP3 account)
    Fetch Heder Only = Off
    Leave Messages on Server = On (I don't know relevant or not)
    Mails used in test: Five mails is sent.
       mail-1 : Subject=test-111, body=test-111
       mail-2 : Subject=test-112, body=test-112
       mail-3 : Subject=test-113, body=test-113
       mail-4 : Subject=test-114, body=test-114
       mail-5 : Subject=test-115, body=test-115
   Filter rules : next rule only (Filter log is enabled).
     name="test-1-Move-Local"
     enabled="yes"
     type="17"
     action="Move to folder"
     actionValue="mailbox://nobody@Local%20Folders/Inbox/F1"
     condition="AND (subject,begins with,test-1)"
   Delete all mails in POP3 account's Inbox and Local Folder's Inbox/F1,
   and "Compact Folders" for both accounts.
(1) Send above five mails
(2) Get Mails
    POP3 account's Inbox: Nothing is shown at thread pane.
    Local Folder's Inbox/F1 - Folder Pane : Unread mail count=5 is shown.
    Filter logs says five mails are filtered.
(3) Open Local Folder's Inbox/F1
    Only test-115 is shown at thread pane.
    Nothing is displayed at message pane and by View/Message Source.
    Unread mail count is reset to zero(null or space atfolder pane)
(4) Mail folder file content
    POP3 account's Inbox: five mails are held, with X-Mozilla-Status: 0000
    Local Folder's Inbox/F1 : Nothing is written.
(5) After "Repair Folders"
    POP3 account's Inbox: five mails are shown, with Read status.
    Local Folder's Inbox/F1 : Nothing is shown, as no mail data in file of F1.
Note: Result with 6/09 build was slightly different.
      At step 4 & step 5, only test-111 was seen in POP3 account's Inbox.

Kent James, check with "Pure Move to Local filter rule" only, with multiple messages, please.
Checked with next trunk build.
> Mozilla/5.0 (Windows NT 5.1; rv:2.0b6pre) Gecko/20100906 Thunderbird/3.2a1pre
Filter rule is same as comment #28.
   if subject begins with test-1, move to F1 of Local Folders
A mail is put in mail folder before test, to force initial offset>0.
Mail size of three mails are different. test-1?1 > test-1?2 > test-1?3.

(1) Inbox has a mail(size=746 bytes), so next mail's data is put at offset=746.
(2) Receive three mails, test-101, test-102, test-103, and filter runs.
    test-103 appears at thread pane of F1 of Local Folders,
    but nothing is written in F1 of Local Folders.
    ==> Keep backup-A of Inbox of POP3 account
(3) Receive three mails additinally, test-111, test-112, test-113, filter runs.
    test-103 is replaced by test-113 at thread pane of F1 of Local Folders.
    Nothing is written in F1 of Local Folders.
    ==> Keep backup-B of Inbox of POP3 account

Problem-1: Required [CRLF] is not written at end of file of Inbox.
Because no [CRLF] at end of file, next data becomes continued data of previous mail. So, test-101 is shown by "Repair Folder" of Inbox. test-101 of backup-A has partial/garbled data for test-101, test-102, test-103, and test-101 of backup-B has partial/garbled data for test-101, test-102, test-103, test-111, test-112, test-113.
This lack of [CRLF] at end of file was not observed with receive of single mail.
 
Problem-2: Garbled data is written as mail data.
For example, line 46 is;
    746 bytes of 0x20 + "From - Wed Sep 15 14:35:42 2010" + [CRLF]
Similar garbled long/continuous 0x20 is seen at some plases.
Similar "From - Wed Sep ..." after continuous 0x20 space is seen at some plases.
Line 90 of backup-B is 2587 bytes of continuous 0x20.

Lack of [CRLF] before "From - ..." produces lack of "separator line of unix mbox". It may be one of causes of "nothing is written to F1 of Local Folders" or garbages or long/continuous spaces.

By the way, I think bug summary is misleading. Lost data is never mail body only.
In my test, next was observd.
  If test-1?3 is shown at first after folder open of F1, header pane was also
  blank. If existent mail is shown first, header data of existent mail was
  kept at header pane, and message pane is cleared.
As seen by "View Message Sorce", nothing is written in move target folder.
Garbage was not 0x20. It's probably NUL. (My text editor shows as blank...)
Summary: Body of message is missing when move to sub-folder of "Local Folders" by filter and mailnews.downloadToTempFile=true → Body of message(and message headers too) is missing when move to sub-folder of "Local Folders" by filter and mailnews.downloadToTempFile=true
any progress on this one?
I want to note a reproducible issue that may be related to the problems of this bug.

In my FiltaQuilla addon, I have a print message function. If you try to use that function with downloadToTempFile = true and POP3, then the message that prints is the first message in the file (impling key = 0) rather than the correct message.

The message uri is set using:

let uri = hdr.folder.generateMessageURI(hdr.messageKey);

I have confirmed that the key is zero at this point, which is why it is behaving this way. The key that comes into custom filters is no different than those that come into other filters. The messagre header is sent to custom filters in the code line:

http://mxr.mozilla.org/comm-1.9.2/source/mailnews/local/src/nsParseMailbox.cpp#2239

2239         customAction->Apply(messageArray, value, nsnull,
2240                             nsMsgFilterType::InboxRule, msgWindow);


So I suspect this is an issue with wider implications than just my addon.
That's how I noticed the issue as well. I was using some rules + FiltaQuilla in order to move incoming mail to certain folders. Then I had some saved searches as folders so I can monitor various mail from a collection of actual folders. Some of these mail started having issues when selected (no body displayed). So, I filed Bug 604754.
Whiteboard: [regression range 2010-06-08 (work) - 2010-06-09 (fails)] → [Wrorkround=mailnews.downloadToTempFile=false], [regression range 2010-06-08 (work) - 2010-06-09 (fails)]
Whiteboard: [Wrorkround=mailnews.downloadToTempFile=false], [regression range 2010-06-08 (work) - 2010-06-09 (fails)] → [Wrorkround==mailnews.downloadToTempFile=false], [regression range 2010-06-08 (work) - 2010-06-09 (fails)]
It looks like this bug pre dates 3.2 at least on Mac Os.

See The GS topic
Whiteboard: [Wrorkround==mailnews.downloadToTempFile=false], [regression range 2010-06-08 (work) - 2010-06-09 (fails)] → [Wrorkround==mailnews.downloadToTempFile=false], [New problem after fix of bug 387361]
(In reply to comment #35)

Kent James, you still can't reproduce this bug's problem with "filter of move only(no copy)" and "multiple new messages" in your evironment?

If so, it may be timing related problem like; if copy is requested too by filter, copy is executed first, then move step is postponed and problem doesn't happen.
Because my environment for testing is as follows, "move by filter" is executed very quckly than ordinal environment, and filtering of second, third, ... mails happens earlier after filtering of first mail than usual environment.
- I disable virus scan upon file I/O by "real time shield of Avast! 5" for
  Tb's profile directory(all files are in profile) and %temp% directory.
- Only a few filter rules are defined, and only one filter of move is enabled.
- I always check message filter rules before test, then msgFilterrules.dat is
  already read, so delay in load of filter rules by bug 571419 doen't happen
  even first test after restart of Tb. 
> bug 571419 Tb3 issues read request for each one byte of msgFilterRules.dat
- Relatively fast download speed than usual environment. 
  100Mbps eathernet adapter, 100Mbps hab, 70Mbps band width between vdsl modem
  and ISP's switching box, 1Gbps fiber cable to ISP, fast POP3 server of
  other ISP in same country(Japan).
- Very small simple text mail is used for test.
- Other mail related activity by IMAP, News, RSS etc. doesn't exist, because I
  tested with Tb's profile in which only one POP3 server for test is defined.
- No add-on is installed.

If key=0 you stated occurs at very early stage of download only, timing depend problem is suspectd.
If key=0(first mail in folder) is a cause, my test result may be explained.
- When I tested with multipl mails of same size, no garbage was seen in Inbox.
  Test was executed with empty/compacted Inbox, and size of all test mails was
  same, and all downloded mails were moved by filter, so any mail written in
  Inbox could be marked as deleted.
- When I tested with multipl mails of different size, size of mail already
  held in Inbox, size of test mail-1, test mail-2, ... were different.
  In this case, garbage was generated in Inbox(Inbox is corrupted).
  See comment #31, please.
WADA, I haven't looked at this for awhile, so I cannot really comment at the moment on "you still can't reproduce this bug's problem with?" but my comment 35 gives me a hook to understand the issues. If the message key iz zero entering the filter, that could cause all kinds of issues.
(In reply to comment #40)

I tried to check with your FiltaQuilla, so I created new profile by Tb 3.1, installed FiltaQuilla, confirmed "no this bug" with Tb 3.1, and tried Tb trunk, found FiltaQuilla disabled, so removed "custom filter not found" row in filter, and tried to reproduce this bug's problem, then I was unable to re-produce this bug's problem any more. And, nothing was written in Inbox of POP3 account, and all filtered mails are normally written in move target folder.
I could reproduce phenomenn of "You couldn't reproduce problem by presented STR" at last! :-)

So, I checked with trunk build using profile I previously used for test, and problem of comment #31 was easiliy/reliably reproduced.
Big difference of the "previously used profile for test" is;
(a) many dummy POP3 accounts are defined, in addition to a few real accounts.
(b) many local folders are defined at each real/dummy POP3 account and "Local Folders".
(c) large account/server number is used in prefs.js(accountN/serverN).
    account901/server901 to account932/seerver932 (7 pop3 accounts/servers)
    (emulation of many account creations followed by many account deletions)
    account999999/server999999 for "Local Folders"
    (for ease of manual creation of many accounts for test,     )
    (for ease of manual change of account/server/identity number)

Kent James, why problem is produced in my environment may be slowness in finding of or locating to or opening of "move tartget folder". If so, it may explain why mail data is written in Inbox in my test.
See bug 545126 comment #121 for fix verification procedure of bug 545126, please. Cause of bug 545126 was (i) "folder open per a <img> in HTML" + (ii) "long folder open time of each open due to many folders placed before folder to be opened". Fix of that bug was "avoid (i). not open for each <img>", and issue of (ii) remains.
If filter requests folder open for each move, and if many folders exist, filter may experience phenomenon of (ii) as that bug did.
(Correction of comment #41)

For test result with new profile, with minimum definition(1 POP3 only, minimum folders for test of this bug, single filter rule only), no manual modifications.

I could produce problem of comment #31 always. When I reported comment #41, I confused with results of Tb 3.1/downloadToTempFile=true(and false) and trunk/downloadToTempFile=false. Sorry fo my confusion and wrong report.
And, "Leave Messages on Server"=on or off was irrelevant, "many local folders before move target" was irrelevant, manual modification of account/server number was irrelevant.
Why problem is always reproduced in my test seems "move step is executed very very quickly on multiple mails in my test" compared to other people's test or real environment.

Kent James, can key=0 explain why mail data is written in Inbox and why garbled mail data is written in Inbox if multiple mails in comment #31?  
How can I force condition of "it takes longer before move step is executed" in my environment? "filter of copy + move"(no problem after your patch) is sufficient?
Can key=0 explain why this bug started to occur after fix of bug 387361?
Observation on garbage in Inbox.
Length of "garbage part of second/third mail in Inbox" looks length of first mail in Inbox.
- L0 = length of first mail in Inbox, placed at offset=0
  L1 = length of mail-1, L2 = length of mail-2, L3 = length of mail-3
  (length includes header for Unix mox and X-...: headers by Tb) 
- Total length of appended data by filter = L1 + L2 + L3
- written part 1 = whole data for mail-1 (From -...[CRLF]X-Mozilla-Status:...)
  written part 2 = garbage of length = L0
                 + data for mail-2, length = (L2 - L0)
                  (From -...[CRLF]X-Mozilla-Status:...[CRLF]...data_of_mail_2)
  written part 3 = garbage of length = L0
                 + data for mail-3, length = (L3 - L0)
                  (From -...[CRLF]X-Mozilla-Status:...[CRLF]...data_of_mail_3)
- If length of first mail(L0) is larger than filtered mail-2/mail-3(L2/L3),
  garage of length=L1 and garbage of length=L2 looks written.
- Garbage seems 0x00.
- "Merge of three mail's data" is merely a result of lack of [CRLF] at end of
  each written part due to garbage. By it, [CRLF] before "From -..." is lost.

Following data looks written for mail-2(mail-3 too)
  offset=X-L0      offset=X
                   (data for mail-2, data length=L2)
  0x0000...        From - ...[CRLF]X-Mozilla-Status:...[CRLF]...data_of_mail_2
  <--- appended data to Inbox, length=L2 --->
As L0=length of first mail=offset in Inbox at where next mail data is to be written, key=0 may explain above garbage.
I guess key=0 explains "why single entry of offset=0 only at move target folder" and "why Subject is always subject of last arrived/filtered mail".
"Why written to Inbox" is still mystery for me. Phenomenon like next?
  Due to unexpected key=0, filter move internally fails,
  then Tb tries to write to Inbox,
  but due to corrupted/unexpected status caused by the filter move failure,
  Tb appends data at wrong offset in memory to Inbox.
Tested with following condition.
  Inbox : One 1320 bytes mail exists. Compacted.
  Move Target folder : F1 under Local Folders. No mail in it, Compacted.
  Filter rule : If subject starts with test-1, move to F1
  Test mails :
    mail-1 : Subject: test-101, 1346 bytes
    mail-2 : Subject: test-102, 1.3KB
    mail-3 : Subject: test-103, 1.3KB
Build-ID:
> Mozilla/5.0 (Windows NT 5.1; rv:2.0b12pre) Gecko/20110205 Thunderbird/3.3a3pre

Process Monitor log, with Filter of:
  If Path contains \Mail, Include
  If Path contains \Temp, Include

> -------- ---------------- ---------------- --------------- ---- ----
> Sequence Relative Time    Time of Day      Process Name    PID  TID
> -------- ---------------- ---------------- --------------- ---- ----
>             Path                                                          Category Operation     Result       Detail
>             ------------------------------------------------------------  -------- ------------- ---------    ------

(0) ...\Temp\newmsg doesn't exists, then created.
    So, file size of newmsg is ZERO at this step.
(1) mail-1(1346 bytes) is downloaded to ...\Temp\newmsg
(2) mail-1(1346 bytes) is read from ...\Temp\newmsg,
    and 1346 bytes are written to Inbox(offset=1320).

(3) move target folder, F1 is write opened
>     9684 00:00:04.5198141 16:53:10.2474910 thunderbird.exe 4404 1072
>             C:\Documents and Settings\...\Application Data\Thunderbird
>                      \Profiles\o3fb6v7v.Trunk-Test\Mail\Local Folders\F1           IRP_MJ_CREATE SUCCESS      Desired Access: Generic Read/Write, Disposition: OpenIf, Options: Synchronous IO Non-Alert, Non-Directory File, Attributes: n/a, ShareMode: Read, Write, AllocationSize: 0, OpenResult: Opened

(4) Read of ...\Temp\newmsg, instead of Inbox, is issued,
    with "Offset: 1,320, Length: 1,346", 
    even though this file is ...\Temp\newmsg instead of Inbox.
    This is is why nothing is written to move target folder of F1.

    If filer action is "copy to a folder and move to other folder",
    read is properly done to Inbox at copy step.
    And, EXPUNGE bit is properly set for mail data in Inbox by move step.

>     9687 00:00:04.5209383 16:53:10.2486152 thunderbird.exe 4404 1072
>             C:\Documents and Settings\...\Local Settings\Temp\newmsg      Read     IRP_MJ_READ   END OF FILE  Offset: 1,320, Length: 1,346

(4) Close of F1(move target folder), with nothing written to it,
    because previous read of newmsg fails with EOF.
>     9689 00:00:04.5212576 16:53:10.2489345 thunderbird.exe 4404 1072
>             C:\Documents and Settings\...\Application Data\Thunderbird
>                     \Profiles\o3fb6v7v.Trunk-Test\Mail\Local Folders\F1            IRP_MJ_CLOSE  SUCCESS

(5) After it, F1.msf is updated, and phantom mail is crated in F1(no mail data).

I don't check log for "file I/O when garbaled data is written to Inbox for mail-2 and mail-3" yet.

I tested with "Leave Messages on Server" enabled, because I need to use daily use POP3 account for testing.
Kent James, does it affect on problem?
Attachment #510976 - Attachment description: Process Monitor. log. "move only filter" moves arrived all three mails → Process Monitor log. "move only filter" moves arrived all three mails
Lengthy path name is shortened for ease of log viewing.
Attachment #510976 - Attachment is obsolete: true
If filter is "copy to F2, then move to F1", following is executed, and no problem happens.
(1) Downloads mail-1 to newmsg at Offset=0.
    Copy step reads newmsg and appends mail-1 to Inbox,
    and copy step reads the mail-1 in Inbox and appends it to F2.
(2) Downloads mail-2 to newmsg at Offset=0.
    Copy step reads newmsg and appends mail-2 to Inbox,
    and copy step reads the mail-2 in Inbox and appends it to F2.
(3) Downloads mail-3 to newmsg at Offset=0.
    Copy step reads newmsg and appends mail-3 to Inbox,
    and copy step reads the mail-3 in Inbox and appends it to F2.
(4) After all mails are saved in Inbox by Copy step, Move steps are executed.
(4-1) Read mail-1 in Inbox, append to F1, set Expunge flag of mail-1 in Inbox.
(4-2) Read mail-2 in Inbox, append to F1, set Expunge flag of mail-2 in Inbox.
(4-3) Read mail-3 in Inbox, append to F1, set Expunge flag of mail-3 in Inbox.

On the other hand, behavior of "move only filter" is as follows.
(0) Size of existent mail in Inbox = LL
(1) Downloads mail-1 to newmsg at Offset=0 (newmsg is created).
    Move step reads newmsg and appends data of mail-1 to Inbox,
    and move step reads *newmsg* from Offset=LL.
    As read error occurs due to bad offset, Move step doesn't write data to F1.
(2) Downloads mail-2 and appends it to newmsg.
    Offset looks 0 + length of mail-1.
    Downloads mail-3 and appends it to newmsg.
    Offset looks 0 + length of mail-1&mail-2.
(3) Move step reads newmsg for mail-2 but it looks from bad Offset.
    Appends data(Length loooks length of mail-2) to Inbox(garbled data).
    Read *newmsg*(not Inbox) from funny Offset, and read error occurs.
    As read error occurs due to bad offset, Move step doesn't write data to F1.
(4) Move step reads newmsg for mail-3 but it looks from bad Offset.
    Appends data(Length loooks length of mail-3) to Inbox(garbled data).
    Read *newmsg*(not Inbox from funny Offset, and read error occurs.
    As read error occurs due to bad offset, Move step doesn't write data to F1.
(5) Update of F1.msf is seen at step (1), (3), (4),
    but finally remained .msf entry is one for mail-3.
    Because nothing is written to F1, nothing is shown at thread pane
    by "Repair Folder" of F1. 
(6) Update of Inbox.msf is not executed, so mail data appended to Inbox
    is not shown to user.
    Because garbled data of "correct mail-1 + garbled mail-2 + garbled mail-3"
    is appended to Inbox, and because setting EXPUNGE flag in X-Mozilla-Status:
    is not executed or fails, a mail(subject is mail-1's Subject:) is shown
    at thread pane by "Repair Folder" of Inbox.
bug 571693 is marked 3.3=needed, so not requesting it in this bug for this trunk regression
Whiteboard: [Wrorkround==mailnews.downloadToTempFile=false], [New problem after fix of bug 387361] → [Workround: comment 14] [ressession of bug 387361]
...I like the way new features are implemented in tb and I follow various evangelism efforts around the net. I would really like to help by using the latest build available and reporting issues as/if I come across them. So, I installed latest 3.3 nightly again after giving it more than 6 months. Sadly though, I found out the hard way that this bug is still around for like a year in a couple of months. This concerns data loss and is marked as critical too, but surprisingly nobody is assigned to it.

Back to 3.1.x then and perhaps in a couple of years we'll see some serious action here :/
(In reply to comment #49)
> ...I like the way new features are implemented in tb and I follow various
> evangelism efforts around the net. I would really like to help by using the
> latest build available and reporting issues as/if I come across them. 

klonos, you are in a great position to act on your comment and help. bug 571693 needs specific information about how this problem can be reproduced. see bug 571693 comment 15 and prior comments.
This unit test fails if downloadToTempFile is set, and succeeds if it does not. Here are the errors:

TEST-PASS | ../../../../mailnews/fakeserver/pop3d.js | [readFile : 17] true == t
rue
WARNING: NS_ENSURE_SUCCESS(rv, result) failed with result 0x80520012: file c:/tb
/trunk/src/mailnews/local/src/nsPop3Protocol.cpp, line 214
WARNING: NS_ENSURE_TRUE(identity) failed: file c:/tb/trunk/src/mailnews/base/uti
l/nsMsgIncomingServer.cpp, line 1934
Begin mail message delivery.
GetDiskSpaceAvailable returned: 474257813504 bytes
Incorporate message begin:
###!!! ASSERTION: didn't read all of original message in filter move: 'length ==
 0', file c:/tb/trunk/src/mailnews/local/src/nsParseMailbox.cpp, line 2404
xul!nsParseNewMailState::MoveIncorporatedMessage+0x0000000000000531 (c:\tb\trunk
\src\mailnews\local\src\nsparsemailbox.cpp, line 2491)
xul!nsParseNewMailState::ApplyFilterHit+0x0000000000000969 (c:\tb\trunk\src\mail
news\local\src\nsparsemailbox.cpp, line 2051)
xul!nsMsgFilterList::ApplyFiltersToHdr+0x000000000000027C (c:\tb\trunk\src\mailn
ews\base\search\src\nsmsgfilterlist.cpp, line 359)
xul!nsParseNewMailState::ApplyFilters+0x00000000000001C3 (c:\tb\trunk\src\mailne
ws\local\src\nsparsemailbox.cpp, line 1943)
xul!nsParseNewMailState::PublishMsgHeader+0x0000000000000564 (c:\tb\trunk\src\ma
ilnews\local\src\nsparsemailbox.cpp, line 1878)
xul!nsPop3Sink::IncorporateComplete+0x000000000000086F (c:\tb\trunk\src\mailnews
\local\src\nspop3sink.cpp, line 896)
xul!nsPop3Protocol::HandleLine+0x0000000000000235 (c:\tb\trunk\src\mailnews\loca
l\src\nspop3protocol.cpp, line 3568)
xul!nsPop3Protocol::RetrResponse+0x0000000000000397 (c:\tb\trunk\src\mailnews\lo
cal\src\nspop3protocol.cpp, line 3354)
xul!nsPop3Protocol::ProcessProtocolState+0x00000000000006B4 (c:\tb\trunk\src\mai
lnews\local\src\nspop3protocol.cpp, line 3975)
xul!nsMsgProtocol::OnDataAvailable+0x0000000000000043 (c:\tb\trunk\src\mailnews\
base\util\nsmsgprotocol.cpp, line 387)
xul!nsInputStreamPump::OnStateTransfer+0x000000000000023C (c:\tb\trunk\src\mozil
la\netwerk\base\src\nsinputstreampump.cpp, line 510)
Assignee: nobody → kent
Status: NEW → ASSIGNED
Attachment #527337 - Flags: review?(dbienvenu)
Blocks: 571693
No longer depends on: 571693
Attached patch tweak prev patchSplinter Review
Hi Kent, thx for fixing this. I've taken your previous patch and tweaked it a bit - since we don't really support having a different path argument to the new mail parser, and it will always be the file for the folder we're downloading to, it's less confusing to just not pass that argument in. (I wanted to make sure this approach would work, which is why I created the patch).

If you incorporate that change, and fix this space before <:

+  nsCOMPtr <nsIInputStream> inboxInputStream;

and use Services.jsm to get prefs, instead of getService,

e.g.,
Components.utils.import("resource://gre/modules/Services.jsm");

Services.prefs.getBoolPref...
then r=me.
Comment on attachment 527337 [details] [diff] [review]
don't confuse parser with temp download issues

r=me, with the prev comments addressed.
Attachment #527337 - Flags: review?(dbienvenu) → review+
Status: ASSIGNED → RESOLVED
Closed: 13 years ago
Resolution: --- → FIXED
Target Milestone: --- → Thunderbird 3.3a4
follow on fix for movemail pushed - http://hg.mozilla.org/comm-central/rev/0707a29119be
Checked test case of my comment #44 etc. with official Tb 5.0 release build.
I couldn't reproduce problem of this bug any more => VERIFIED.
Status: RESOLVED → VERIFIED
Depends on: 668952
You need to log in before you can comment on or make changes to this bug.