[Dovecot] Mail lost - maybe a bug???
Marco Carcano
marco at carcano.ch
Tue Dec 20 13:46:16 EET 2011
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- at 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- at 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=<e9447410-51fe-45ff-b624-197840b9a862 at usstlz-pinfez02.emrsn.org
>>>>> : 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.)
More information about the dovecot
mailing list