Closed Bug 545082 Opened 14 years ago Closed 12 years ago

Filters filing to IMAP folders not running automatically (quarantine option=on/mailnews.downloadToTempFile=true, "MOVE to IMAP folder" action does nothing)

Categories

(MailNews Core :: Networking: IMAP, defect)

Product:
MailNews Core
Component:
Networking: IMAP
Version:
1.9.1 Branch
Platform:
x86
Windows XP
Type:
defect
Priority:
Not set
Severity:
major

Tracking

(Not tracked)

Status:
RESOLVED INCOMPLETE

People

(Reporter: internationils, Unassigned)

References

Details

(Whiteboard: [closeme 2012-03-25])

Attachments

(3 files)

logfile with set NSPR_LOG_MODULES=imap:5,pop3:5,MSGDB:5,ImapAutoSync:5,timestamp
63.12 KB, text/plain
Details
imap logfile of a manual filter working fine
6.14 KB, text/plain
Details
set NSPR_LOG_MODULES=imap:5,ImapAutoSync:5,timestamp
103.15 KB, text/plain
Details 
User-Agent:       Mozilla/5.0 (Windows; U; Windows NT 5.1; en-US; rv:1.9.1.7) Gecko/20091221 Firefox/3.5.7 (.NET CLR 3.5.30729)
Build Identifier: Mozilla/5.0 (Windows; U; Windows NT 5.1; en-US; rv:1.9.1.7) Gecko/20100111 Lightning/1.0b1 Thunderbird/3.0.1

I migrated from the latest 2.x to 3.0.1 this weekend, and changed my filters to point at an IMAP server on the local machine instead of Local Folders

Results: 
- some mails are filtered just fine (from one pop account), i.e. identified, moved, listed as new
- some mails (from 2 other pop accounts) are listed in BOTH the original folder and the destination folder as UNREAD, but are not moved to the destination folder and remain unread in the source folder
- going to the destination folders then shows no unread mails
- going back to the source folder and running filters manually files the mails corerctly.

Reproducible: Always

Steps to Reproduce:
Not sure how to set it up to reproduce but
1. get mails from several accounts (pop) that 
2. refile to IMAP server (could be that this works to normal folders as well, didn't test this)
3. see mails not show up correctly
Actual Results:  
Mails not filed correctly - remain in source folder and show as unread in both source and destination folder, and on click in destination folder are not there.

Expected Results:  
Mails should be filed correctly

I installed the Extra Folder Columns addon, not sure if this has anything to do with the bug or not...
This evening:

- started thunderbird, had 10 new messages in one of the inboxes that doesn't work
- saw it run down to 4 messages and claim to refile the others (by unread count) but the messages remained in the inbox, the indexer was running (maybe in that folder but not sure...)
- then the unread count in that inbox went back up to 10 and the messages are still there.
- ran filters manually and they moved, with 3 remaining unread in the inbox
Another weird effect I'm noticing:

One mail shows up in several different filtered mailboxes, almost as if the mails that should get moved don't, and that one message gets moved into several filter destination folders instead.
Can you provide us with an imap log as described at https://wiki.mozilla.org/MailNews:Logging so we can investigate what is going on ?
Component: General → Networking: IMAP
Product: Thunderbird → MailNews Core
QA Contact: general → networking.imap
Version: unspecified → 1.9.1 Branch
Just grabbed 3.0.2 beta build 1 from http://ftp.mozilla.org/pub/mozilla.org/thunderbird/nightly/3.0.2-candidates/build1/ ... maybe the bug's gone there... the "IMAP mails getting marked unread again" bug was driving me crazy as well
Updated to 3.0.2 beta build 1 ... bug is still there... one mail retrieved that should not have been filed, one that should have been filed, showed up as unread in the dest folder (unison), and then in indexing disappeared as unread again, and as before is still in the inbox that it was retrieved into.
> 2010-02-20 20:45:50.763000 UTC - 0[192d140]: SEND: QUIT
> 
2010-02-20 20:45:50.826000 UTC - 1640[6177040]: 46acc00:192.168.2.84:S-folders.Online.lists.debian.private:SendData: DONE
> 2010-02-20 20:45:50.826000 UTC - 1640[6177040]: 46acc00:192.168.2.84:S-folders.Online.lists.debian.private:CreateNewLineFromSocket: 2663 OK Idle completed.
> 2010-02-20 20:45:50.826000 UTC - 1640[6177040]: 46acc00:192.168.2.84:S-folders.Online.lists.debian.private:ProcessCurrentURL: entering
> 2010-02-20 20:45:50.842000 UTC - 1640[6177040]: 46acc00:192.168.2.84:S-folders.Online.lists.debian.private:ProcessCurrentURL:imap://nils@192.168.2.84:993/appendmsgfromfile%3E.folders.Online.lists.unison:  = currentUrl
> 2010-02-20 20:45:50.842000 UTC - 0[192d140]: RECV: +OK GMX POP3 server signing off
> (End of log) 

It looks that Tb tried to append mail to IMAP folder but didn't do append(upload mail).
Do you use ation of "Copy Message to" "Move Message to" for the mail?
If yes, same problem as bug 387361?

Do you use both "Copy Message to" and "Move Message to" in a filter rule?
Do you have filter rule with "Copy Message to" and other filter rule with "Move Message to" for a same mail?
"changed my filters to point at an IMAP server on the local machine instead of Local Folders"

Could you please describe this IMAP server better? Is it something that I could easily install on a local machine, so that I could try to reproduce what you are observing?
@WADA: all filters exist only once, and are set to move the mail to the destination folder, no copying.

@rkent: the mailserver is a plain dovecot IMAP server on a localhost (running in a virtualbox virtual machine, latest kubuntu host, debian testing guest)
maybe a little more on the setup: the Thunderbird doing the filtering is on an older XP laptop (2GHz Pentuim M), connected via gigabit ethernet to the kubuntu box with the kubuntu host and debian testing vbox guest.

@WADA: bug 387361 doesn't seem to have anything to do with it, but I've turned junk mail filtering off on all incoming pop3 servers anyway... if it changes anything I'll post a message tomorrow AM CET.
Nope, same result with junk mail filters disabled. I have the feeling that indexing is getting in the way somehow, that possibly the IMAP mailserver is being blocked by indexing when the filter wants to move the mail or something...
(In reply to comment #10)
> Nope, same result with junk mail filters disabled. I have the feeling that
> indexing is getting in the way somehow, 

easy to prove by turning off indexing.
but i have my doubts that disabling will help.
Correct, turning off indexing didn't change anything. Any other suggestions on more debugging options from https://wiki.mozilla.org/MailNews:Logging ... perhaps the ones from "Other Protocol Logging options within MailNews" such as movemail? Which builds would have that option included?
Here is the filter I am running on the POP3 inbox... 

name="unison-users"
enabled="yes"
type="17"
action="Move to folder"
actionValue="imap://nils@192.168.2.84/folders/Online/lists/unison"
condition="OR (to or cc,contains,unison-users@yahoogroups.com) OR (\"Sender\",contains,unison-users@yahoogroups.com)"
Nils, I run this on my system (POP3 receives a message, moves it to IMAP folder with an incoming filter) and it works fine. As WADA says, the append never seems to happen for you like it does for me. So your last IMAP action is:

2010-02-20 20:45:50.842000 UTC - 1640[6177040]: 46acc00:192.168.2.84:S-folders.Online.lists.debian.private:ProcessCurrentURL:imap://nils@192.168.2.84:993/appendmsgfromfile%3E.folders.Online.lists.unison:  = currentUrl

The equivalent for me is followed by the actual message:

=== begin log ===
...
2010-02-23 00:35:54.812000 UTC - 3516[367bb80]: 419a800:mail.caspia.com:S-INBOX.test:ProcessCurrentURL:imap://kenttest2@mail.caspia.com:143/appendmsgfromfile%3E.INBOX.test:  = currentUrl
2010-02-23 00:35:54.812000 UTC - 3516[367bb80]: 419a800:mail.caspia.com:S-INBOX.test:SendData: 15 append "INBOX.test" "22-Feb-2010 16:34:28 -0800" {1847+}

2010-02-23 00:35:54.812000 UTC - 3516[367bb80]: 419a800:mail.caspia.com:S-INBOX.test:SendData: X-Account-Key: account2

X-UIDL: UID2738-1165860186

X-Mozilla-Keys:                                                                                 

Return-path: <kent@caspia.com>
...
=== end log ===

So this looks like an IMAP issue, and not a filter issue. That's more bienvenu's specialty than mine.
OK, thanks... any chance you can point him at this bug? 

I upgraded dovecot to the latest from debian testing (as well as an upgrade to all the latest testing packages) last night, here's the info:

nils@dpim64:~$ dpkg -l | grep dovecot
ii  dovecot-common                          1:1.2.10-1                 secure mail server that supports mbox and ma
ii  dovecot-imapd                           1:1.2.10-1                 secure IMAP server that supports mbox and ma
nils@dpim64:~$ uname -a
Linux dpim64 2.6.32-trunk-amd64 #1 SMP Sun Jan 10 22:40:40 UTC 2010 x86_64 GNU/Linux

The mail logs on the dovecot side show no problems, just connections and Logouts:

Feb 23 00:09:20 dpim64 dovecot: imap-login: Login: user=<nils>, method=PLAIN, rip=192.168.2.100, lip=192.168.2.84, TLS
Feb 23 00:09:56 dpim64 dovecot: imap-login: Login: user=<nils>, method=PLAIN, rip=192.168.2.100, lip=192.168.2.84, TLS
Feb 23 00:18:45 dpim64 dovecot: imap-login: Login: user=<nils>, method=PLAIN, rip=192.168.2.100, lip=192.168.2.84, TLS
Feb 23 00:20:58 dpim64 dovecot: IMAP(nils): Disconnected: Logged out bytes=103/816
Feb 23 00:20:58 dpim64 dovecot: IMAP(nils): Disconnected: Logged out bytes=749/33082
Feb 23 00:20:58 dpim64 dovecot: IMAP(nils): Disconnected: Logged out bytes=45102/42556

I'm using Maildirs (one mail per file) with dovecot, and they're all in all 1.2G ... Thunderbird on XP keeps a copy of the IMAP server mails locally as well.

The weird thing is: if I run the filters MANUALLY it works just fine, it's just that the automatic filtering at retrieval has a problem.
Here's what the dovecot.rawlog reports when I manually filter a message:

---in the [timestamp].out File:
* OK [RAWLOG TIMESTAMP] 2010-02-23 07:37:17
1 OK [CAPABILITY IMAP4rev1 LITERAL+ SASL-IR LOGIN-REFERRALS ID ENABLE SORT SORT=DISPLAY THREAD=REFERENCES THREAD=REFS MULTIAPPEND UNSELECT IDLE CHILDREN NAMESPACE UIDPLUS LIST-EXTENDED I18NLEVEL=1 CONDSTORE QRESYNC ESEARCH ESORT SEARCHRES WITHIN CONTEXT=SEARCH LIST-STATUS] Logged in^M
2 OK [APPENDUID 1254141290 156] Append completed.^M
* BYE Logging out^M
3 OK Logout completed.^M

---in the [timestamp].in File:
2 append "folders.Online.lists.unison" (\Seen) "23-Feb-2010 04:09:58 +0100" {17927+}
<...whole message body...>
3 logout
in this TB logfile you see the manual filtering working just fine...
@WADA (or whomever):

if my not-working-logfile shows:
> 
2010-02-20 20:45:50.826000 UTC - 1640[6177040]:
46acc00:192.168.2.84:S-folders.Online.lists.debian.private:SendData: DONE
> 2010-02-20 20:45:50.826000 UTC - 1640[6177040]: 46acc00:192.168.2.84:S-folders.Online.lists.debian.private:CreateNewLineFromSocket: 2663 OK Idle completed.
> 2010-02-20 20:45:50.826000 UTC - 1640[6177040]: 46acc00:192.168.2.84:S-folders.Online.lists.debian.private:ProcessCurrentURL: entering
> 2010-02-20 20:45:50.842000 UTC - 1640[6177040]: 46acc00:192.168.2.84:S-folders.Online.lists.debian.private:ProcessCurrentURL:imap://nils@192.168.2.84:993/appendmsgfromfile%3E.folders.Online.lists.unison:  = currentUrl
> 2010-02-20 20:45:50.842000 UTC - 0[192d140]: RECV: +OK GMX POP3 server signing off
> (End of log) 

...then why on earth are the S-folders.Online.lists.debian.private mentioned???? That mail should have gone to the unison folder. listed later in that line S-folders.Online.lists.debian.private ... ???
sorry, paste error... listed later in that line imap://nils@192.168.2.84:993/appendmsgfromfile%3E.folders.Online.lists.unison:
Attachment #428381 - Attachment mime type: application/octet-stream → text/plain
When mails are moved by "Run filters on folder", "Moved N messages from xxx to yyy" appears at Activity Manager window. Does the message appear when not moved by filter upon download?
"Move(==copy+delete) from Inbox of POP3 account" may be interfered by other process such as auto-compact on Inbox.
Following is known issues, and, "Junk not moved" was observed several times when auto-compact was executed or after auto-compact was executed.
> bug 310431 Junk filter sometimes doesn't move junk to junk folder (Seamonkey, Local Junk folder)
> bug 324777 junk mail not moved to junk folder sometimes (Thunderbird, Local Junk folder)
> bug 362247 Junk mail not always put in Junk folder (IMAP)

Do you enable auto-compact? If yes, do you enable dialog just before start of auto-compact?
See bug 498274 comment #2 and set mail.purge.ask=true (restart of Tb is needed) if you enable auto-comact, and reply Cancel if dialog appears.
- I set mail.purge.ask=true and restarted but that didn't change anything
- the activity manager shows the mails that should have been moved, but where more than one should have gone into a folder (bugs, unison), it only shows "Moved 1 message from Inbox to <folder>"
- when running the filters manually, the correct number is shown

Should I try disabling addons to see if it changes anything?
it might be easier to follow with just imap logging turned on.

Did you change the name of your imap server in prefs? i.e., is there a hostname and a realhostname pref that's different?
one email (the last one from this bug report in response to my entry) should go into the bugs folder.

Do you want me to turn off ImapAutoSync logging as well?
The server name is set to 192.168.2.84, the hostname is dpim64... why would that make a difference in automatically and manually run filters?
it's just a little suspicious, that's all. If we get the wrong uri/hostname, things will fail. What seems to be happening is that we're running the url to do the append, but once we've done the authentication and folder discovery on the server, we don't try to do the append. What's almost certainly happening is that the file containing the message we're trying to append no longer exists by the time we try to read it to upload it to the server. Do you have incoming message quarantining turned in your pop3 server settings? Tools | options, security, anti virus.
Yep, that did it! After disabling it, the mail shows up in the inbox, gets filtered and filed to teh IMAP server just fine.

Can I provide you any logfiles to narrow the problem down further?
no, thx, I think this is actually a "known" issue. I don't know what the bug # is, though.
Looks like Bug 387361 - https://bugzilla.mozilla.org/show_bug.cgi?id=387361

I've turned all addons, indexing, and junk mail controls back on, and it still works fine.
yeah, that's very similar. It's about copying to a different local folder account, but the issue is the same.
I've stuck a note in the other bug about this one, feel free to close this as a dupe if you like. Thanks for the help, guys!
Known bugs. If move target is IMAP folder, "move to" looks equivallent to "copy to" followed by "delete", then action of "move to" seems to be interfered too.
> Bug 355537 FILTERS: If Action includes adding a TAG, the filter does not work on incoming mail - must be run manually
> (when "allow antivirus clients to quarantine individual messages"=ON)
> Bug 387361 test: msg copy action on incoming pop3 mail fails with quarantining turned on for antivirus
I asked about "Copy to" because of Bug 387361. I should have requested check with "add tag before move to"...
Steps to reproduce at WADAs request from Bug 387361:

- set up a pop account where mails get retrieved automatically
- turn on the incoming message quarantining pop3 server settings: Tools | options,
security, anti virus.
- set up a filter (I use subject BUGTEST) to move mails to the IMAP server
- send yourself a mail
- watch it show up in the inbox, then the destination folder (virtually only as an unread mail)
- see the mail still in the original inbox.

Note: junk mail filtering, indexing, compacting and extensions had no effect on this behavior.
Additinal Info: I'm running Avira Antivir Personal Edition, in case it's a timing issue or some such where one antivir takes longer or works differently than another one.
Nils Lohner, can you check with filter rule like bug 387361 comment #13? (I couldn't reproduce this bug with filter rules written in bug 387361 comment #13) 
  Insert two rules(same condition as rule of "move to") before rule of "move to".
  (1) action = add tag (for ease of test result check)
  (2) action = copy to local mail folder of same POP3 account(bug 387361 occurs)
      (to postpone "move to IMAP folder" execution)
      Note: As "copy to" is added, separate rules is needed to avoid known bug.
(In reply to comment #35)
>   Insert two rules(same condition as rule of "move to") before rule of "move
> to".
>   (1) action = add tag (for ease of test result check)
>   (2) action = copy to local mail folder of same POP3 account(bug 387361
> occurs)

Did that with antivirus OFF, with the following results:
- the mail is tagged IMPORTANT as expected
- mail was copied to the local folder of the pop3 account as expected
- mail was moved to the IMAP server as expected

Did that with antivirus ON, with the following results:
- the mail is tagged IMPORTANT as expected
- mail was copied to the local folder of the pop3 account as expected
- mail was NOT moved to the IMAP server as expected
(In reply to comment #36)
> Did that with antivirus ON, with the following results:

What action do you mean by "antivirus ON/OFF"?
Check/Uncheck of "[?] Allow antivirus clients to quarantine ..." ?

> - the mail is tagged IMPORTANT as expected
> - mail was copied to the local folder of the pop3 account as expected

Did you check both thread pane display(subject,tag etc.) and mail data(view/message source)? (See bug 387361 comment #13, please)

> - mail was NOT moved to the IMAP server as expected

Why I can't reproduce this bug... What is difference from your environment...
I used Tb 3.0.1. Did you use nightly builds? (Tb3.0.2pre, Tb3.1pre, Tb3.2pre etc.)
- Yes, the quarantining
- Yes, I checked both.
- I use 3.0.2 beta1 because of the IMAP folders becoming unread again bug. (see comment #5)
- I use avira antivir, maybe it takes longer / works differently from other antiviruses (see comment #34)? Maybe my machine is older (see comment #9), so the virus check takes longer and this the conflict occurs?
(In reply to comment #38)
> - I use avira antivir, maybe it takes longer / works differently (snip)

I think "one time check with avira antivir fully disabled" will answer to your question. 

> - I use 3.0.2 beta1

I see. I'll check with Tb 3.0.2pre nightly build and trunk nightly build.
Summary: Filters filing to IMAP folders not running automatically → Filters filing to IMAP folders not running automatically (quarantine option=on/mailnews.downloadToTempFile=true, "move to IMAP folder" action does nothing)
I had the same behavior with 3.0.1 before, shouldn't be different. I'll check without antivir. Can someone test on a slower / older computer?
Setting dependency to bug 387361 for ease of tracking.
Depends on: 387361
Summary: Filters filing to IMAP folders not running automatically (quarantine option=on/mailnews.downloadToTempFile=true, "move to IMAP folder" action does nothing) → Filters filing to IMAP folders not running automatically (quarantine option=on/mailnews.downloadToTempFile=true, "MOVE to IMAP folder" action does nothing)
Currently selected folder at connection : folders.Online.lists.debian.private
> 46acc00:192.168.2.84:S-folders.Online.lists.debian.private:
ProcessCurrentURL : .folders.Online.lists.unison
> ProcessCurrentURL:imap://nils@192.168.2.84:993/appendmsgfromfile%3E.folders.Online.lists.unison

Why ".folders" in ProcessCurrentURL? Issue with delimiter of "." reported to some bugs?
As I use Gmail IMAP, no namespace is used and delimiter is "/" in my test.

What hapens, if you open separate Tb new window and open folders.Online.lists.unison (move target folder of filter) at the new window before filtering?
can you reproduce this using a current version of thunderbird?

if you are unable to reproduce, please close by setting stats to resolved, and resolution to WORKSFORME or another appropriate setting.

If you are able to reproduce, add new details, and a testcase if one does not already exist in the bug report.
Whiteboard: [closeme 2012-03-25]
RESOLVED INCOMPLETE due to lack of response to last question. If you feel this change was made in error please respond to this bug with your reasons why.
Status: UNCONFIRMED → RESOLVED
Closed: 12 years ago
Resolution: --- → INCOMPLETE
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: