387361 - msg copy action to imap on incoming pop3 mail fails with quarantining turned on for antivirus (quarantine option=on/mailnews.downloadToTempFile=true, COPY to any of IMAP folder and local mail folder)

Status: RESOLVED FIXED

(MailNews Core :: Filters, defect)

Description

[David :Bienvenu]

1. Set up a filter to copy an incoming pop3 message to an other local folder.
2. Turn on message quaranting in tools | options |privacy | anti-virus
3. Send yourself a msg that triggers the filter.

The message won't be copied successfully. I tried this with the global inbox turned on, but I don't think that matters.

Comment 1

[Wayne Mery (:wsmwk)]

David, can you reproduce?
WFM filtering on subject 
Mozilla/5.0 (Windows; U; Windows NT 5.1; en-US; rv:1.9.1b4pre) Gecko/20090423 Shredder/3.0b3pre

Comment 2

[[:Aureliano Buendía]]

I agree to comment #1: WFM here on

Mozilla/5.0 (Windows; U; Windows NT 5.1; en-US; rv:1.9.1.2pre) Gecko/20090729 Lightning/1.0pre Shredder/3.0b4pre ID:20090729051958

I try:
1. with filter apply to account [A] (not in local folders) and sending a mail fom local folders account [B] and moving incoming mail to another account [C] (not in local folders)

2. with filter apply to account (in local folder) [A] and sending a mail from account [B] not in local folder and moving incoming mail to folder located in local folder.

Anyone can confirm that work?

Comment 3

[Kent James (:rkent)]

Attachment: unit test, WFM but leaks

Since I'm in the middle of creating unit tests involving local folders and filtered copies, it was real easy to adapt one as a test for this. Test passes with current trunk.

Might as well add it to the tree - but this test leaks as reported in bug 507285. I'm not sure what the policy is in adding leaking tests.

Comment 4

[David :Bienvenu]

Comment on attachment 391623 [details] [diff] [review]
unit test, WFM but leaks

thx for the test. Let's hold off landing this until the underlying leak is fixed.

Comment 5

[Kent James (:rkent)]

I'm changing the assign to myself, since this has morphed into a unit test that confirms that the bug should be WFM (and I had lost track of its existence.)

Comment 6

[Kent James (:rkent)]

The underlying leak was fixed long ago in bug 507285. I just reran this test, it works, and does not seem to leak anymore.

Would there by any objections to me landing the already approved unit test patch, and closing this bug?

Comment 7

[David :Bienvenu]

no, sounds good, thx.

Comment 8

[Kent James (:rkent)]

Comment on attachment 391623 [details] [diff] [review]
unit test, WFM but leaks

Checked in http://hg.mozilla.org/comm-central/rev/6b54b36e5e35

Comment 9

[Kent James (:rkent)]

I'm going to mark this bug "Resolved - Fixed" and change the summary slightly to indicate that the bug has been morphed into writing a test for a function. Feel free to complain if that doesn't work for you.

Comment 10

[Mark Banner (:standard8)]

Backed out due to test failures (hangs) across all trunk tinderboxes (c-c plus m-c):

http://hg.mozilla.org/comm-central/rev/624f41b4f599

c-c plus m-1.9.2 seemed fine, but I couldn't see anything that was branch dependent at a quick glance.

Comment 11

[Nils Lohner]

I saw this in 3.0.2 beta1 ... reported in Bug 545082 (feel free to mark it as a dupe of this one).

Comment 12

[Kent James (:rkent)]

(In reply to comment #11)
> I saw this in 3.0.2 beta1 ... reported in Bug 545082 (feel free to mark it as a
> dupe of this one).

Nils, this bug does not currently have any known ways to reproduce, and the test was supposed to show that it is not an issue. The bug as defined is local->local copies, while I think your issue was local->IMAP.

So this bug needs to be either broadened to include the local->IMAP case, or we need a new bug (or morph one of your other bugs.)

Comment 13

[WADA:World Anti-bad-Duping Agency]

(In reply to comment #12)
> this bug does not currently have any known ways to reproduce, (snip)

Procedure of of comment #0 to reproduce this bug is still effective.

(Filter rules for pop.ops.dti.ne.jp)
> name="test-1-Add-TAG" enabled="yes" type="17"
>   action="AddTag" actionValue="test-1"
>   condition="AND (subject,begins with,test-1)"
> name="test-1-Copy-POP" enabled="yes" type="17"
>   action="Copy to folder"
>   actionValue="mailbox://[e-mail]/Inbox/test-1"
>   condition="AND (subject,begins with,test-1)"
> name="test-1-Move-IMAP" enabled="yes" type="17"
>   action="Move to folder"
>   actionValue="imap://[e-mail]/INBOX/F1"
>   condition="AND (subject,begins with,test-1)"

(0) Send two mails to muttley @ ops.dti.ne.jp.
    mail-1=Subject: test-1-A, mail-2=Subject: test-1-B
(1) Get Msgs
  (Tb 3.0.1 on Ms Win-XP, Qurantine option=enabled)
  (Fetch header only=Off, no download mail size limitation)
  (Leave message on server=On, as the POP3 account is for my daily use by Sm2)
(2) Two mails appeared in Inbox(unread mail count=2)
(3) Only one mail appeared at thread pane of Inbox/test-1, Subject=test-1-B
    (.msf entry of only last mail is created at copy-target/local folder)
    View/Messages Source : Nothing was displayed.  
    tag-1 was added to the mail (bug 355537 doesn't occur)
(4) After a while, two mails disappeared from local Inbox.
    Two mails appeared at IMAP Inbox/F1 folder.
    tag-1 was added (bug 355537 doesn't occur).
    => Unable to reproduce Bug 545082 by above message filter rules.

Kent James, did you check copied mail data in copy target folder?
If single test mail only, "last mail only at copy target folder" can't be observed. Check with multiple test mails, please.

To Nils Lohner:
As I wrote above, I couldn't reproduce your Bug 545082. Can you add detailed "steps to reproduce" to Bug 545082 with appropriate bug summary for IMAP case?

Comment 14

[WADA:World Anti-bad-Duping Agency]

Note:
In my test, "Global Search and Indexer" was disabled. I checked both Inbox/F1(offline use=on) and Inbox/F2(offline use=off), and no difference was observed.

Comment 15

[Kent James (:rkent)]

WADA: no, I have not tried multiple emails. I'll try to give that a try. Do you know if one of the folders needs to be IMAP, or does it also fail if all of the folders are Local (easier to write the XPCSHELL test if I don't have to use IMAP).

Comment 16

[WADA:World Anti-bad-Duping Agency]

(In reply to comment #15)

"move to IMAP folder" part is only to check Bug 545082. Only "copy to local folder" with qurantine opion=on is needed. "add tag" part is merely to see "mail is really filtered" easily. 
As I have two free Gmail accounts for IMAP testing, I'll check "copy to IMAP folder" case. (I recomend you to get free Gmail account for ease of test.)

Comment 17

[Nils Lohner]

Steps to reproduce are posted in https://bugzilla.mozilla.org/show_bug.cgi?id=545082#c33  

I would assume that it doesn't make a difference whether the destination is local folders or IMAP but let's test:

- filtering from the POP3 inbox to another (local) folder in that account works fine
- filtering from the POP3 inbox to a folder in Local Folders works fine
- filtering from the POP3 inbox to a folder in the IMAP server does not work and yields Bug 545082

OK, so much for my assumptions ;)

Let me know if you need anything else.

Comment 18

[WADA:World Anti-bad-Duping Agency]

(In reply to comment #17)
> and yields Bug 545082

Bug 545082 is "move to IMAP folder" case(you said no "Copy to" action).
Nils Lohner, is your test result of "to local folder" in comment #17 for "Move to" case? Or "Copy to" case? (This bug is for "Copy to" case, never for "Move to" case.)

Comment 19

[Nils Lohner]

@WADA I have only MOVE TO actions in my filters, no copying at all, please see the filter that I pasted into the other bug at https://bugzilla.mozilla.org/show_bug.cgi?id=545082#c13

Comment 20

[WADA:World Anti-bad-Duping Agency]

(In reply to comment #19)
> @WADA I have only MOVE TO actions in my filters, no copying at all, (snip)

Nils Lohner, if so, please don't add comments for "Move to" cases to this bug (this bug is only for "Copy to" case) any more, please. "Move to IMAP" && "Source Folder=POP3" && "Quarantine option=On" case is your Bug 545082. Let's analyze your "Move to IMAP" case in that bug, instead of this bug which is only for "Copy to" case.

Comment 21

[Nils Lohner]

(In reply to comment #20)
> Nils Lohner, if so, please don't add comments for "Move to" cases to this bug
> (this bug is only for "Copy to" case) any more, please. "Move to IMAP" &&
> "Source Folder=POP3" && "Quarantine option=On" case is your Bug 545082. Let's
> analyze your "Move to IMAP" case in that bug, instead of this bug which is only
> for "Copy to" case.

Sorry, you commented that the IMAP MOVE is a COPY then DELETE ... which is why I commented here as well.

Comment 22

[David :Bienvenu]

(In reply to comment #16)
> (In reply to comment #15)
> 
> "move to IMAP folder" part is only to check Bug 545082. Only "copy to local
> folder" with qurantine opion=on is needed. "add tag" part is merely to see
> "mail is really filtered" easily. 
> As I have two free Gmail accounts for IMAP testing, I'll check "copy to IMAP
> folder" case. (I recomend you to get free Gmail account for ease of test.)

One thing to be aware of is that filter moves on incoming mail happen synchronously, which is why they work. It's the async operations like copy, or move to an imap folder that cause problems.

Comment 23

[WADA:World Anti-bad-Duping Agency]

(In reply to comment #21)
> you commented that the IMAP MOVE is a COPY then DELETE ...

I didn't(can't) say "is"(wrote "looks equivallent to" instead), as I don't know design. According to comment #22, the "equivallence" I thought seems "asynchronous or synchronous".
a. Move to local folder/same POP3 account: Synchronous
b. Copy to local folder/same POP3 account: Asynchronous
c. Move to IMAP folder: "server connection and select if required, and append"
                        step is same as "copy from local to IMAP", and seems
                        asynchronous. (how about "delete from local" step?)
b. is simplest case and is this bug. c.(your bug) is complex case than b.

Comment 24

[Kent James (:rkent)]

Attachment: test case that fails

This is a variation of test_localToImapFilter.js, with quarantining enabled, that fails and presumably demonstrates this bug. That is good for debugging. Unfortunately the original bug was disabled due to intermittent failures.

Comment 25

[Kent James (:rkent)]

I've spent a bit of time looking at this, and here's a summary.

The quarantining code, which copies the message to a temporary file, tries to avoid adding that message back into the main mbox prior to filtering. Instead it tries to trick the filters into using the temporary file as the "inbox" with tricks like setting the message key to 0 temporarily, and passing the temporary file as the folder location. But this trick does not survive all filter actions, and in particular is failing for the imap folder copy. The imap folder copy ultimately sees a string request to copy from the local inbox folder with message key of 0, which fails.

It seems to me the cleanest way to fix this would be to go ahead and remove this trickery, and just move the message from the temp file to the mbox prior to running message filters.

But I don't really know the motivation for the trickery in the first place. Is this just some sort of performance optimization, trying to eliminate one move of the message in the case where the filter is going to move it again? Or is there some other reason for it?

Comment 26

[David :Bienvenu]

(In reply to comment #25)

> But I don't really know the motivation for the trickery in the first place. Is
> this just some sort of performance optimization, trying to eliminate one move
> of the message in the case where the filter is going to move it again? Or is
> there some other reason for it?

The performance optimization is part of it. The other motivation is that delaying the move back to the mbox gives the virus checker as much time as possible to decide the message has a virus and only destroy the temp file, not the mbox. Reasoning about virus checkers is not a fruitful exercise, however, and the trickery is massively painful, so I could get behind your idea for fixing it.

Comment 27

[Kent James (:rkent)]

Attachment: Remove the trickery

I updated the test to use the async and new IMAPpump frameworks.

The patch attempts to remove all of the trickery associated with trying to use the temp file in the filters. The effects of this on antivirus vendors is hard to determine, but there is enough of a risk of issues that this should probably not be considered for 3.0.x, even though it is a bug fix.

Comment 28

[David :Bienvenu]

Attachment: fix movemail so this compiles on mac/linux

this makes the movemail code compile.

Comment 29

[David :Bienvenu]

Attachment: log file of test hand on mac

I tried running this test on the mac - it hung with the attached log...

Comment 30

[David :Bienvenu]

I should say - the test eventually succeeds but it takes a couple minutes, which seems wrong.

Comment 31

[David :Bienvenu]

+        // we need to clone because nsLocalFileUnix caches its stat result,
+        // so it doesn't realize the file has changed size.

I know you just changed the indentation, but it's nsLocalFileWin that caches the stat result, not Unix, afaict. I'm happy with the patch, but I'd really like to know why the test takes two minutes.

Comment 32

[Kent James (:rkent)]

I don't have any way currently to test this on a Mac to see this. Do you have any suggestions of how to move forward?

Comment 33

[WADA:World Anti-bad-Duping Agency]

Attachment: Process Monitor log of Tb 3.0, backup of test-1.msf, for test case of comment #13

Downloaded mails in test.
1. A spam mail(remains in Inbox)
2. Subject=test-1-A, body=test-1-A[CRLF]
3. Subject=test-1-B, body=test-1-B[CRLF]test-1-B[CRLF]
4. Subject=test-1-C, body=test-1-C[CRLF]test-1-C[CRLF]test-1-C[CRLF]

Files.
(1) Process monitor log(CSV) for download.
    "Get Msgs" to "unread count=3 at folder pane". 
    Filter: If process name=thunderbird.exe, Include.
            No other rule, so all file I/O by Tb is logged. 
    Unread mail count=3 is shown at folder pane.
(2) test-1.msf after download. test-1-A.msf, size=4,515 bytes.
    file size of test-1=0.
(3) test-1.msf after folder open(click test-1). test-1-B.msf, size=3,440 bytes.
    file size of test-1 is still 0.
    Unread mail count=1 is shown at folder pane.
    Thread pane shows test-1-C only.

(Observation)
1. Mail data is not appended to test-1.
2. At step (2), three mails are seen in .msf.
   However, only one mail(test-1-C) is seen after folder open, step (3).
   Where have test-1A/test-1-B gone?

Filter copy tries to copy from Inbox at where mail data is not written yet instead of ...\Temp\newmsg?
Filter copy is scheduled too early?

By the way, read of each one byte of \msgFilterRules.dat is seen in Process Monitor log. By design?

Comment 34

[WADA:World Anti-bad-Duping Agency]

Filter log never helps diagnosis. David, is enhancement like next possible?
1. Add timetamp.
2. Add UIDL if POP3, UID if IMAP.
3. Add offset data(POP3) or UID(IMAP) to log for Copy/Move.
4. If something wrong happens after current filter log write for copy/move,
   write the incident of the something wrong in filter log.
5. NSPR logging or optional Error Console message for message filter activity.

Comment 35

[WADA:World Anti-bad-Duping Agency]

Attachment: Reduced Process Monitor log(access of profile directory, temp directory, removal of huge log for msgfilterRules.dat)

Comment 36

[David :Bienvenu]

WADA, we have a patch that should fix the bug, so I don't think we need more diagnosis.

rkent, I'm not sure what to do about the mac test. I'll go make sure the problem doesn't also happen on windows.

Comment 37

[David :Bienvenu]

rkent, the test is just as slow on Windows. A couple minutes at least. The test hangs here:

TEST-PASS | ../../mailnews/fakeserver/pop3d.js | [readFile : 17] true == true
WARNING: NS_ENSURE_SUCCESS(rv, result) failed with result 0x80520012: file C:/mo
zilla-build/msys/tbirdhq/mailnews/local/src/nsPop3Protocol.cpp, line 214
WARNING: NS_ENSURE_TRUE(identity) failed: file C:/mozilla-build/msys/tbirdhq/mai
lnews/base/util/nsMsgIncomingServer.cpp, line 1941
Begin mail message delivery.
GetDiskSpaceAvailable returned: 159301271552 bytes
Incorporate message begin:
msgAdded to folder <Inbox> subject <[Bug 397009] A filter will let me tag, but n
ot untag>
Incorporate message complete.
End mail message delivery.
TEST-PASS | ../../mailnews/resources/POP3pump.js | [OnStopRunningUrl : 53] 0 ==
0
waiting for POP3Pump done
TEST-INFO | (xpcshell/head.js) | test 3 finished
TEST-INFO | (xpcshell/head.js) | test 2 finished

Seems odd that test 2 should finish after test 3...

Comment 38

[David :Bienvenu]

Comment on attachment 448424 [details] [diff] [review]
fix movemail so this compiles on mac/linux

reluctantly minusing based on test slowness - I suspect the test is timing out instead of finishing cleanly, and we really need clean tests.

Comment 39

[Kent James (:rkent)]

OK I'll try to duplicate this on Windows.

Comment 40

[David :Bienvenu]

Let me know if I can help - perhaps the pop3pump is taking a long time to shutdown. I'd like to get this in soon because it's going to cause conflicts with my pluggable storage work, but perhaps also simplify some edge cases, and I'd like to get that resolved soon.

Comment 41

[Kent James (:rkent)]

Attachment: use function for onDone

do_timeout no longer accepts strings.

Comment 42

[David :Bienvenu]

Comment on attachment 449700 [details] [diff] [review]
use function for onDone

great, thx. Does this mean an error was getting swallowed and not dumped to the console?

Comment 43

[Kent James (:rkent)]

I have found that timeouts frequently stop the test without generating errors. I think that is what was happening here. I don't know if that is my code or inherent in the infrastructure, but it is obviously not ideal. I'm pretty sure though that it is not unique to this test and bug.

Comment 44

[Kent James (:rkent)]

Comment on attachment 449700 [details] [diff] [review]
use function for onDone

Checked in http://hg.mozilla.org/comm-central/rev/c921c5d17a30

Comment 45

[Matthias Bockelkamp]

I think this checkin broke msg filters for POP3. I've been seeing a problem with my message filters for some time now: An incoming message is at first stored in Inbox, then my message filter tries to copy it to its destination folder. The result is, that the message disappears from Inbox and shows up in the destination folder (as expected) - but it cannot be opened. Source view shows nothing. After starting repair folder on both Inbox an the filter's destination folder, the message is again shown in Inbox, where it can now be opened normally, and its entry in the filter's destination folder disappears.

I today tried to track down the date on which the bug was introduced. Nightly 2010-06-08-01-comm-central-trunk.zip works as expected while nightly 2010-06-09-01-comm-central-trunk.zip shows the bug as described. The comm-central pushlog tells me that between 2010-06-08 00:00:00 and 2010-06-09 00:00:00 only two checkins happened: One for this bug and one for bug 479200.

So I come to the conclusion, that probably this checkin caused the bug.

Comment 46

[Kent James (:rkent)]

Do you have an anti-virus program active, and if so which one? Do you have quarantining selected?

Comment 47

[Matthias Bockelkamp]

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.

Comment 48

[Kent James (:rkent)]

The status of the patches in this bug got confused by the reopening (which is a good reason to not reopen bugs that have patches checked in).

What was checked into 1.9.2 (and TB 3.1) was simply a test. The later attachment 449700 [details] [diff] [review] was only checked into trunk, and is not in TB 3.1  Since that is the patch that could affect the actual application, I'm going to remove the 3.1 status to make that clearer.

Comment 49

[WADA:World Anti-bad-Duping Agency]

changing target milestore too per coment #48.