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

Thu Nov 17 18:47:34 EET 2011

Hello Timo, and thanks for your reply

I waited to reply until got it another time

as I already said, it does not happen very often, for example it  
happened on 12 november - the log is at the end of this mail

> Enable mail_log plugin to make sure of this.
> http://wiki2.dovecot.org/Plugins/MailLog

I already did, but just for a few days:  it does not happen very often  
that we loose mails, so I'm afraid I can damage the disks of the  
production server if I keep logging enabled for too much time - it  
will be a pain, years ago I had a server damaged because of logging  
enabled for too much time. I do not want to repeat such a painfull  
experience

>
>> 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 - 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 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:"

and never got anything

here is the log instead

Nov 12 08:48:01 srv001 postfix/smtpd[1430]: connect from  
mail.tasnee.com[62.3.52.58]
Nov 12 08:48:02 srv001 postfix/smtpd[1430]: 6C3874E4A9F:  
client=mail.tasnee.com[62.3.52.58]
Nov 12 08:48:03 srv001 postfix/cleanup[1434]: 6C3874E4A9F: warning:  
header Subject: RE: RFQ NO. 6000029222 - OUR OFFER NO. 2111221 from  
mail.tasnee.com[62.3.52.58]; from=<sender at tasnee.com> to=<theuser at ourdomain.ch 
 > proto=ESMTP helo=<mail.tasnee.com>
Nov 12 08:48:03 srv001 postfix/cleanup[1434]: 6C3874E4A9F: message-id=<899EAB831EA7414F994704DB43677A140450EE74 at NPICMAIL.npic.com.sa 
 >
Nov 12 08:48:03 srv001 postfix/qmgr[4876]: 6C3874E4A9F: from=<sender at tasnee.com 
 >, size=9920, nrcpt=4 (queue active)
Nov 12 08:48:06 srv001 postfix/smtpd[1442]: connect from  
localhost.localdomain[127.0.0.1]
Nov 12 08:48:06 srv001 postfix/smtpd[1442]: 244774E4AA2:  
client=localhost.localdomain[127.0.0.1]
Nov 12 08:48:06 srv001 postfix/cleanup[1434]: 244774E4AA2: message-id=<899EAB831EA7414F994704DB43677A140450EE74 at NPICMAIL.npic.com.sa 
 >
Nov 12 08:48:06 srv001 postfix/qmgr[4876]: 244774E4AA2: from=<sender at tasnee.com 
 >, size=10323, nrcpt=4 (queue active)
Nov 12 08:48:06 srv001 postfix/smtpd[1442]: disconnect from  
localhost.localdomain[127.0.0.1]
Nov 12 08:48:06 srv001 amavis[8902]: (08902-05) Passed CLEAN,  
[62.3.52.58] [62.3.52.58] <sender at tasnee.com> ->  
< 
user2 
@ourdomain.local>,<theuser at ourdomain.local>,<user4 at ourdomain.local>,<user3 at ourdomain.local 
 >, Message-ID: <899EAB831EA7414F994704DB43677A140450EE74 at NPICMAIL.npic.com.sa 
 >, mail_id: z4aAgl2gBrfV, Hits: -0.592, size: 9919, queued_as:  
244774E4AA2, 2632 ms
Nov 12 08:48:06 srv001 postfix/lmtp[1438]: 6C3874E4A9F: to=<user2 at ourdomain.local 
 >, orig_to=<user2 at ourdomain.ch>, relay=127.0.0.1[127.0.0.1]:10024,  
delay=3.9, delays=1.2/0.01/0/2.6, dsn=2.0.0, status=sent (250 2.0.0  
from MTA([127.0.0.1]:10025): 250 2.0.0 Ok: queued as 244774E4AA2)
Nov 12 08:48:06 srv001 postfix/lmtp[1438]: 6C3874E4A9F: to=<theuser at ourdomain.local 
 >, orig_to=<theuser at ourdomain.ch>, relay=127.0.0.1[127.0.0.1]:10024,  
delay=3.9, delays=1.2/0.01/0/2.6, dsn=2.0.0, status=sent (250 2.0.0  
from MTA([127.0.0.1]:10025): 250 2.0.0 Ok: queued as 244774E4AA2)
Nov 12 08:48:06 srv001 postfix/lmtp[1438]: 6C3874E4A9F: to=<user4 at ourdomain.local 
 >, orig_to=<user4 at ourdomain.ch>, relay=127.0.0.1[127.0.0.1]:10024,  
delay=3.9, delays=1.2/0.01/0/2.6, dsn=2.0.0, status=sent (250 2.0.0  
from MTA([127.0.0.1]:10025): 250 2.0.0 Ok: queued as 244774E4AA2)
Nov 12 08:48:06 srv001 postfix/lmtp[1438]: 6C3874E4A9F: to=<user3 at ourdomain.local 
 >, orig_to=<user3 at ourdomain.ch>, relay=127.0.0.1[127.0.0.1]:10024,  
delay=3.9, delays=1.2/0.01/0/2.6, dsn=2.0.0, status=sent (250 2.0.0  
from MTA([127.0.0.1]:10025): 250 2.0.0 Ok: queued as 244774E4AA2)
Nov 12 08:48:06 srv001 postfix/qmgr[4876]: 6C3874E4A9F: removed
Nov 12 08:48:06 srv001 dovecot: lda(user3): msgid=<899EAB831EA7414F994704DB43677A140450EE74 at NPICMAIL.npic.com.sa 
 >: saved mail to INBOX
Nov 12 08:48:06 srv001 dovecot: lda(user2): msgid=<899EAB831EA7414F994704DB43677A140450EE74 at NPICMAIL.npic.com.sa 
 >: saved mail to INBOX
Nov 12 08:48:06 srv001 postfix/pipe[1452]: 244774E4AA2: to=<user3 at ourdomain.local 
 >, relay=dovecot, delay=0.08, delays=0.01/0.02/0/0.05, dsn=2.0.0,  
status=sent (delivered via dovecot service)
Nov 12 08:48:06 srv001 postfix/pipe[1445]: 244774E4AA2: to=<user2 at ourdomain.local 
 >, relay=dovecot, delay=0.08, delays=0.01/0.01/0/0.06, dsn=2.0.0,  
status=sent (delivered via dovecot service)
Nov 12 08:48:06 srv001 dovecot: lda(theuser): msgid=<899EAB831EA7414F994704DB43677A140450EE74 at NPICMAIL.npic.com.sa 
 >: saved mail to INBOX
Nov 12 08:48:06 srv001 postfix/pipe[1447]: 244774E4AA2: to=<theuser at ourdomain.local 
 >, relay=dovecot, delay=0.09, delays=0.01/0.01/0/0.07, dsn=2.0.0,  
status=sent (delivered via dovecot service)
Nov 12 08:48:06 srv001 dovecot: lda(user4): msgid=<899EAB831EA7414F994704DB43677A140450EE74 at NPICMAIL.npic.com.sa 
 >: saved mail to INBOX
Nov 12 08:48:06 srv001 postfix/pipe[1450]: 244774E4AA2: to=<user4 at ourdomain.local 
 >, relay=dovecot, delay=0.26, delays=0.01/0.02/0/0.23, dsn=2.0.0,  
status=sent (delivered via dovecot service)
Nov 12 08:48:06 srv001 postfix/qmgr[4876]: 244774E4AA2: removed
Nov 12 08:48:08 srv001 postfix/smtpd[1430]: disconnect from  
mail.tasnee.com[62.3.52.58]

as you can see again, the mail seems delivered, but is not

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)

thank you

Marco Carcano