[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