1071628 - filter actions after message move fail

Status: RESOLVED INCOMPLETE

(MailNews Core :: Filters, defect)

Description

[[e-mail]]

User Agent: Mozilla/5.0 (X11; Linux i686; rv:24.0) Gecko/20140319 Firefox/24.0 Iceweasel/24.4.0
Build ID: 20140319114152

Steps to reproduce:

After creating a filter that does the next operations:

Conditions:
AAAA message conditions

Operations:

forward to XXXX@X.X
Move to folder ZZZZ

and executed manually or at arrival with a message that acomplish AAAA conditions


Actual results:

When the filter is triggered, the message that acomplish the conditions is moved to the folder ZZZZ, but it's not forwarded to the email XXXX@X.X

It's because the message have been moved before have been forwarded. I suposse it happens because the operations in the same filter are done in parallel, not secuencially, so the message it's moved before its forwarded (because forwarding it is slower). And every time it hapens a "blank message" windows appears because the forwarding operation didn't find the message.


Expected results:

The message have to be forwarded to XXXX@X.X and after moved to folder ZZZZ.

-------------------------------------------------

Like a solution i recomend to implement a "delay" function and the possibility of indicating that the operations for mail filtering are done in secuential mode not parallel

As a tip, if I divide the filter in two filters:

Filter 1: (Priority or position of the filter 1)

Conditions:   AAAA

Forward to XXXX@X.X

Filter 2: (Priority o position 100, or lower)

Conditions: AAAA

Move to folder ZZZZ

It works perfectly because thunderbird has to process all the filters between 1 and 99 before moving the mail to folder ZZZZ, so it's like creating a delay.

Comment 1

[:aceman]

The operations should not be done in parallel, but sequentially and TB even has a priority list in which to execute the various actions. So Move/Delete is always the last action in the list and Forward should be done sooner, when the message is still there. In TB31 the filter editor even shows you this real order of execution. So theoretically this should not happen. But of course, there may be a bug. What is exact TB version?

Comment 2

[[e-mail]]

Hi, 

sorry it's icedove, Package: icedove (10.0.12-1~bpo60+1) and icedove (24.8.0-1~deb7u1 and others) [security], from debian stable and stable-sec. In this 2 versions happens the problem.

I'm going to try it in a last versión thunderbird. I'll post then.

Comment 3

[WADA:World Anti-bad-Duping Agency]

(In reply to [e-mail] from comment #0)
> Steps to reproduce:
> After creating a filter that does the next operations:
> Conditions:
> AAAA message conditions
> Operations:
> forward to XXXX@X.X
> Move to folder ZZZZ
> and executed manually or at arrival with a message that acomplish AAAA conditions
> Actual results:
> When the filter is triggered, the message that acomplish the conditions is
> moved to the folder ZZZZ, but it's not forwarded to the email XXXX@X.X
> 
> It's because the message have been moved before have been forwarded. 
> I suposse it happens because the operations in the same filter are done in
> parallel, not secuencially, so the message it's moved before its forwarded
> (because forwarding it is slower). 
> And every time it hapens a "blank message" windows appears because the forwarding operation didn't find the message.

(Q1) POP3? IMAP? Gmail IMAP? If Gmail IMAP, do you enable auto-expunge of Gmail?

I could observe the "blank message windows" with following in Tb 31.1.1.
  IMAP delete model = Mark it as deleted, in order to see deleted mail as "mail with trash can icon & strike-thru line".
  Gmail IMAP, auto-expunge of Gmail is enabled.
  FolderX = Offline-Use=Off folder in Tb. Mail data is not held in Offline-Store file.
  Filter Rule: [x] Manually Run, If subject begins with ..., Forward to ..., Forward to ..., Move to FolderY.
  Forward option : Inline forward (not forward as attachment).
  At FolderX of Gmail IMAP, "Run Filters on Folder".
In message filter log, all actions(Forward, Move) are normally logged.

If  "Run Filters on Folder" is executed while "Work Offline" mode, 
   "Forward to ..." is impossible because message body is not available(Offline-Use=Off),
   "Move to FolderY" is executed in "Work Offline" mode.
Because mail is already moved to FolderY in Thunderbird, "Move from FolderX to FolderY" is actually executed after going back to Work Online mode.

If "Run Filters on Folder" on Offline-Use=On folder, "Run Filters on Folder while Work Offline mode",  did do next.
   "Forward to ..." is executed because message body is available in Offline-Store file,
    but "SMTP send fails because of Work Offline mode.
   "Move to FolderY" is executed in "Work Offline" mode, and .actual move is executed when going back to Work Online mode.
   
(Q2) If Gmail IMAP, do you see your problem on already downloaded mails in Offline-Use=On folder with "Run Filters on Folder"?

(Q3) About "newly arrived mails in Inbox" :
         Do you see your problem with "[ x ] Getting New Mail: Filter after Junk Classification"?

(Q4) About "mails in [Gmail]/All Mail" :
         Do you see your problem with next?
              "[Gmail]/All Mail" is Offline-Use=Off  folder, message body is not held in Offline-Store file.
              "Run Filters on" on "[Gmail]/All Mail".
         UID of mail in [Gmail]/All Mail is not removed by "move from [Gmail]/All Mail to other than [Gmail]/Trash(or Spam)".
         So, UID of mail is accessible at [Gmail]/All Mail even after "move from [Gmail]/All Mail" or ".delete at [Gmail]/All Mail".

As known by bug 971401 and bug 1067706, if new mails, entire message data is fetched prior to message filter application.
And, because Gmail IMAP supports Move extension, IMAP move command is used by Tb upon filter move.
And, if auto-expunge of Gmail is enabled, UID of the moved mail is removed immediately by Gmail IMAP, even when simple "store +Flags(\Deleted)" is used upon filter move. 
So, once "uid move xx MoveTargetFolder" is executed at Inbox by message filter, "subsequent UID access at Inbox by forward mail composition & SMTP send" is impossible.
If Move extension is not supported by IMAP server, "Move mail in Tb" = "uid copy xx MoveTragetFolder" +  "uid store xx +Flags(\Deleted)".
So, if ordinl IMAP server and Move extension is not used, uid=xx is available even after "Filter Move".

(Q5) If IMAP, do you see your problem with ordinal IMAP servers?

Comment 4

[WADA:World Anti-bad-Duping Agency]

Attachment: IMAP log, manual Filter Forward & Move at Gmail IMAP Offline-Use=Off folder

NSPR log parameter
   SET NSPR_LOG_MODULES=SMTP:5,imap:5,ImapAutoSync:5,IMAPOFFLINE:5,MsgCopyService:5
Gmail IMAP, max cached connections = 2, IDLE is enabled
Filter Rule : If subject begins ..., Forward to aaa, Forward to bbb, Move to MoveTargetX
Mail Folder : MoveTargetX,  Offline-Use=Off folder, 1 hit mail

Filter Log : 1. Forward to aaa, 2. Forward to bbb, 3. Move to MoveTargetX in this order
NSPR log :
  0. Connection for MoveTarget is IDLE state
  1. DoCopy src MoveTarget dest MoveTargetX, number of mails=1
  2. At connection for MoveTarget, DONE 	
  3. queuing url:imap://[e-mail]@imap.gmail.com:993/fetch>UID>/MoveTarget>88
  4. 17 OK IDLE terminated (Success)
  5. :S-MoveTarget:ProcessCurrentURL:imap://[e-mail]:993/
                                                               onlinemove%3EUID%3E/MoveTarget%3E88%3E/MoveTargetX:  = currentUrl	
       At connection for MoveTarget, 19 uid move 88 "MoveTargetX
                                                        20 OK Success
  6. playing queued url:imap://[e-mail]@imap.gmail.com:993/fetch>UID>/MoveTarget>88
      21 UID fetch 88 (UID RFC822.SIZE BODY[])
           nothing is returned, because UID=88 is already moved
      21 OK Success

It looks :
  1. "Forward to aaa" action is executed
      => mail composition window is internally created with request of "inline forward of UID=88
      => end of "Forward action by message filter"
  2. "Forward to bbb" action is executed
      => mail composition window is internally created with request of "inline forward of UID=88
      => end of "Forward action by message filter"
  3. "Move to MoveTargetX" action is executed => DoCopy is requested and is invoked
  4. Before "request for message body to do forward"(= "uid fetch 88 body.peek[]" command) is requested and queued by mail composition job for forward,
      "request for move by DoCopy"(= "uid move 88 MoveTargetX" command) is requested at cached connection.

In this test with NSPR logging enabled, "blank mail composition windows" is not observed.
"Forward to ..." step silently fails and nothing is forwarded.
It looks that "blank mail composition windows appears or not" is timing dependent.
Effect of "Splitting filter rule to 'Rule for Forward' and 'Rule for Move'" is perhaps ;
   When new mail  and "Filter before Junk Classification",
   "uid fetch xx body.peek[] for forward" is requested by mail composition task before "uid move xx Move-Target-Folder" is requested by DoCopy for filter move.
"Filter after Junk Classification" may be a workaround, but it may not be a workaround as seen in bug 1067706.

If Move extension is not used, "Move to MoveTargetX" is executed by following IMAP commands :
   "uid copy 88 MoveTargetX" + "uid store 88 +Flags(\Deleted)"
So, subsequent "uid fetch 88 body.peek[]" always returns mail data normally.

Comment 5

[WADA:World Anti-bad-Duping Agency]

FYI.
Following is copy of Bug 1071754 Comment #1 posted by Kent James.
> "Filter after" uses entirely different code (the FilterAfterTheFact code) than "filter before", 
> so it is common that bugs in one do not appear in the other. 
> Although that was added to allow the bayes filter to be used, there are other special cases where works, such as this one. 
> The bayes filter will not actually occur unless it is selected for the account. Not sure if RSS allows that or not.
Because FilterAfterTheFact code is used for "Filter after junk Classification", "Filter after junk Classification" is similar to "Run Filters on Folder".

Comment 6

[WADA:World Anti-bad-Duping Agency]

Problem seems to depend on "Forward option".

Test case is same as comment #4.
     Gmail IMAP, max cached connections = 2, IDLE is enabled
     Filter Rule  : If subject begins ..., Forward to aaa(valid addr), Forward to bbb(non-existent), Move to MoveTargetFolder
     Mail Folder : TestFolder,  Offline-Use=Off folder, 1 hit mail is held,
                          "Run Filters on Folder" is executed on TestFolder
     Used identity : Mailn identity of this Gmail IMAP account which uses Gmail's SMTP server
Test result.
(1)  Forward option=Inline Forward, No NSPR logging :
       Two blank composition windows are shown. Forwarded icon is not set.
(2)  Forward option=Forward as attachment, No NSPR logging :
       Forward is executed. Forwarded icon is set.
       Because mail-addr=bbb doesn't exist(non-existent mail domain), delivery failure is notified from Gmail's SMTP server.

Forward by messge filter is done via Compose Service->ForwardMessage.
> http://mxr.mozilla.org/comm-central/source/mailnews/imap/src/nsImapMailFolder.cpp#3708
> 3696       case nsMsgFilterAction::Forward:
> 3708             rv = compService->ForwardMessage(NS_ConvertASCIItoUTF16(forwardTo),
> 3709                                              msgHdr, msgWindow, server,
> 3710                                              nsIMsgComposeService::kForwardAsDefault);
ForwardMessage Service is defined at;
> http://mxr.mozilla.org/comm-central/source/mailnews/compose/src/nsMsgComposeService.cpp#1166
> 1166 nsMsgComposeService::ForwardMessage(const nsAString &forwardTo,
If Inline Forward, ForwardMessage Service returns at here after end of RunMessageThroughMimeDraft.
> 1212   if (aForwardType == nsIMsgComposeService::kForwardInline)
> 1213     return RunMessageThroughMimeDraft(msgUri,
> 1214                                       nsMimeOutput::nsMimeMessageDraftOrTemplate,
> 1215                                       identity,
> 1216                                       msgUri.get(), aMsgHdr,
> 1217                                       true, forwardTo,
> 1218                                       false, aMsgWindow);
If Forward as attachment, ForwardMessage Service returns at here after end of SendMsg service.
> 1246   rv = pMsgCompose->Initialize(pMsgComposeParams, parentWindow, nullptr);
> 1249   rv = pMsgCompose->SendMsg(nsIMsgSend::nsMsgDeliverNow, identity, nullptr, nullptr, nullptr);
> 1257   return folder->AddMessageDispositionState(aMsgHdr, nsIMsgFolder::nsMsgDispositionState_Forwarded);

RunMessageThroughMimeDraft(used when Inline Forward) is asynchronous?

FYI. Logic for Inline Forward was added by Inline Forward support in message filter.
> http://hg.mozilla.org/comm-central/annotate/2b6f0a685995/mailnews/compose/src/nsMsgComposeService.cpp#l1212
> http://hg.mozilla.org/comm-central/diff/b80ba3cbee79/mailnews/compose/src/nsMsgComposeService.cpp#l1.76
> http://hg.mozilla.org/comm-central/diff/b80ba3cbee79/mailnews/compose/src/nsMsgComposeService.cpp#l1.126
> http://hg.mozilla.org/comm-central/rev/b80ba3cbee79
>            add forward inline filter action, r=rkent, sr=standard8, bug 312025

Comment 7

[WADA:World Anti-bad-Duping Agency]

FYI.
If local mail folder(POP3 account or Local Folders), "forward of filter" is processed here.
> http://mxr.mozilla.org/comm-central/search?string=case%2BnsMsgFilterAction%3A%3AForward%3A
> http://mxr.mozilla.org/comm-central/source/mailnews/local/src/nsParseMailbox.cpp#2155
> 2155       case nsMsgFilterAction::Forward:
> 2156         {
> 2157           nsCString forwardTo;
> 2158           filterAction->GetStrValue(forwardTo);
> 2159           m_forwardTo.AppendElement(forwardTo);
> 2160           m_msgToForwardOrReply = msgHdr;
> 2161         }
> 2162         break;
m_forwardTo is referred at here, and Compose Service->ForwardMessage is used too.
> http://mxr.mozilla.org/comm-central/ident?i=forwardTo
> 2275     if (!m_forwardTo[i].IsEmpty())
> 2276     {
> 2281       {
> 2282         nsCOMPtr<nsIMsgComposeService> compService =
> 2283           do_GetService (NS_MSGCOMPOSESERVICE_CONTRACTID, &rv);
> 2284         NS_ENSURE_SUCCESS(rv, rv);
> 2285         rv = compService->ForwardMessage(forwardStr, m_msgToForwardOrReply,
> 2286                                          msgWindow, server,
> 2287                                          nsIMsgComposeService::kForwardAsDefault);
> 2288       }
> 2289     }
If local mail folder, "messageKey==messageOffset of filter moved mail(==forwarded mail)" is not changed, unless Compact is executed at Filter Move Source Folder(Inbox when filter on new mail) just after"Filter Move" and just before compService->ForwardMessage call for "Forward Inline by filter". Therefore, "Forward Inline by message filter" can nearly always read mail data of forwarded mail, even if "Filter Move" is executed too quickly before completion of "Forward Inline by filter".
So, Problem won't be exposed if local mail folder.

Comment 8

[[e-mail]]

Wooo, a lot of information for my short time now. Thanks a  lot for all this WADA.

All problems start when I changed my mail "configuration" from a local mail to a IMAP mail (outlook.office365.com; microsoft).  With local mail configuration ever have this problem. All mails arrived to local mail and then the same filters than now forward to the same addreses and move to local mail folders (same structure than imap) correctly.

But... let's go.


Q1? - It's IMAP in  (outlook.office365.com; microsoft server), not gmail nor pop. 
    - I always work in online mode, it's rare condition that we have network connectivity problems.

Q2? - Not Gmail.

Q3?  Where it is "Getting New Mail: Filter after Junk Classification"?" Ahhh ok, I see, I always have "Check before Junk Classification", I'LL TEST IT, but I think there isn't to be changes.

Q4? - Not Gmail

Q5? Yes I see, in (outlook.office365.com; microsoft), but I don't know if it's an ordinal IMAP server.


Too much for reading in the "comment 6" for now :-). I'll try.... to understand.

Thanks in advance.

Comment 9

[[e-mail]]

Ohh, more information,

I forgot, the filters logs of icedove (10.0.12-1~bpo60+1) and icedove (24.8.0-1~deb7u1 and others) [security]  indicate the operations have finished OK.... but really don't.

Comment 10

[WADA:World Anti-bad-Duping Agency]

(In reply to [e-mail] from comment #9)
> I forgot, the filters logs of icedove (10.0.12-1~bpo60+1) and icedove
> (24.8.0-1~deb7u1 and others) [security]  indicate the operations have finished OK.... but really don't.

As known by bug 935934, current purpose of filter logging is to show "which filter did hit on which mail", perhaps except for "filter move from IMAP folder".  So, we can't know "filter action was successfully executed or not" by message filter log. This is sadly current design/implementation of message filter logging. "No timestamp of log in message filter log" is also current spec :-)

Comment 11

[WADA:World Anti-bad-Duping Agency]

(In reply to [e-mail] from comment #8)
> Q1? - It's IMAP in  (outlook.office365.com; microsoft server), not gmail nor pop. 

Does IMAP server of outlook.office365.com suppot Move extension?
Get IMAP log(See bug 402793 comment #28) and check CAPABILITY response and move command use upon move mail/delete mail(move to Trash) by Tb.

Comment 12

[WADA:World Anti-bad-Duping Agency]

 :aceman, RunMessageThroughMimeDraft(used when Inline Forward) is asynchronous?

Comment 13

[:aceman]

(In reply to WADA from comment #10)
> (In reply to [e-mail] from comment #9)
> > I forgot, the filters logs of icedove (10.0.12-1~bpo60+1) and icedove
> > (24.8.0-1~deb7u1 and others) [security]  indicate the operations have finished OK.... but really don't.
> 
> As known by bug 935934, current purpose of filter logging is to show "which
> filter did hit on which mail", perhaps except for "filter move from IMAP
> folder".  So, we can't know "filter action was successfully executed or not"
> by message filter log. This is sadly current design/implementation of
> message filter logging. "No timestamp of log in message filter log" is also
> current spec :-)
I proposed some improvements to make the filter log more useful in bug 697522 to allow us better debugging.

(In reply to WADA from comment #12)
>  :aceman, RunMessageThroughMimeDraft(used when Inline Forward) is
> asynchronous?
I have no idea, just that there is a line "converter->AsyncConvertData(nullptr, nullptr, nullptr, channel);" in that function. I don't know what effect that has. I am not familiar with IMAP either.

Comment 14

[Wayne Mery (:wsmwk)]

miguel, do you still see this issue?

Comment 15

[Wayne Mery (:wsmwk)]

miguel seems to be gone

Comment 16

[Wayne Mery (:wsmwk)]

(In reply to :aceman from comment #13)
> I proposed some improvements to make the filter log more useful in bug
> 697522 to allow us better debugging.

possible to finish that work? It blocks quite a few items.

Comment 17

[:aceman]

Filter hits logging finished, but the bug here may be more dependent on bug 1547508, as it seems the filters hit the right messages here but the actions aren't executed successfully.

Comment 18

[Thilo [:ThiloteE]]

Please try the "move later function" of the FiltaQuilla Addon