935934 - Filter log don't give infos about filtered mails (No From:/Subject:/Message-ID: data and 1970/01/01 as Date in filter move log, when "Filter before Junk Classification" is used )

Status: RESOLVED FIXED

(MailNews Core :: Filters, defect)

Description

[Alain AUPEIX]

User Agent: Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:25.0) Gecko/20100101 Firefox/25.0 (Beta/Release)
Build ID: 20131028113308

Steps to reproduce:

The filter is executed, but there is no valuable information in the log file.



 


Actual results:

Filtre « Harbour » appliqué au message de - le 01/01/1970 01:00:00 message id = déplacé vers mailbox://[e-mail]/harbour

Filtre « Gramps » appliqué au message de - le 01/01/1970 01:00:00 message id = déplacé vers mailbox://[e-mail]/Gramps

Filtre « Gramps » appliqué au message de - le 01/01/1970 01:00:00 message id = déplacé vers mailbox://[e-mail]/Gramps

Filtre « Copains » appliqué au message de - le 01/01/1970 01:00:00 message id = déplacé vers mailbox://[e-mail]/Copains-Copines

Filtre « Gramps » appliqué au message de - le 01/01/1970 01:00:00 message id = déplacé vers mailbox://[e-mail]/Gramps 


Expected results:

I think it's obvious, the log ought to have:
- the sender
- the real date
- the message ID

Comment 1

[WADA:World Anti-bad-Duping Agency]

Phenomenon is same as bug 762318.

All logs has time stamp of "01/01/1970 01:00:00"?
"Filter move by filter name written in log" is normally executed and some mails are actually moved to "mail folder written in log" from Inbox as expected?
Do you see your problem with Tb's -safe-mode? (addon disabled)
When did your problem start to occur? Just after upgrade of Tb?
Do you use Global Inbox? (Account Settings/Server Settings/Advanced)
Do you enable "Quarantine" option? (mailnews.downloadToTempFile=true)
Do you have IMAP accounts too? If yes, does your problem occur on IMAP account?
Do you request both "Copy to folder" and "Move to folder" o same mail in filter deinition?
Do you use "Delete" action or "Stop Filter Execution" action in your message filter rules?

Can following be workaround in your case? 
  "Set Junk Status to/Not Junk" action in all filter rules which requests "Move to folder" 

Is workaround of that bug(bug 762318, "After Classification") effective in your case too?

Comment 2

[Alain AUPEIX]

1- "Filter move by filter name written in log" is normally executed and some mails are actually moved to "mail folder written in log" from Inbox as expected?
Yes, all the moves are realized.
Since a few time, I have some errors concerning some moves where the target path is not the good, but as the infos aren't served in log, I'm not able to precise which are concerned. I just notice that often, the sender is the same, and it's when the mail has an pdf attachment. But it's not the reason of this bug, and I prefer first solve this one, to have more infos for the second one.

2- Do you see your problem with Tb's -safe-mode? (addon disabled)
I haven't tried, i will do it and report.

3- When did your problem start to occur? Just after upgrade of Tb?
I can't say.

4- Do you use Global Inbox? (Account Settings/Server Settings/Advanced)
No, but if I have more than one count, I have all separated, and I have some rules which moves from one count to a folder of the first count.

5- Do you enable "Quarantine" option? (mailnews.downloadToTempFile=true)
I don't know. If it's related to anti-virus, it's no

6- Do you have IMAP accounts too? If yes, does your problem occur on IMAP account?
No

7- Do you request both "Copy to folder" and "Move to folder" to same mail in filter definition?
No, all my rules are 'move to', except one which also 'transfert to'

8- Do you use "Delete" action or "Stop Filter Execution" action in your message filter rules?
No

9- Can following be workaround in your case? 
  "Set Junk Status to/Not Junk" action in all filter rules which requests "Move to folder"
I don't understand the question. 

10-  Is workaround of that bug(bug 762318, "After Classification") effective in your case too?
Humm, it seems that this bug is exactly mine, and perhaps as said by  Ole Junker 2013-06-10 16:46:40
is the solution. All my rules have this parameter.
I will try it and report as soon as I can.

A+

Comment 3

[Alain AUPEIX]

Hourra ... 
I change all the parameters to apply rules after searching for spam
After having clear the log, I launch 'Apply filters on the folder'
Le log file contains all the result of the moves, and all the fileds are served, date, sender, ID ...

Thanks a lot.
A+

Comment 4

[WADA:World Anti-bad-Duping Agency]

(In reply to Alain AUPEIX from comment #2)
> > 9- Can following be workaround in your case? 
> >  "Set Junk Status to/Not Junk" action in all filter rules which requests "Move to folder"
> I don't understand the question. 

I don't understand your answer...
In filter rule definition panel, action of "Set Junk Status to" surely exists, and "Junk" or "Not Junk" can be selected for "action of "Set Junk Status to".
Even if you use non en-US build of Tb, and even if you are general user, I believe any one can find it at filter defiition panel of Tb, if you are actually using Tb by your self...

By following pretty simple test for other bugs which is relevant to "filter move"(with Tb 24.3.0),
> 1. Put a mail in Mbox of POP3 server, whose Subject starts with "???".
>   (Web mail, IMAP, POP3 is supported by my ISP, simply "copy a mail to Inbox via IMAP" :-)
> 2. Filter rule : Only next rule only is enabled, in order to make it simple, obvious.
>      "Filter before Junk Classification"
>      If Subject begins with "???",
>         Set Junk Status to / "Not Junk"
>         Move to folder named XXX
> 3. Get Msg
next log was obtained for each "filter moved mail".
> filterlog.html content.
>   (a "set of logs" == "next two logs". 'the "set of logs" per a mail' is writen by Tb)
> (i) Log for "Set Junk Status to" of a mail.
> <p>
> Applied filter &quot;(New, before) Subject begins with: Biff,Move to Sent&quot;
>   to message from &quot;M. Wada&quot; &lt;[e-mail]&gt;
>   - Biff-XYZ Test 001 123 at 2013/07/11 09:31:33
> junk score
> </p>
> (ii) Log for "Move to folder" of a mail.
> <p>
> Applied filter &quot;(New, before) Subject begins with: Biff,Move to Sent&quot;
>   to message from  
>   -  at 1970/01/01 09:00:00
> moved message id =  
>   to mailbox://[e-mail]/Sent
> </p>
Phenomenon is;
  When log for "Set Junk Status to" is written, Tb can get mail data for filter log.
  When log for "Move to folder" is written, Tb fails to fiｎd mail data.
If "Move to folder" only, (i) is not logged and obly (ii) is visible, so it's mystery. 
If (i) is visible, it's not mystery :-)

This is irrelevant to Qurantine option.
  (Tools/Opions/Security/AntiVirus, mailnews.downloadToTempFile=true/false)
This is problem upon "mail download" only. No problem when "manual message filter run".

This is relevant to "Filter before/after Junk Classification" setting. 
If  "Filter after Junk Classification", following log was obtained for two downloaded/moved mails.
> (1) Log for "Set Junk Status to" of two mails.
> <p>
> Applied filter &quot;(New, before) Subject begins with: Biff,Move to Sent&quot;
>   to message from [e-mail]
>   - Biff-XYZ Test 000 000 at 2013/07/11 09:31:33
> junk score
> </p>
> <p>
> Applied filter &quot;(New, before) Subject begins with: Biff,Move to Sent&quot;
>   to message from &quot;M. Wada&quot; &lt;[e-mail]&gt;
>   - Biff-XYZ Test 001 123 at 2013/07/11 09:31:33
> junk score
> </p>
> After (1), (2) Log for "Move to folder" of two mails.
> <p>
> Applied filter &quot;(New, before) Subject begins with: Biff,Move to Sent&quot;
>   to message from [e-mail]
>   - Biff-XYZ Test 000 000 at 2013/07/11 09:31:33
> moved message id = [e-mail].001.001.000
>   to mailbox://[e-mail]/Sent
> </p>
> <p>
> Applied filter &quot;(New, before) Subject begins with: Biff,Move to Sent&quot;
>   to message from &quot;M. Wada&quot; &lt;[e-mail]&gt;
>   - Biff-XYZ Test 001 123 at 2013/07/11 09:31:33
> moved message id = [e-mail].001.001.001
>   to mailbox://[e-mail]/Sent
> </p>


Difference between "before Junk Classification" and "after Junk Classification".

"before Junk Classification" is perhaps;
>     for(nn=0;nn<number of mails;nn++){
>        download data of nn-th mail to Inbox(or temp file);
>        apply all filter rules;
>        write filter log for action category #1
>          do requied cat-#1-action-#1, do requied cat-#1-action-#2, ,,,
>        write filter log for action category #M
>          do requied cat-#M-action-#1, do requied cat-#M-action-#2, ,,,
>        write filter log for action category "Copy to folder"
>          do requied Copy-to-Folder-#1, do requied Copy-to-Folder-#2, ,,,
>      < Before here, mail data is in Inbox(or temp file) >
>      < After here, preparation of "Move to Folder" starts >
>  =>  at this step, Tb perhaps loses track of mail data location
>        write filter log for final action(Delete, Move to Folder, Stop further application)
>          do requied Move-to-Folder, or do required Delete
>          truncate Inbox(or delete temp file) after Move/Delete
>        if(Move to Folder)
>          request Junk filter to process mail in Inbox, or move target folder
>          (Junk filter applied to copied mail?)
>     }   

"before Junk Classification" may be;
(same as "manual filter run"==after the fact filter)
>     for(nn=0;nn<number of mails;nn++){
>        download data of nn-th mail to Inbox(or temp file);
>     }   
>     for(nn=0;nn<number os mails which is not moved/deleted by Junk ilter;nn++){
>        apply all filter rules, and determine required action;
>     }   
>     for(nn=0;nn<number os mails which is not moved/deleted by Junk ilter;nn++){
>        write filter log for action category #1
>     }   
>     for(nn=0;nn<number os mails which is not moved/deleted by Junk ilter;nn++){
>         do requied cat-#1-action-#1, do requied cat-#1-action-#2, ,,,
>     }   
>     for(nn=0;nn<number os mails which is not moved/deleted by Junk ilter;nn++){
>        write filter log for action category #M
>     }   
>     for(nn=0;nn<number os mails which is not moved/deleted by Junk ilter;nn++){
>         do requied cat-#M-action-#1, do requied cat-#M-action-#2, ,,,
>     }   
>     for(nn=0;nn<number os mails which is not moved/deleted by Junk ilter;nn++){
>        write filter log for action category "Copy to folder"
>     }   
>     for(nn=0;nn<number os mails which is not moved/deleted by Junk ilter;nn++){
>         do requied Copy-to-Folder-#1, do requied Copy-to-Folder-#2, ,,,
>     }   
>     for(nn=0;nn<number os mails which is not moved/deleted by Junk ilter;nn++){
>        write filter log for final action(Delete, Move to Folder, Stop further application)
>     }   
>     < Before here, mail data is in Inbox(or temp file) >
>     < After here, preparation of "Move to Folder" starts >
>     for(nn=0;nn<number os mails which is not moved/deleted by Junk ilter;nn++){
>         do requied Move-to-Folder, or do required Delete
>         truncate Inbox(or delete temp file) after Move/Delete
>     }

Comment 5

[WADA:World Anti-bad-Duping Agency]

I believe dup of bug 762318(problem started from Tb 12). But phenomena may be slightly different from Tb 12, because many changes were applied to Tb 24 after Tb 12.

Comment 6

[WADA:World Anti-bad-Duping Agency]

Setting dependency to bug 762318 for ease of tracking and search.

Comment 7

[WADA:World Anti-bad-Duping Agency]

Attachment: MSDB:5,MsgCopyService:5 log, HdrAdded event log by MsgDB Event Listener, and filter.log html

When HdrAdded event is notified, MsgDB Event Listener checks messageKey/messageOffset of passed MsgDBHdr, and checks msgDatabase.summaryValid.

Difference between "after Classification" and "before Classification" is visible by MsgCopyService:5 log and MsgDB Event Listener log.

  "after Classification"  :
     Use MsgCopyService(DoCopy).
     Download all new mails to Inbox => Apply Junk Filter
     => Batch type messege filter application to all newly downloaded mails

  "before Classification" :
     Don't use MsgCopyService(DoCopy).
     (i)   Download a mail => apply filter to a mail => move if required.
     (ii)  Repeat (i) for each new mail which is not downloaded yet.
     (iii) Apply Junk Filter to all newlydownloaded mails

Interesting phenomenon was observed by MsgDB Event Listener log.

  "after Classification" : Use MsgCopyService(DoCopy)
    - When HdrAdded event is notified to Event Listener,
      msgDatabase.summaryValid=false is returned
      "filter move to move target folder".
    - This msgDatabase.summaryValid=false is not observed after folder close
      at end of download/filter move.
    - When HdrAdded event is notified to Event Listener,
      messageOffset = Offset in Inbox(when added to Inbox)
                      Offset in move target folder(when added to move target)
      messageKey = same as messageOffset value at both Inbox and move target

 "before Classification" : Don't use MsgCopyService(DoCopy)
    - No MessageCopy/DoCopy log is written.
    - No HdrAdded Event occurs at Inbox.
    - When HdrAdded event is notified to Event Listener,
      messageKey = Highest messagekey + 1
      messageOffset = Offset in *Inbox* (== File Size of Inbox)
    - This "messageOffset = Offset in *Inbox*" is not observed
      when MsgDBHdr.messageKey is checked at move target folder,
      after end of download/dilter move.
      messageOffset = Offset in move target folder is always shown.

Comment 8

[:aceman]

That looks bad there is such a big difference.

Comment 9

[:aceman]

So it would look like we do not pass the right msgHdr into logRuleHit, e.g. at http://mxr.mozilla.org/comm-central/source/mailnews/local/src/nsParseMailbox.cpp#2065 . The msgHdr used there seems to be of the original message that probably isn't already there, because it was moved to a new folder. But we still access the old header, which somehow does not crash straight away but just returns empty/zero data.

We could return newHdr from nsParseNewMailState::MoveIncorporatedMessage (and MoveNewlyDownloadedMessage()) and send that one to the logRuleHit(). Looks like msgHdr (mailHdr in that function) is discarded inside that function so probably shouldn't be used at the caller after that. We probably can't move the call to logRuleHit before the move because we do not know if it succeeds.

rkent, Neil, what do you think?

Comment 10

[Kent James (:rkent)]

Trying to trace out the history of this, it looks to me that prior to the landing of pluggable stores, the hdr was not fully deleted until AFTER the logging was called. The line "m_mailDB->RemoveHeaderMdbRow(msgHdr);" after the log call was then removed, so presumably that is now occurring before the logging call, hence the problem. Or at least that is my guess.

We are inconsistent in whether we log a failed action. In filter-after-the-fact here http://mxr.mozilla.org/comm-central/source/mailnews/base/search/src/nsMsgFilterService.cpp#471 we log the move before we attempt it. In nsIImapMailFolder we have the comment "only log if successful move, or non-move action".

It seems to me that the purpose of LogRuleHit is to show users which filters are being applied in normal circumstances rather than to log failures. If we want it to track failures, it should have an explicit method to report failures, which AFAICT it does not. SO I would vote to just move the log before we attempt the move and not worry about trying to log the failure (unless you want to add a method to the log file to explicitly log failures).

Comment 11

[:aceman]

(In reply to Kent James (:rkent) from comment #10)
> Trying to trace out the history of this, it looks to me that prior to the
> landing of pluggable stores, the hdr was not fully deleted until AFTER the
> logging was called. The line "m_mailDB->RemoveHeaderMdbRow(msgHdr);" after
> the log call was then removed, so presumably that is now occurring before
> the logging call, hence the problem. Or at least that is my guess.

sourceDB->RemoveHeaderMdbRow(mailHdr); is inside nsParseNewMailState::MoveIncorporatedMessage now (bug 719307), so before the logRuleHit.

> We are inconsistent in whether we log a failed action. In
> filter-after-the-fact here
> http://mxr.mozilla.org/comm-central/source/mailnews/base/search/src/
> nsMsgFilterService.cpp#471 we log the move before we attempt it. In
> nsIImapMailFolder we have the comment "only log if successful move, or
> non-move action".
> 
> It seems to me that the purpose of LogRuleHit is to show users which filters
> are being applied in normal circumstances rather than to log failures. If we
> want it to track failures, it should have an explicit method to report
> failures, which AFAICT it does not. SO I would vote to just move the log
> before we attempt the move and not worry about trying to log the failure
> (unless you want to add a method to the log file to explicitly log failures).

Yes, I would be OK with moving it before the attempt. I'll try to test whether these theories are correct.

Reporting failures and other debug data can be left for bug 697522.

Comment 12

[[e-mail]]

(In reply to Kent James from comment #10)
> I would vote to just move the log
> before we attempt the move and not worry about trying to log the failure

I would go one step further and log before we switch on the filter action in all cases (pop, imap, news, filter after the fact).

Comment 13

[Dan Pernokis]

I posted Bug 933352 which turns out to be a duplicate of this bug and Bug 762318.  However, you might want to look at this workaround:

MOVE and DELETE do not capture timestamp and user info in the log (date is 31 Dec 1969).  (DELETE is basically a MOVE to Trash.)  But if you do a PUT-STAR prior to the MOVE or DELETE, then it not only captures time & info for the PUT-STAR but now also has it for the MOVE or DELETE.

But strangely, although TAG will also capture time & info, its subsequent MOVE or DELETE does not.

I also noticed that DELETE FROM POP3 also captures the time & info, although a corresponding DELETE does not.

Comment 14

[Dan Pernokis]

Further to Comment #13:
After further testing, it seems that the PUT-STAR trick allows info to be known to MOVE and DELETE ON POP3, but it does *not* work for DELETE.  But at least the PUT-STAR itself identifies the message.

Comment 15

[:aceman]

Attachment: patch

OK, so I move the logRuleHit to before the applying in all cases.
In my test this fixes the filter log entry when moving a received POP3 message.

Comment 16

[Kent James (:rkent)]

Comment on attachment 8490970 [details] [diff] [review]
patch

Review of attachment 8490970 [details] [diff] [review]:
-----------------------------------------------------------------

r=me with the nits fixed.

::: mailnews/imap/src/nsImapMailFolder.cpp
@@ +3477,5 @@
>        }
>  
> +      if (loggingEnabled)
> +      {
> +        (void) filter->LogRuleHit(filterAction, msgHdr);

Nit: Yes I realize this is controversial and that you copied this code, but the de facto standard in mailnews (and in this file) is no brackets around a single-line if clause.

Also, in the equivalent code in nsParseMailbox, the LogRuleHit is before the uri check, while here it is after. We should at least be consistent. I don't have a strong opinion, but I would prefer before (since we are changing to log even on errors).

Comment 17

[:aceman]

Attachment: patch v1.1

Yeah, the different placement of the logging was my fault.

Comment 18

[Patrick Cloke [:clokep]]

https://hg.mozilla.org/comm-central/rev/fbd6551e7540