424876 - Spam processing sometimes skipped on IMAP folders

Status: RESOLVED WORKSFORME

(MailNews Core :: Filters, defect)

Description

[Kent James (:rkent)]

Ever since I configured Thunderbird to display whether emails have received spam processing or not, I have noticed that about 20% of the messages in a particular IMAP account are never processed by the Junk filtering. The IMAP folder being accessed is on Exchange 2003, and has several hundred milliseconds of latency since it is across the Atlantic from me.

In the normal Thunderbird configuration, an unprocessed email looks just like a HAM email, so most people will not notice this even if it is occurring. So to see this, you need to add a trivial CSS change to use a different icon for unprocessed emails. In my case, because I am also routinely displaying junkstatusorigin and junkpercent from my patch for bug 366491, it is really obvious.

Each morning, this account receives a standard organization news email, which is often the first email that I receive every morning. This email virtually never is spam filtered. Other emails also are not filtered sometimes, so it is not unique to this particular email.

I have an IMAP log running now, which I will post when I catch it in the act.

I am currently using a custom Thunderbird build based on a March 14, 2008 CVS trunk download.

Comment 1

[Kent James (:rkent)]

Attachment: IMAP log when junk processing is skipped

Comment 2

[Kent James (:rkent)]

Attachment: IMAP log when junk processing succeeds

For comparison, this attachment shows the IMAP log for the next message, where the junk processing succeeded. Between these two logs, I shut down and restarted TB so that I could copy the logs.

Comment 3

[WADA:World Anti-bad-Duping Agency]

(A) IMAP log when junk processing succeeds
> S-INBOX:SendData: 9 UID fetch 918 (UID RFC822.SIZE FLAGS BODY.PEEK[HEADER.FIELDS (From To ... (snip)
> S-INBOX:CreateNewLineFromSocket: * 811 FETCH (UID 918 RFC822.SIZE 5704 ... (snip)
>(snip)
After FETCH fo HEADER.FIELDS, fetch for body is requested.
> S-INBOX:SendData: 10 UID fetch 918 (UID RFC822.SIZE BODY.PEEK[])
Other headers such as Received:, mail body text, some mime part's data are downloaded. And finally, "close boundary" line is downloaded.  
> S-INBOX:CreateNewLineFromSocket: --=_alternative 00529D8485257418_=--
So whole mail data is downloaded in this case.

(B) IMAP log when junk processing is skipped
> S-INBOX:SendData: 9 UID fetch 917 (UID RFC822.SIZE FLAGS BODY.PEEK[HEADER.FIELDS (From To ... (snip)
> S-INBOX:CreateNewLineFromSocket: * 810 FETCH (UID 917 RFC822.SIZE 35869 ... (snip)
After FETCH fo HEADER.FIELDS, fetch for body is not requested, so additional mail headers such as Received:, body text etc. are not downloaded.

When (B), no additional header / no additional body data is available for client side Junk filtering.
It looks to be similar situation to Bug 184490 (filter for customized header doesn't work).

UID 918(A) : RFC822.SIZE 5704. UID 917(B) : RFC822.SIZE 35869.  
Depends on mime_parts_on_demand / fetch_by_chunks setting?
> mail.imap.mime_parts_on_demand           (default=true)
> mail.imap.mime_parts_on_demand_max_depth (default=15)
> mail.imap.mime_parts_on_demand_threshold (default=30000)
> mail.imap.fetch_by_chunks                (default=true)
> mail.imap.chunk_size                     (default=10240)
See following MozillaZine Knowledge Base article for above options.
> http://kb.mozillazine.org/Entire_message_fetched_when_opening_a_IMAP_message

Comment 4

[Kent James (:rkent)]

Yes the IMAP log confirms that when junk processing fails, the body is not requested. But why? These logs were taken within minutes of each other, with the same configuration, and on very similar messages. Something is messing up the logic in IMAP so that it decides to skip the body download sometimes.

I am tempted to add some additional logging statements to IMAP that log critical decisions that are made that might be affecting this. I see this problem several times a week reliably, so with enough logging I should be able to track it down.

Unfortunately it is blocking my attempts to make spam processing more visible. This is a hidden bug for most people, as it just looks like the junk filter did not perform correctly.

Bug 184490 describes a design decision that creates a reliable change in what works and what doesn't. I doubt it is related to this intermittent problem.

Comment 5

[WADA:World Anti-bad-Duping Agency]

(In reply to comment #4)
> the body is not requested. But why?
> Something is messing up the logic in IMAP so that it decides to skip the body download sometimes.

Comment in logic for "Message filter with customized header" and "Junk filter" says "requests download of body for filtering". And Bug 184490 is regression - started to occur at a point in the past. So something wrong in message/junk filter is suspected in your problem too.

> I doubt it is related to this intermittent problem.

Does "intermittent problem" mean some other IMAP mails like above (B), larger mail than mime_parts_on_demand_threshold==30000, are sometimes filtered correctly, or some other smaller mail like (A) are sometimes not filtered? 
Is there any characteristic in "20% of the messages not filtered by Junk filter"? 
In your case, (B) in log is larger than mime_parts_on_demand_threshold. So next bug is also a suspect.
> Bug 405437 IMAP mail are not cached for offline use if message size is bigger than mail.imap.mime_parts_on_demand_threshold 

Comment 6

[Drew]

When clicking the spam icon to mark as spam and move to the Spam folder, only the first message gets moved, and the rest sit around in the Inbox folder.  Once the first message have moved to the Spam folder, then additional messages can be marked as spam.  This is really annoying because I have to click to mark as spam, wait a couple seconds for the message to move over to the Spam folder, then click the next one, and so on and so forth, so to process 50 spam messages as you can imagine is quite tedious!!

Comment 7

[Kent James (:rkent)]

(In reply to comment #6)
> When clicking the spam icon to mark as spam and move to the Spam folder, only
> the first message gets moved, and the rest sit around in the Inbox folder. 
> Once the first message have moved to the Spam folder, then additional messages
> can be marked as spam.  This is really annoying because I have to click to mark
> as spam, wait a couple seconds for the message to move over to the Spam folder,
> then click the next one, and so on and so forth, so to process 50 spam messages
> as you can imagine is quite tedious!!
>
What you are describing is unrelated to the current bug. But to reply, there are plenty of UI options available to you. Simply select all of the messages that you want to junk, then hit the "Junk" toolbar button. That should address your issue.

If you want to followup this discussion, you should really file a new bug - though this sounds to me more like a user support question than a bug.

Comment 8

[Wayne Mery (:wsmwk)]

rkent, does wada's last comment stick?

Comment 9

[Kent James (:rkent)]

(In reply to comment #8)
> rkent, does wada's last comment stick?

Unfortunately I no longer work for that particular client, so  am unable to confirm whether his suggestions make sense. Since nobody else has seen this, and I can't help move it forward, let's change it to WFM.