Re: [Dovecot] Mail lost - maybe a bug???

Hello Timo and Urban

I took quite a long time to reply, but as I told you this issue does
not verify very often, so I had enabled verbose logging and just
waited ..

I summarize the situation - user mmanzoni sometimes does not receive a
message - it does not matter if he is the only recipient or if there
are others

its outlook 2010 is configured for POP3 mail and to leave all messages
on the server, and setup to never delete them (neither after a few
days, neither when he deletes from his trash folder). There are not
any other client that log to that mail account: this is the only one
client that download messages

the following extract of the LDA log shows what happened: the message
was sent to 4 users (I report just 2 of them: criva, that received it,
and mmanzoni, who didn't)

################CRIVA#####################

Dec 12 10:51:24 srv001 dovecot: lda: Debug: Loading modules from
directory: /usr/lib64/dovecot Dec 12 10:51:24 srv001 dovecot: lda: Debug: Module loaded: /usr/lib64/ dovecot/lib10_quota_plugin.so Dec 12 10:51:24 srv001 dovecot: lda: Debug: Module loaded: /usr/lib64/ dovecot/lib90_sieve_plugin.so Dec 12 10:51:24 srv001 dovecot: lda: Debug: auth input: criva home=/ home/criva 499=criva quota_rule=*:storage=8192M Dec 12 10:51:24 srv001 dovecot: lda: Debug: Added userdb setting:
plugin/499=criva Dec 12 10:51:24 srv001 dovecot: lda: Debug: Added userdb setting:
plugin/quota_rule=*:storage=8192M Dec 12 10:51:24 srv001 dovecot: lda(criva): Debug: Effective uid=499,
gid=499, home=/home/criva Dec 12 10:51:24 srv001 dovecot: lda(criva): Debug: Quota root:
name=User quota backend=maildir args= Dec 12 10:51:24 srv001 dovecot: lda(criva): Debug: Quota rule:
root=User quota mailbox=* bytes=8589934592 messages=0 Dec 12 10:51:24 srv001 dovecot: lda(criva): Debug: Quota rule:
root=User quota mailbox=Trash bytes=+1048576000 messages=0 Dec 12 10:51:27 srv001 dovecot: lda(criva): Debug: Quota warning:
bytes=6871947673 (80%) messages=0 reverse=no command=quota-warning 80
criva Dec 12 10:51:27 srv001 dovecot: lda(criva): Debug: Quota warning:
bytes=7730941132 (90%) messages=0 reverse=no command=quota-warning 90
criva Dec 12 10:51:27 srv001 dovecot: lda(criva): Debug: Quota warning:
bytes=8160437862 (95%) messages=0 reverse=no command=quota-warning 95
criva Dec 12 10:51:27 srv001 dovecot: lda(criva): Debug: Quota root:
name=Shared quota backend=maildir args=ns=Public/ Dec 12 10:51:27 srv001 dovecot: lda(criva): Debug: Quota rule:
root=Shared quota mailbox=* bytes=20971520000 messages=0 Dec 12 10:51:27 srv001 dovecot: lda(criva): Debug: Namespace :
type=private, prefix=, sep=/, inbox=yes, hidden=no, list=yes,
subscriptions=yes location=maildir:/home/mailboxstore/criva/Maildir Dec 12 10:51:27 srv001 dovecot: lda(criva): Debug: maildir++: root=/ home/mailboxstore/criva/Maildir, index=, control=, inbox=/home/ mailboxstore/criva/Maildir Dec 12 10:51:27 srv001 dovecot: lda(criva): Debug: Namespace :
type=shared, prefix=shared/%u/, sep=/, inbox=no, hidden=no,
list=children, subscriptions=no location=maildir:/home/mailboxstore/ %Lu/Maildir:INDEX=/home/mailboxstore/criva/Maildir/shared/%Lu Dec 12 10:51:27 srv001 dovecot: lda(criva): Debug: shared: root=/var/ run/dovecot, index=, control=, inbox= Dec 12 10:51:27 srv001 dovecot: lda(criva): Debug: Namespace :
type=public, prefix=Public/, sep=/, inbox=no, hidden=no, list=yes,
subscriptions=no location=maildir:/home/mailboxstore/public Dec 12 10:51:27 srv001 dovecot: lda(criva): Debug: maildir++: root=/ home/mailboxstore/public, index=, control=, inbox= Dec 12 10:51:27 srv001 dovecot: lda(criva): Debug: Quota root:
name=User quota backend=maildir args= Dec 12 10:51:27 srv001 dovecot: lda(criva): Debug: Quota rule:
root=User quota mailbox=* bytes=14680064000 messages=0 Dec 12 10:51:27 srv001 dovecot: lda(criva): Debug: Quota rule:
root=User quota mailbox=Trash bytes=+1048576000 messages=0 Dec 12 10:51:27 srv001 dovecot: lda(criva): Debug: Quota warning:
bytes=11744051200 (80%) messages=0 reverse=no command=quota-warning 80
criva Dec 12 10:51:27 srv001 dovecot: lda(criva): Debug: Quota warning:
bytes=13212057600 (90%) messages=0 reverse=no command=quota-warning 90
criva Dec 12 10:51:27 srv001 dovecot: lda(criva): Debug: Quota warning:
bytes=13946060800 (95%) messages=0 reverse=no command=quota-warning 95
criva Dec 12 10:51:27 srv001 dovecot: lda(criva): Debug: Quota root:
name=Shared quota backend=maildir args=ns=Public/ Dec 12 10:51:27 srv001 dovecot: lda(criva): Debug: Quota rule:
root=Shared quota mailbox=* bytes=20971520000 messages=0 Dec 12 10:51:27 srv001 dovecot: lda(criva): Debug: none: root=,
index=, control=, inbox= Dec 12 10:51:27 srv001 dovecot: lda(criva): Debug: sieve: user's
script path /home/mailboxstore/criva/.dovecot.sieve doesn't exist
(using global script path in stead) Dec 12 10:51:27 srv001 dovecot: lda(criva): Debug: sieve: user has no
valid personal script Dec 12 10:51:27 srv001 dovecot: lda(criva): Debug: sieve: no scripts
to execute: reverting to default delivery. Dec 12 10:51:27 srv001 dovecot: lda(criva): msgid=<1888520041-1323683477-cardhu_decombobulator_blackberry.rim.net-2066152169-@b12.c13.bise7.blackberry

: saved mail to INBOX

#################MMANZONI###############

Dec 12 10:51:28 srv001 dovecot: lda: Debug: Loading modules from
directory: /usr/lib64/dovecot Dec 12 10:51:28 srv001 dovecot: lda: Debug: Module loaded: /usr/lib64/ dovecot/lib10_quota_plugin.so Dec 12 10:51:28 srv001 dovecot: lda: Debug: Module loaded: /usr/lib64/ dovecot/lib90_sieve_plugin.so Dec 12 10:51:28 srv001 dovecot: lda: Debug: auth input: mmanzoni home=/ home/mmanzoni 499=mmanzoni quota_rule=*:storage=8192M Dec 12 10:51:28 srv001 dovecot: lda: Debug: Added userdb setting:
plugin/499=mmanzoni Dec 12 10:51:28 srv001 dovecot: lda: Debug: Added userdb setting:
plugin/quota_rule=*:storage=8192M Dec 12 10:51:28 srv001 dovecot: lda(mmanzoni): Debug: Effective
uid=499, gid=499, home=/home/mmanzoni Dec 12 10:51:28 srv001 dovecot: lda(mmanzoni): Debug: Quota root:
name=User quota backend=maildir args= Dec 12 10:51:28 srv001 dovecot: lda(mmanzoni): Debug: Quota rule:
root=User quota mailbox=* bytes=8589934592 messages=0 Dec 12 10:51:28 srv001 dovecot: lda(mmanzoni): Debug: Quota rule:
root=User quota mailbox=Trash bytes=+1048576000 messages=0 Dec 12 10:51:28 srv001 dovecot: lda(mmanzoni): Debug: Quota warning:
bytes=6871947673 (80%) messages=0 reverse=no command=quota-warning 80
mmanzoni Dec 12 10:51:28 srv001 dovecot: lda(mmanzoni): Debug: Quota warning:
bytes=7730941132 (90%) messages=0 reverse=no command=quota-warning 90
mmanzoni Dec 12 10:51:28 srv001 dovecot: lda(mmanzoni): Debug: Quota warning:
bytes=8160437862 (95%) messages=0 reverse=no command=quota-warning 95
mmanzoni Dec 12 10:51:28 srv001 dovecot: lda(mmanzoni): Debug: Quota root:
name=Shared quota backend=maildir args=ns=Public/ Dec 12 10:51:28 srv001 dovecot: lda(mmanzoni): Debug: Quota rule:
root=Shared quota mailbox=* bytes=20971520000 messages=0 Dec 12 10:51:28 srv001 dovecot: lda(mmanzoni): Debug: Namespace :
type=private, prefix=, sep=/, inbox=yes, hidden=no, list=yes,
subscriptions=yes location=maildir:/home/mailboxstore/mmanzoni/Maildir Dec 12 10:51:28 srv001 dovecot: lda(mmanzoni): Debug: maildir++: root=/ home/mailboxstore/mmanzoni/Maildir, index=, control=, inbox=/home/ mailboxstore/mmanzoni/Maildir Dec 12 10:51:28 srv001 dovecot: lda(mmanzoni): Debug: Namespace :
type=shared, prefix=shared/%u/, sep=/, inbox=no, hidden=no,
list=children, subscriptions=no location=maildir:/home/mailboxstore/ %Lu/Maildir:INDEX=/home/mailboxstore/mmanzoni/Maildir/shared/%Lu Dec 12 10:51:28 srv001 dovecot: lda(mmanzoni): Debug: shared: root=/ var/run/dovecot, index=, control=, inbox= Dec 12 10:51:28 srv001 dovecot: lda(mmanzoni): Debug: Namespace :
type=public, prefix=Public/, sep=/, inbox=no, hidden=no, list=yes,
subscriptions=no location=maildir:/home/mailboxstore/public Dec 12 10:51:28 srv001 dovecot: lda(mmanzoni): Debug: maildir++: root=/ home/mailboxstore/public, index=, control=, inbox= Dec 12 10:51:28 srv001 dovecot: lda(mmanzoni): Debug: Quota root:
name=User quota backend=maildir args= Dec 12 10:51:28 srv001 dovecot: lda(mmanzoni): Debug: Quota rule:
root=User quota mailbox=* bytes=14680064000 messages=0 Dec 12 10:51:28 srv001 dovecot: lda(mmanzoni): Debug: Quota rule:
root=User quota mailbox=Trash bytes=+1048576000 messages=0 Dec 12 10:51:28 srv001 dovecot: lda(mmanzoni): Debug: Quota warning:
bytes=11744051200 (80%) messages=0 reverse=no command=quota-warning 80
mmanzoni Dec 12 10:51:28 srv001 dovecot: lda(mmanzoni): Debug: Quota warning:
bytes=13212057600 (90%) messages=0 reverse=no command=quota-warning 90
mmanzoni Dec 12 10:51:28 srv001 dovecot: lda(mmanzoni): Debug: Quota warning:
bytes=13946060800 (95%) messages=0 reverse=no command=quota-warning 95
mmanzoni Dec 12 10:51:28 srv001 dovecot: lda(mmanzoni): Debug: Quota root:
name=Shared quota backend=maildir args=ns=Public/ Dec 12 10:51:28 srv001 dovecot: lda(mmanzoni): Debug: Quota rule:
root=Shared quota mailbox=* bytes=20971520000 messages=0 Dec 12 10:51:28 srv001 dovecot: lda(mmanzoni): Debug: none: root=,
index=, control=, inbox= Dec 12 10:51:28 srv001 dovecot: lda(mmanzoni): Debug: sieve: user's
script path /home/mailboxstore/mmanzoni/.dovecot.sieve doesn't exist
(using global script path in stead) Dec 12 10:51:28 srv001 dovecot: lda(mmanzoni): Debug: sieve: user has
no valid personal script Dec 12 10:51:28 srv001 dovecot: lda(mmanzoni): Debug: sieve: no
scripts to execute: reverting to default delivery. Dec 12 10:51:28 srv001 dovecot: lda(mmanzoni): msgid=<1888520041-1323683477-cardhu_decombobulator_blackberry.rim.net-2066152169-@b12.c13.bise7.blackberry

: saved mail to INBOX

#########################################

I know it seems absurd, but mmanzoni has not received the message - I
tried also "grepping" for the object in the maildir, but haven't been
able to get it

what do you think about this?

I really do not know where this issue can be - the only componet I
suppose could have some kind of problem is in the LDA phase, but I'm
just supposing

do you want to give a look to my config files? If so, which one could
be interesting to post?

kind regards

Marco Carcano

Il giorno 17/nov/11, alle ore 18:34, Timo Sirainen ha scritto:

On 17.11.2011, at 18.47, Marco Carcano wrote:

...

...

...

Oct 27 11:20:34 srv001 dovecot: lda(user3): msgid=

...

: saved mail to INBOX

If Dovecot logs this, then the message definitely was saved to
INBOX.

it is exactly what I told to my colleagues, but belive me, sometime
some mail get lost -

Most likely reason for this is that the user's client deletes the
message. Possibly an automatic client side filter or some UI issue
that causes user to accidentally delete a mail. The mail_log
plugin's logging would have showed if this was the case.

...

I suspect however that could be mine misconfiguration somewhere, so
that lda sometimes write the email not in the right place, but
elsewhere, and just write the phrase " saved mail to INBOX in the
logs (however I'm wondering why sometimes?!?)

I can't think of any reason why it would randomly write to a wrong
place.

...

I tried to find the missed email in the Maildir, but have not been
able to get it - the commands used are

cd /home/mailboxstore/theuser/Maildir

grep "6000029222" */* |grep "RE:" grep "6000029222" .Drafts/* |grep "RE:" grep "6000029222" .Drafts/*/* |grep "RE:" grep "6000029222" .Junk/* |grep "RE:" grep "6000029222" .Posta\ eliminata/* |grep "RE:" grep "6000029222" .Posta\ indesiderata/* |grep "RE:" grep "6000029222" .Posta\ inviata/* |grep "RE:" grep "6000029222" .Sent/* |grep "RE:" grep "6000029222" .Templates/* |grep "RE:" grep "6000029222" .Trash/* |grep "RE:"

Only the grep "6000029222" .Drafts/*/* |grep "RE:" was grepping from
mail files. Easier would be just:

grep -r "RE:.*6000029222" .

...

I really think is some kind of misconfiguration of mine, may you
help me, please? Just tell me what pieces of config to show (just
not to flood the whole config)

I doubt this is related to configuration.

But you could enable http://wiki2.dovecot.org/Plugins/Lazyexpunge so
that messages won't be lost if they are expunged. The next time a
message is lost, you would most likely find it from the lazy-expunge
namespace. (Then you could write a script that deletes e.g. >1 week
old files nightly.)