[Dovecot] Sieve (randomly?) flagging messages as \\Seen \\Deleted
Hi, I'm trying to debug (without great results, so far) a very weird behaviour in my environment. Sorry if this came out in another form before, but I've not been able to find out anything resembling what I'm experiencing, so far...
OS is a debian wheezy and dovecot is the version provided by the OS:
# 2.1.7: /etc/dovecot/dovecot.conf # OS: Linux 3.2.0-4-amd64 x86_64 Debian 7.4
The system uses postfix with virtual users, credentials and maildir locations stored on mysql, local delivery through LMTP and sieve+managesieve available to users (although managesieve only listens on localhost and is only usable through the webmail interface).
FWIW, I've been running 10-20 systems just like this one (mostly with earlier dovecot versions and using LDA when LMTP wasn't available yet) for many years, and this is the very first time I'm so puzzled I end up searching for help here :-|
Even though the system has been working for months (more or less 1 year now) without big changes, a strange behaviour appeared (or became evident enough to be noticed) in the last few days, apparently involving sieve and some sort of "default/hidden" action triggered by something. Or at least that's what I ended up supposing.
The problem in short:
Messages I expected to find in certain folders were simply not there, although sieve logs reported them as delivered in those same folders. By manually inspecting the maildir, I actually found the messages, but they were all flagged as \\Seen + \\Deleted and therefore not displayed by the MUA (ThunderBird in my case).
I initially supposed this to be a TB issue, 'cause nothing in my sieve script ever flags messages that way, but I could not find anything on my client explaining that.
Then I received a notification from one of my users saying he was experiencing exactly the same, except he's using mutt as IMAP client; that restricted the issue to server-side interactions only, but nothing useful could be found in logfiles...
This is the "relevant" portion of a "dovecot -n" output:
[...] plugin { sieve = ~/.dovecot.sieve sieve_dir = ~/sieve sieve_extensions = +vacation-seconds +editheader sieve_vacation_default_period = 2d sieve_vacation_dont_check_recipient = yes sieve_vacation_max_period = 30d sieve_vacation_min_period = 2s sieve_vacation_use_original_recipient = no }
[...] protocol lmtp { mail_plugins = sieve hostname = alternativename.bofhland.org }
There is no sieve_(before|after) script in addition to what users create for themselves.
The mailboxes are relatively low-traffic; most of the traffic is caused by a single role address translated into multiple-recipients alias going to many of the users (100-300 messages per day).
Almost all the users using sieve rely on it to store traffic for that role-address in a dedicated folder, including the mutt user and myself. Not that's all that important, but means that most of the misbehaviours observed (but not all) are observed in these folders.
I enabled mail_debug, but there's nothing unusual in there AFAICT:
it just says:
- using the following location for user's Sieve script: /blabla/.dovecot.sieve
- opening script /blabla/.dovecot.sieve
- script binary /blabla/.dovecot.svbin successfully loaded
- not saving binary /blabla/.dovecot.svbin, because it is already stored
- executing script from /blabla/.dovecot.svbin
- stored mail into mailbox 'DedicatedFolder'
And it does, except the message happens to be flagged as seen and deleted...
In order to try restricting what may be causing the issue, I added...
removeflag "\\Deleted";
removeflag "\\Seen";...to the rule sending messages to the dedicated folder cited above for my mailbox. The problem apparently disappeared for me as long as I kept those in place.
This should mean (I suppose) that the decision of flagging messages that way is taken before the users' sieve scripts are applied (sort of "hidden sieve_before").
The problem is hard to replicate as it's apparently not deterministic: the same message is being flagged for one user but not for the other, different messages between the same people and with the same thread are sometimes flagged and sometimes not.
Something is surely triggering whatever is causing this, but it's not evident enough for me to point a finger and say "ha ha!" (https://www.youtube.com/watch?v=rX7wtNOkuHo)
So, a question for people knowing pigeonhole's internals: does it ever choose to mark messages as described above for any reason? If yes, I may be triggering this behavior with something I recently added/modified, and at least I'll have something to focus my investigation on. :-|
Any other suggestion is obviously welcome...
-----BEGIN PGP SIGNED MESSAGE----- Hash: SHA1
On Thu, 3 Apr 2014, Emanuele Balla (aka Skull) wrote:
I'm trying to debug (without great results, so far) a very weird behaviour in my environment.
Did you tried with enabled mail_log plugin?
Steffen Kaiser -----BEGIN PGP SIGNATURE----- Version: GnuPG v1.4.11 (GNU/Linux)
iQEVAwUBUz1S1nD1/YhP6VMHAQKdiAgApn+4IYZry7RYN0YZFdMxp8BGPMUkCsKI OOya2vQR62rFg3pKqw4PWlgOSaHV0e8DWk64S/N63FGNxz2fMfaF6om+8LQYJ5Yo 4WSa39LHeQPqCzg1G8tEMf6rqctr3++lIcWWfOu/09Yug6yvPVeJBPA59ZuJ4udu GHMkFb6NL54DIhsjKuIEeLMBiQcfFiX70X9ql9CPwNZvxbPZ04ayQiMw0wtr6bSY X3inQIaUXE40SHxcQyVYddSkEunl80ZBUnsyQxwjMg4E3N1NoDxVGN7JjR4JPykX m8IZYK25KidBBC1cPPg2DmVtBcDCgWmGjNTH+rNZGTsdgrGJxoA55Q== =r1bW -----END PGP SIGNATURE-----
On 03/04/14 14:23, Steffen Kaiser wrote:
On Thu, 3 Apr 2014, Emanuele Balla (aka Skull) wrote:
I'm trying to debug (without great results, so far) a very weird behaviour in my environment.
Did you tried with enabled mail_log plugin?
I didn't but I tried it now: as far as I see/understand, that plugin tracks only status changes taking place on the IMAP side of things, as I don't see anything related with the LMTP session.
It confirmed, however, what I already found out through other means: I see messages marked as \Seen,\Deleted in my folder, without any flag_change being logged by mail_log.
So -it seems- the message is stored with those flags already applied...
-----BEGIN PGP SIGNED MESSAGE----- Hash: SHA1
On Thu, 3 Apr 2014, Emanuele Balla (aka Skull) wrote:
On 03/04/14 14:23, Steffen Kaiser wrote:
On Thu, 3 Apr 2014, Emanuele Balla (aka Skull) wrote:
I'm trying to debug (without great results, so far) a very weird behaviour in my environment.
Did you tried with enabled mail_log plugin?
I didn't but I tried it now: as far as I see/understand, that plugin tracks only status changes taking place on the IMAP side of things, as I don't see anything related with the LMTP session.
It confirmed, however, what I already found out through other means: I see messages marked as \Seen,\Deleted in my folder, without any flag_change being logged by mail_log.
So -it seems- the message is stored with those flags already applied...
Honestly, I hoped otherwise and suggested the plugin. :)
Steffen Kaiser -----BEGIN PGP SIGNATURE----- Version: GnuPG v1.4.11 (GNU/Linux)
iQEVAwUBUz1rc3D1/YhP6VMHAQLbswf/WHIoWot2IZHWWmdqmdar0OxeDCoaa45d WX7Gu3hE2TPqDNVFq6TNSR6zxRU1/aO8Sl1wjPTtAzmLsgL6jXG5lpp8IDM9rEgr R+Jb05WlB2S/hxjd8DuuPZYP0kyHpkTZIjLQ38ESGKeYd6hWLisCn8qFNp7zKUk4 SQc6G3GP+sflYtAU3KRuk3eUoKPFS1hJ3TIUI0feDnyeXG9D2F3Sinejs/Uhjy5J jxS3jg5k5mjgcfoQGlCykHrwcTmbsflHrrSfAN7DIm1Qk4KmlEVezj4EGH/7HqGq Sad3ppMcJbvEPK3tOz8Uev2nAhIeT385YZCu1/OeeIdwxQm0wYkaAg== =6uHd -----END PGP SIGNATURE-----
On 4/3/2014 1:28 PM, Emanuele Balla (aka Skull) wrote: [...]
The problem in short:
Messages I expected to find in certain folders were simply not there, although sieve logs reported them as delivered in those same folders. By manually inspecting the maildir, I actually found the messages, but they were all flagged as \\Seen + \\Deleted and therefore not displayed by the MUA (ThunderBird in my case). [...] In order to try restricting what may be causing the issue, I added...
removeflag "\\Deleted"; removeflag "\\Seen";...to the rule sending messages to the dedicated folder cited above for my mailbox. The problem apparently disappeared for me as long as I kept those in place.
This should mean (I suppose) that the decision of flagging messages that way is taken before the users' sieve scripts are applied (sort of "hidden sieve_before"). [...] So, a question for people knowing pigeonhole's internals: does it ever choose to mark messages as described above for any reason? If yes, I may be triggering this behavior with something I recently added/modified, and at least I'll have something to focus my investigation on. :-|
Sieve doesn't add flags unless it is explicitly told to do so. The behavior you describe is therefore quite bizarre, especially since using removeflag seems to provide a workaround.
What does your full Sieve script look like? What is your full configuration? Do you perhaps return a sieve_before setting from userdb?
Regards,
Stephan.
On 04/04/14 18:31, Stephan Bosch wrote:
Sieve doesn't add flags unless it is explicitly told to do so. The behavior you describe is therefore quite bizarre, especially since using removeflag seems to provide a workaround.
I know, or I wouldn't be so puzzled...
What does your full Sieve script look like?
Mine is relatively long, although quite straightforward: just foldering stuff in several places based on List-Id and applying Thunderbird tags/labels based on a few conditions.
But the other user's one is way shorter:
require ["regex","fileinto"]; # rule:[rule0] if anyof (header :contains "To" "XXX", header :contains "From" "xxx", header :regex "Subject" "xxx", [...]) { fileinto "folder1"; stop; } # rule:[rule1] if anyof (header :contains "To" "YYY", header :contains "From" "YYY", header :contains "Received" "YYY") { fileinto "folder1"; stop; }
What is your full configuration?
Not much longer than what I already provided...
# 2.1.7: /etc/dovecot/dovecot.conf # OS: Linux 3.2.0-4-amd64 x86_64 Debian 7.4 auth_mechanisms = plain login default_vsz_limit = 512 M first_valid_gid = 8 first_valid_uid = 201 last_valid_gid = 8 last_valid_uid = 201 mail_plugins = mail_log notify managesieve_notify_capability = mailto managesieve_sieve_capability = fileinto reject envelope encoded-character vacation subaddress comparator-i;ascii-numeric relational regex imap4flags copy include variables body enotify environment mailbox date ihave vacation-seconds editheader passdb { args = /etc/dovecot/dovecot-sql.conf.ext driver = sql } plugin { mail_debug = yes mail_log_events = flag_change save mail_log_fields = uid box msgid flags subject sieve = ~/.dovecot.sieve sieve_dir = ~/sieve sieve_extensions = +vacation-seconds +editheader sieve_vacation_default_period = 2d sieve_vacation_dont_check_recipient = yes sieve_vacation_max_period = 30d sieve_vacation_min_period = 2s sieve_vacation_use_original_recipient = no } postmaster_address = postmaster@bofhland.org protocols = " imap lmtp sieve pop3" service auth { unix_listener /var/spool/postfix/private/auth { mode = 0660 user = postfix } } service imap-login { inet_listener imap { address = 127.0.0.1 port = 143 } inet_listener imaps { port = 993 ssl = yes } process_min_avail = 0 } service imap { idle_kill = 30 mins process_limit = 1024 vsz_limit = 1 G } service lmtp { unix_listener /var/spool/postfix/private/dovecot-lmtp { group = postfix mode = 0660 user = postfix } } service managesieve-login { inet_listener sieve { address = 127.0.0.1 port = 4190 } } service pop3-login { inet_listener pop3s { port = 995 ssl = yes } } ssl_cert =
I can also provide the SQL query I'm using, if you wish, but all I extract from the DB is home, maildir and quota (although this is not used at the moment). UID and GID are statically assigned, as you can also see from the "(first|last)_valid_(uid|gid)" in the config above.
Really, dovecot usage is quite trivial here. The only "strange" thing is the fact that the LMTP process is provided an hostname on its own.
Do you perhaps return a sieve_before setting from userdb?
Nope. Also, if there was one defined somehow/somewhere, I'd see something in sieve's debug (when trying to open it, compiling, etc), but there's nothing.
I can tell more: searching for a global workaround, in the meanwhile I added a sieve_before script (not shown in the config above) doing only this:
require ["imap4flags"]; removeflag "\\Deleted"; removeflag "\\Seen";
As a result, the problem disappeared for all users... :-| (and yeah, the execution of this sieve_before appears in my debug logs, now)
On 4/4/2014 8:20 PM, Emanuele Balla (aka Skull) wrote:
On 04/04/14 18:31, Stephan Bosch wrote:
Also, if there was one defined somehow/somewhere, I'd see something in sieve's debug (when trying to open it, compiling, etc), but there's nothing.
I can tell more: searching for a global workaround, in the meanwhile I added a sieve_before script (not shown in the config above) doing only this:
require ["imap4flags"]; removeflag "\\Deleted"; removeflag "\\Seen";
As a result, the problem disappeared for all users... :-| (and yeah, the execution of this sieve_before appears in my debug logs, now)
I have no idea what may be going on here. Upgrading may help. If you can, you should try that first. If it persists, I'd have to add some more debug logging to get an idea where these flags (or rather this message state) is generated.
Regards,
Stephan.
participants (3)
-
Emanuele Balla (aka Skull)
-
Steffen Kaiser
-
Stephan Bosch