dovecot - Apr 2014 - 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-----

-----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...

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.